Re: [Dovecot] dovecot and time
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) = 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) = Should I attach full traces? They're 32k and 64k respectively. Sorry Rick
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:
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:
about the lack of threading, I had my subscription off and didn't get
a copy to reply to :/
Quoting Rick Romero rick@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
participants (2)
-
Ben Morrow
-
Rick Romero