#802369 dovecot-lmtpd: lmtpd stops responding, fails to restart

Package:
dovecot-lmtpd
Source:
dovecot
Description:
secure POP3/IMAP server - LMTP server
Submitter:
Ralf Jung
Date:
2015-10-19 19:03:05 UTC
Severity:
normal
#802369#5
Date:
2015-10-19 19:02:13 UTC
From:
To:
Dear Maintainer,

yesterday around 9:30, dovecot-lmtpd stopped working properly. This is what I can see
in "fgrep dovecot mail.log":

  Oct 18 09:27:37 h2020100 postfix/lmtp[11830]: 8489917D01D6: to=<ralf@ralfj.de>, orig_to=<post@ralfj.de>, relay=mx.ralfj.de[private/dovecot-lmtp], delay=601, delays=0.45/0.02/0.34/600, dsn=4.4.2, status=deferred (conversation with mx.ralfj.de[private/dovecot-lmtp] timed out while sending end of data -- message may be sent more than once)
  Oct 18 09:42:44 h2020100 postfix/lmtp[13202]: 8489917D01D6: to=<ralf@ralfj.de>, orig_to=<post@ralfj.de>, relay=mx.ralfj.de[private/dovecot-lmtp], delay=1508, delays=1207/0.03/300/0, dsn=4.4.2, status=deferred (conversation with mx.ralfj.de[private/dovecot-lmtp] timed out while performing the LHLO handshake)
  Oct 18 09:52:08 h2020100 postfix/lmtp[14393]: D8A5F17D09D5: to=<ralf@ralfj.de>, orig_to=<root@ralfj.de>, relay=mx.ralfj.de[private/dovecot-lmtp], delay=300, delays=0.07/0.02/300/0, dsn=4.4.2, status=deferred (conversation with mx.ralfj.de[private/dovecot-lmtp] timed out while performing the LHLO handshake)
  ...

Coincidentally, a few hours later, a wave of backscatter spam starts to hit my server. Only now
can I also see messages from dovecot itself in the log:

  Oct 18 15:57:44 h2020100 dovecot: master: Warning: service(lmtp): process_limit (100) reached, client connections are being dropped
  Oct 18 16:03:09 h2020100 dovecot: master: Warning: service(lmtp): process_limit (100) reached, client connections are being dropped
  Oct 18 16:07:07 h2020100 dovecot: master: Warning: service(lmtp): process_limit (100) reached, client connections are being dropped
  ...

I did not notice this until around 13:00 today, when a friend told me he's getting delayed notifcations
from my mail server. Only a few hours later, I could finally look into the situation.
When I tried to restarts dovecot using "service dovecot restart", that did not work:

  Oct 19 16:11:08 h2020100 dovecot: master: Warning: Killed with signal 15 (by pid=2229 uid=0 code=kill)
  Oct 19 16:11:08 h2020100 dovecot: master: Error: service(lmtp): Socket already exists: /var/run/dovecot/lmtp
  Oct 19 16:11:08 h2020100 dovecot: master: Error: service(lmtp): Socket already exists: /var/spool/postfix/private/dovecot-lmtp
  Oct 19 16:11:08 h2020100 dovecot: master: Fatal: Failed to start listeners

Clearly, dovecot is in some form of broken state. Whether that has been caused by the huge wave
of mails I got due to the backscatter, I cannot tell.

I managed to properly restart dovecot with "service dovecot stop" followed by
"service dovecot start". Then, the ~20k mails postfix still had in the
queue (the entire wave of backscatter spam) hit my inbox, which dovecot
managed just fine.

Kind regards,
Ralf