> -----Original Message----- > From: Timo Sirainen [mailto:[EMAIL PROTECTED] > 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", "[EMAIL PROTECTED]"], [/* 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", "[EMAIL PROTECTED]"], [/* 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, "[EMAIL PROTECTED]"..., 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, "[EMAIL PROTECTED]"..., 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=<[EMAIL PROTECTED]> Apr 10 10:12:14 mail postfix/qmgr[452]: A7F1B168734: from=<[EMAIL PROTECTED]>, size=2600, nrcpt=1 (queue active) Apr 10 10:12:14 mail postfix/smtp[464]: E4B351686E4: to=<[EMAIL PROTECTED]>, 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=<[EMAIL PROTECTED]>, 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=<[EMAIL PROTECTED]>, size=2600, nrcpt=1 (queue active) Apr 10 10:13:55 mail postfix/pipe[890]: A7F1B168734: to=<[EMAIL PROTECTED]>, 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.