[Kolab-devel] [issue4755] postfix silently lost emails during kolab restart

[Gavin McCullagh]

This issue is following up on these posts to kolab-users....

http://kolab.org/pipermail/kolab-users/2011-June/012787.html
http://kolab.org/pipermail/kolab-users/2011-July/thread.html#12788

Hi,

from time to time, we need to stop and start Kolab for small maintenance
tasks.  For example, having recently discovered a few bogus entries in
mailboxes.db, I took kolab down last night for a few minutes so I could use
cyr_dbtool to prune them.

During this time, one of our clients tried to send a mail.  She apparently
got it through to postfix, but the mail then failed to get through
kolabmailboxfilter which gave "service unavailable".  Rather than deferring
the mail for a while, a bounce was generated in response to this.  The
bounce then also hit kolabmailboxfilter and got a service unavailable.

According to the user, she didn't get a bounce and it looks like the mail
never reached the destination either.  That seems quite serious to me.  The
user (using outlook) didn't get a copy written to sent mail, though I'm not
sure how connected that process is.

Is this a bug perhaps?  I would have thought mail should never get silently
dropped like this, even in the event of mail server restart.

Gavin

Jun 29 23:11:58 paidi <info> postfix/smtpd[25786]: connect from
ghrmgr.staff.aaa.bbb[172.16.17.60]
Jun 29 23:11:58 paidi <info> postfix/smtpd[25786]: 7AB9D440C2:
client=ghrmgr.staff.aaa.bbb[172.16.17.60]
Jun 29 23:11:59 paidi <info> postfix/cleanup[25588]: 7AB9D440C2:
message-id=<01f201cc36a9$c51432f0$4f3c98d0$@xxxxxx at aaa.bbb>
Jun 29 23:11:59 paidi <info> postfix/qmgr[24920]: 7AB9D440C2:
from=<xxxx.xxxxxx at aaa.bbb>, size=10862, nrcpt=2 (queue active)
Jun 29 23:11:59 paidi <info> postfix/smtpd[25591]: table
hash:/kolab/etc/postfix/virtual(0,lock|fold_fix) has changed -- restarting
Jun 29 23:11:59 paidi <info> postfix/cleanup[25592]: 2A2FE440C5:
message-id=<01f201cc36a9$c51432f0$4f3c98d0$@xxxxxx at aaa.bbb>
Jun 29 23:11:59 paidi <info> postfix/qmgr[24920]: 2A2FE440C5:
from=<xxxx.xxxxxx at aaa.bbb>, size=11006, nrcpt=3 (queue active)
Jun 29 23:11:59 paidi <info> postfix/smtpd[26072]: disconnect from
localhost[127.0.0.1]
Jun 29 23:11:59 paidi <info> postfix/pipe[25589]: 7AB9D440C2:
to=<zzzzzzzzzz at aaa.bbb>, relay=kolabfilter, delay=0.74, delays=0.64/0/0/0.1,
dsn=2.0.0,status=sent (delivered via kolabfilter service)
Jun 29 23:11:59 paidi <info> postfix/pipe[25589]: 7AB9D440C2:
to=<yyyyyyy.yyyyyy at aaa.bbb>, relay=kolabfilter, delay=0.74, delays=0.64/0/0/0.1,
      dsn=2.0.0, status=sent (delivered via kolabfilter service)
Jun 29 23:11:59 paidi <info> postfix/qmgr[24920]: 7AB9D440C2: removed
Jun 29 23:11:59 paidi <info> postfix/smtpd[25596]: table
hash:/kolab/etc/postfix/virtual(0,lock|fold_fix) has changed -- restarting
Jun 29 23:11:59 paidi <info> postfix/smtpd[26074]: connect from localhost[127.0.0.1]
Jun 29 23:11:59 paidi <info> postfix/smtpd[26074]: CC707440C2:
client=localhost[127.0.0.1]
Jun 29 23:11:59 paidi <info> postfix/cleanup[25592]: CC707440C2:
message-id=<01f201cc36a9$c51432f0$4f3c98d0$@xxxxxx at aaa.bbb>
Jun 29 23:11:59 paidi <info> postfix/smtpd[26074]: disconnect from
localhost[127.0.0.1]
Jun 29 23:11:59 paidi <info> postfix/qmgr[24920]: CC707440C2:
from=<xxxx.xxxxxx at aaa.bbb>, size=11372, nrcpt=4 (queue active)
Jun 29 23:11:59 paidi <info> postfix/smtp[25593]: 2A2FE440C5:
to=<zzzzzzzzzz at aaa.bbb>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.74,         
       delays=0.04/0/0/0.69, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as
