[Dovecot] Connection refused with auth-master afterupgradingto Dovecot 1.0 rc 28
Jason Warner
jasonw at brashers.com
Tue Apr 10 19:30:51 EEST 2007
> -----Original Message-----
> From: Timo Sirainen [mailto:tss at iki.fi]
> Sent: Tuesday, April 10, 2007 9:36 AM
> To: Jason Warner
> Cc: 'Jason Warner'; dovecot at 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 at 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 at 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 at 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 at domain"..., 54) = 54
Again, it was a partial before changing the domain.
> 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,
59995) = 1
> gettimeofday({1176221679, 242218}, {360, 0}) = 0
> read(6, "", 4074) = 0
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 at mail.domain.com>
Apr 10 10:12:14 mail postfix/qmgr[452]: A7F1B168734: from=<user at domain.com>,
size=2600, nrcpt=1 (queue active)
Apr 10 10:12:14 mail postfix/smtp[464]: E4B351686E4: to=<user at 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 at 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 at domain.com>,
size=2600, nrcpt=1 (queue active)
Apr 10 10:13:55 mail postfix/pipe[890]: A7F1B168734: to=<user at 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.
More information about the dovecot
mailing list