-----Original Message----- From: Timo Sirainen [mailto:tss@iki.fi] Sent: Tuesday, April 10, 2007 9:36 AM To: Jason Warner Cc: 'Jason Warner'; dovecot@dovecot.org Subject: Re: [Dovecot] Connection refused with auth-master afterupgradingto Dovecot 1.0 rc 28
On Tue, 2007-04-10 at 09:32 -0600, Jason Warner wrote:
Sorry, I forgot to mention that when I tried the -d parameter, I was running as the vmail user and everything went just fine.
I'm running out of ideas. strace could be helpful. Run:
strace -o /tmp/deliver.log deliver -d ..
Both as standalone and in Postfix. What's different in the log file?
Here's a diff of the two log files:
1,3c1,3 < execve("/usr/libexec/dovecot/deliver", ["/usr/libexec/dovecot/deliver", "-d", "user1@domain.com"], [/* 26 vars */]) = 0 < brk(0) = 0x9cac000 < mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f31000
execve("/usr/libexec/dovecot/deliver", ["/usr/libexec/dovecot/deliver", "-d", "user2@domain.com"], [/* 3 vars */]) = 0 brk(0) = 0x8192000 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f4b000 7c7 < mmap2(NULL, 102341, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7f18000
mmap2(NULL, 102341, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7f32000 22,23c22,23 < mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f17000 < set_thread_area({entry_number:-1 -> 6, base_addr:0xb7f176c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f31000 set_thread_area({entry_number:-1 -> 6, base_addr:0xb7f316c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0 27,30c27,30 < munmap(0xb7f18000, 102341) = 0 < time(NULL) = 1176220958 < brk(0) = 0x9cac000 < brk(0x9cd5000) = 0x9cd5000
munmap(0xb7f32000, 102341) = 0 time(NULL) = 1176221679 brk(0) = 0x8192000 brk(0x81bb000) = 0x81bb000 32,33c32,33 < getpid() = 31531 < gettimeofday({1176220958, 974801}, {360, 0}) = 0
getpid() = 1143 gettimeofday({1176221679, 229181}, {360, 0}) = 0 96,106c96,106 < _llseek(6, 0, 0xbfa70aa0, SEEK_CUR) = -1 ESPIPE (Illegal seek) < getsockname(6, {sa_family=AF_FILE, path="Ã "}, [2]) = 0 < write(6, "VERSION\t1\t0\nUSER\t1\tuser1@domain"..., 55) = 55
At this line, before changing the domain, it was a partial of my domain name
< gettimeofday({1176220958, 988500}, NULL) = 0 < poll([{fd=3, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=6, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL, revents=POLLIN}], 2, 59986) = 1 < gettimeofday({1176220958, 988718}, {360, 0}) = 0 < read(6, "VERSION\t1\t0\nSPID\t28471\n", 4096) = 23 < gettimeofday({1176220958, 988913}, NULL) = 0 < poll([{fd=3, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=6, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL, revents=POLLIN|POLLHUP}], 2, 59986) = 1 < gettimeofday({1176220959, 11220}, {360, 0}) = 0 < read(6, "", 4073) = 0
_llseek(6, 0, 0xbf9345b0, SEEK_CUR) = -1 ESPIPE (Illegal seek) getsockname(6, {sa_family=AF_FILE, path="^Y^H"}, [2]) = 0 write(6, "VERSION\t1\t0\nUSER\t1\tuser2@domain"..., 54) = 54
Again, it was a partial before changing the domain.
- = 1
gettimeofday({1176221679, 242218}, {360, 0}) = 0 read(6, "", 4074) = 0
gettimeofday({1176221679, 234529}, NULL) = 0 poll([{fd=3, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=6, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL, revents=POLLIN}], 2, 59995) = 1 gettimeofday({1176221679, 234669}, {360, 0}) = 0 read(6, "VERSION\t1\t0\nSPID\t1141\n", 4096) = 22 gettimeofday({1176221679, 234825}, NULL) = 0 poll([{fd=3, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=6, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL, revents=POLLIN|POLLHUP}], 2,
The first file was run as the vmail user from the command line with the -d. The second was run from Postfix.
An interesting thing about the Postfix bug is that I now get these lines in the log:
Apr 10 10:12:14 mail postfix/smtpd[562]: A7F1B168734: client=mail.domain.com[127.0.0.1] Apr 10 10:12:14 mail postfix/cleanup[496]: A7F1B168734: message-id=20070410161207.E4B351686E4@mail.domain.com Apr 10 10:12:14 mail postfix/qmgr[452]: A7F1B168734: from=user@domain.com, size=2600, nrcpt=1 (queue active) Apr 10 10:12:14 mail postfix/smtp[464]: E4B351686E4: to=user@domain.com, relay=127.0.0.1[127.0.0.1]:10024, delay=7, delays=0.22/0/0.01/6.8, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=31657-06, from MTA: 250 2.0.0 Ok: queued as A7F1B168734) Apr 10 10:12:15 mail postfix/pipe[563]: A7F1B168734: to=user@domain.com, relay=dovecot, delay=0.75, delays=0.24/0.06/0/0.45, dsn=4.3.0, status=deferred (temporary failure) Apr 10 10:13:55 mail postfix/qmgr[864]: A7F1B168734: from=user@domain.com, size=2600, nrcpt=1 (queue active) Apr 10 10:13:55 mail postfix/pipe[890]: A7F1B168734: to=user@domain.com, relay=dovecot, delay=101, delays=101/0.02/0/0.11, dsn=2.0.0, status=sent (delivered via dovecot service) Apr 10 10:13:55 mail postfix/qmgr[864]: A7F1B168734: removed
The weird thing is that after the mail claims to have a temporary failure, it then says it is delivered, but I can't seem to find the mail on my server. It just disappears.