CC707440C2)
Jun 29 23:11:59 paidi <info> postfix/smtp[25593]: 2A2FE440C5:
to=<zzzzzzzzzz at aaa.bbb>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.74,         
       delays=0.04/0/0/0.69, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as
CC707440C2)
Jun 29 23:11:59 paidi <info> postfix/smtp[25593]: 2A2FE440C5:
to=<yyyyyyy.yyyyyy at aaa.bbb>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.74,     
       delays=0.04/0/0/0.69, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as
CC707440C2)
Jun 29 23:11:59 paidi <info> postfix/qmgr[24920]: 2A2FE440C5: removed
Jun 29 23:11:59 paidi <info> postfix/pipe[25633]: CC707440C2:
to=<yyyyyyy.yyyyyy at aaa.bbb>, relay=kolabmailboxfilter, delay=0.09,             
       delays=0.01/0/0/0.08, dsn=5.3.0, status=bounced (service unavailable)
Jun 29 23:11:59 paidi <info> postfix/pipe[25638]: CC707440C2:
to=<zzzzzzzzzz at aaa.bbb>, relay=kolabmailboxfilter, delay=0.09,
delays=0.01/0/0/0.08,   dsn=5.3.0, status=bounced (service unavailable)
Jun 29 23:11:59 paidi <info> postfix/pipe[25604]: CC707440C2:
to=<zzzzzzzzzz at aaa.bbb>, relay=kolabmailboxfilter, delay=0.09,
delays=0.01/0/0/0.08,   dsn=5.3.0, status=bounced (service unavailable)
Jun 29 23:11:59 paidi <info> postfix/pipe[25632]: CC707440C2:
to=<zzzzzzzzzz at aaa.bbb>, relay=kolabmailboxfilter, delay=0.14,
delays=0.01/0.08/0/0.05,dsn=5.3.0, status=bounced (service unavailable)
Jun 29 23:11:59 paidi <info> postfix/cleanup[25588]: table
hash:/kolab/etc/postfix/virtual(0,lock|fold_fix) has changed -- restarting
Jun 29 23:11:59 paidi <info> postfix/cleanup[26081]: EEC4C440D5:
message-id=<20110629221159.EEC4C440D5 at paidi.aaa.bbb>
Jun 29 23:11:59 paidi <info> postfix/qmgr[24920]: EEC4C440D5: from=<>,
size=13336, nrcpt=1 (queue active)
Jun 29 23:11:59 paidi <info> postfix/bounce[26079]: CC707440C2: sender
non-delivery notification: EEC4C440D5
Jun 29 23:11:59 paidi <info> postfix/qmgr[24920]: CC707440C2: removed
Jun 29 23:12:00 paidi <info> postfix/pipe[25617]: EEC4C440D5:
to=<xxxx.xxxxxx at aaa.bbb>, relay=kolabmailboxfilter, delay=0.06,
delays=0.01/0/0/0.05,  dsn=5.3.0, status=bounced (service unavailable)
Jun 29 23:12:00 paidi <info> postfix/qmgr[24920]: EEC4C440D5: removed
Jun 29 23:12:08 paidi <info> postfix/trivial-rewrite[25784]: table
hash:/kolab/etc/postfix/virtual(0,lock|fold_fix) has changed -- restarting
Jun 29 23:12:27 paidi <info> postfix/smtpd[25786]: disconnect from
ghrmgr.staff.aaa.bbb[172.16.17.60]
Jun 29 23:12:27 paidi <info> postfix/smtpd[25538]: table
hash:/kolab/etc/postfix/virtual(0,lock|fold_fix) has changed -- restarting
Jun 29 23:12:27 paidi <info> postfix/smtpd[25786]: table
hash:/kolab/etc/postfix/virtual(0,lock|fold_fix) has changed -- restarting

----------
messages: 28017
nosy: gavinmc
status: unread
title: postfix silently lost emails during kolab restart

______________________________________
Kolab issue tracker <issues at kolab.org>
<https://issues.kolab.org/issue4755>
______________________________________