I found something interesting via strace. lda is writing a timestamp
with utime before doign the fsync, but I'm really not a C guy, so I
have no idea why that's going on via procmail and not via commandline.
I assume it's related to the choice of pread64 vs read.
when called from commandline (working):
read(0, "July 14-20, 2013\n10 courses. Bon"..., 4096) = 4096
read(0, "s bigger\nthan most realistic cyb"..., 4096) = 4096
read(0, "olina company in\nnumerous small,"..., 4096) = 4096
read(0, "on't have any way to tell you\". "..., 4096) = 4096
read(0, "rer. This version of Chrome addr"..., 4096) = 4096
read(0, "edu.\n\nDr. Johannes Ullrich is Ch"..., 4096) = 3164
read(0, "", 932) = 0
umask(0177) = 077
open("/usr/home/vpopmail/domains/havokmon.com/rick/Maildir/tmp/1370448645.M589211P14191.smtp101",
O_WRONLY|O_CREAT|O_EXCL|O_TRUNC|O_LARGEFILE, 0777) =
11
umask(077) = 0177
open("/usr/home/vpopmail/domains/havokmon.com/rick/Maildir/dovecot.index.cache",
O_RDWR|O_LARGEFILE) =
12
fstat64(12, {st_mode=S_IFREG|0600, st_size=1568768, ...}) = 0
mmap2(NULL, 1568768, PROT_READ, MAP_SHARED, 12, 0) = 0xb7064000
fstat64(11, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
write(11, "Return-Path: <newsbites at sans.org"..., 8192) = 8192
write(11, "s bigger\nthan most realistic cyb"..., 8192) = 8192
write(11, "on't have any way to tell you\". "..., 11356) =
11356
fstat64(11, {st_mode=S_IFREG|0600, st_size=27740, ...}) = 0
fsync(11) = 0
_llseek(11, 0, [27740], SEEK_END) = 0
close(11) = 0
time(NULL) = 1370448645
umask(0177) = 077
when called from procmail (not working):
pread64(10, "00.vfemail.net,S=10941\n968 W2552"..., 4064, 52993) =
4064
pread64(10, "53 :1361943010.39085.mx100.vfema"..., 4087, 57057) = 4087
pread64(10, " :1364597743.43999.mx100.vfemail"..., 4085, 61144) = 4085
pread64(10, "mx100.vfemail.net,S=15951\n17287 "..., 4065, 65229) =
4065
pread64(10, "637P32360.smtp101.vfemail.net,S="..., 4074, 69294) = 3967
pread64(10, "", 107, 73261) = 0
umask(0177) = 077
open("/usr/home/vpopmail/domains/havokmon.com/rick/Maildir/tmp/1370449940.M313792P17436.smtp101",
O_WRONLY|O_CREAT|O_EXCL|O_TRUNC|O_LARGEFILE, 0777) =
11
umask(077) = 0177
open("/usr/home/vpopmail/domains/havokmon.com/rick/Maildir/dovecot.index.cache",
O_RDWR|O_LARGEFILE) =
12
fstat64(12, {st_mode=S_IFREG|0600, st_size=1575936, ...}) = 0
mmap2(NULL, 1575936, PROT_READ, MAP_SHARED, 12, 0) = 0xb70b0000
fstat64(11, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
read(0, "", 1127) = 0
write(11, "Return-Path: <dovecot-bounces at do"..., 2911) = 2911
utime("/usr/home/vpopmail/domains/havokmon.com/rick/Maildir/tmp/1370449940.M313792P17436.smtp101",
[2013/06/05-16:32:20, 2013/06/05-21:32:18]) =
fsync(11) = 0
_llseek(11, 0, [2911], SEEK_END) = 0
close(11) = 0
time(NULL) = 1370449940
umask(0177) = 077
Should I attach full traces? They're 32k and 64k respectively. Sorry
about the lack of threading, I had my subscription off and didn't get
a copy to reply to :/
Rick
Quoting Rick Romero <rick at havokmon.com>:> I found something interesting via strace.? lda is writing a timestamp > with utime before doign the fsync, but I'm really not a C guy, so I have > no idea why that's going on via procmail and not via commandline.? I > assume it's related to the choice of pread64 vs read.Got it. Working: connect(6, {sa_family=AF_FILE, path="/var/run/dovecot/config"}, 110) = 0 NonWorking: connect(6, {sa_family=AF_FILE, path="/var/run/dovecot/config"}, 110) = -1 EACCES (Permission denied) /var/run/dovecot/config was owned by root.?? I changed it to vpopmail (which procmail runs under), and my timestamps are now correct. Rick
At 11AM -0500 on 5/06/13 you (Rick Romero) wrote:> I found something interesting via strace. lda is writing a timestamp > with utime before doign the fsync, but I'm really not a C guy, so I > have no idea why that's going on via procmail and not via commandline. > I assume it's related to the choice of pread64 vs read. > > when called from commandline (working): > > read(0, "July 14-20, 2013\n10 courses. Bon"..., 4096) = 4096[...]> open("/usr/home/vpopmail/domains/havokmon.com/rick/Maildir/tmp/1370448645.M589211P14191.smtp101", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC|O_LARGEFILE, 0777) = > 11[...]> > when called from procmail (not working): > > pread64(10, "00.vfemail.net,S=10941\n968 W2552"..., 4064, 52993) = 4064[...]> open("/usr/home/vpopmail/domains/havokmon.com/rick/Maildir/tmp/1370449940.M313792P17436.smtp101", > O_WRONLY|O_CREAT|O_EXCL|O_TRUNC|O_LARGEFILE, 0777) = > 11[...]> utime("/usr/home/vpopmail/domains/havokmon.com/rick/Maildir/tmp/1370449940.M313792P17436.smtp101", [2013/06/05-16:32:20, 2013/06/05-21:32:18]) =[...] Eeenteresting. The pread64 vs read is presumably because procmail is passing lda a regular file on stdin rather than a pipe; you can't use pread on a pipe. I wondered if maybe lda might be copying the timestamp across from its input file, which it isn't, but while checking that I found this (in src/lda/main.c): /* If input begins with a From-line, drop it */ ret = i_stream_read_data(input, &data, &size, 5); if (ret > 0 && size >= 5 && memcmp(data, "From ", 5) == 0) { /* ... */ (void)mbox_from_parse(data, i, mtime_r, &tz, &sender); /* ... */ } which says to me that if lda is passed a mail starting with an mbox-format From_ line, it will use the datestamp from that line rather than the current time. Procmail likes to give things From_ lines, so it's likely this is what's happening. Can you add something to the procmail recipe to write the mail out somewhere unmodified, to see whether procmail is writing the date out wrong or dovecot is parsing it wrong? Presumably the timezone information is getting screwed up somewhere; is procmail leaving it out altogether, or maybe writing a named timezone (which Dovecot will ignore, apparently)? You may be able to help matters by running the whole delivery process (both procmail and lda) with TZ=UTC (and probably LC_ALL=C for good measure), just to try and get things to use machine-readable rather than human-readable timestamp formats. You could also try head -n +1 | lda, or something a little less crude. Ben