Your message dated Sun, 25 Oct 2020 08:01:06 +0100
with message-id <[email protected]>
and subject line Closing non confirmed bugs
has caused the Debian Bug report #928788,
regarding lmtp socket creation race condition?
to be marked as done.
This means that you claim that the problem has been dealt with.
If this is not the case it is now your responsibility to reopen the
Bug report if necessary, and/or fix the problem forthwith.
(NB: If you are a system administrator and have no idea what this
message is talking about, this may indicate a serious mail system
misconfiguration somewhere. Please contact [email protected]
immediately.)
--
928788: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=928788
Debian Bug Tracking System
Contact [email protected] with problems
--- Begin Message ---
Package: cyrus-imapd
Version: 2.5.10-3
Severity: normal
The players in game are Cyrus, Postfix, Fetchmail and Spamassassin.
I'm facing the following issue with Cyrus and lmtp socket.
Everything is working but when starting Cyrus daemon, it looks like the
socket creation is somehow delayed and delivery of mails are deferred.
Logs are better to explain the issue (care of the timestamps):
# Cyrus starts just fine at 07:16:47 and starts its routines.
may 11 07:16:47 stt005 systemd[1]: Started Cyrus IMAP/POP3 daemons.
# Postfix starts just fine at 07:16:47 and starts its routines...
may 11 07:16:47 stt005 systemd[1]: Starting Postfix Mail Transport Agent
(instance -)...
may 11 07:17:04 stt005 postfix/postfix-script[742]: starting the Postfix mail
system
may 11 07:17:06 stt005 postfix/master[744]: daemon started -- version 3.1.12,
configuration /etc/postfix
may 11 07:17:06 stt005 systemd[1]: Started Postfix Mail Transport Agent
(instance -).
may 11 07:17:14 stt005 postfix/smtpd[775]: connect from localhost[127.0.0.1]
may 11 07:17:17 stt005 postfix/smtpd[775]: 0603D406AD87:
client=localhost[127.0.0.1]
(...)
may 11 07:17:23 stt005 postfix/pickup[745]: 1E72D407050E: uid=117
from=<[email protected]>
may 11 07:17:23 stt005 postfix/cleanup[780]: 1E72D407050E:
message-id=<[email protected]>
may 11 07:17:23 stt005 postfix/qmgr[746]: 1E72D407050E:
from=<[email protected]>, size=15966, nrcpt=1 (queue active)
may 11 07:17:24 stt005 postfix/pipe[856]: 1E72D407050E:
to=<stepc010@workgroup>, relay=cyrus, delay=1.3, delays=0.16/0.23/0/0.9,
dsn=4.3.0, status=deferred (temporary failure. Command output: couldn't connect
to lmtpd: No such file or directory_ 421 4.3.0 deliver: couldn't connect to
lmtpd_ )
# ... but when trying to deliver at 07:17:23 it fails:
may 11 07:17:23 stt005 cyrus/deliver[861]: connect(/run/cyrus/socket/lmtp)
failed: No such file or directory
may 11 07:17:23 stt005 cyrus/deliver[860]: connect(/run/cyrus/socket/lmtp)
failed: No such file or directory
And Postfix is right, at the time there's no lmtp socket created:
# lmtp socket is created at 07:18:09
root@stt005:/etc/postfix# ls -la --full-time /var/run/cyrus/socket/
total 0
drwxr-x--- 2 cyrus mail 100 2019-05-11 07:18:09.277574690 +0200 .
drwxr-xr-x 5 cyrus mail 100 2019-05-11 07:23:39.896299450 +0200 ..
srwxrwxrwx 1 cyrus mail 0 2019-05-11 07:16:55.984084378 +0200 idle
srwxrwxrwx 1 root root 0 2019-05-11 07:18:09.277574690 +0200 lmtp
srwxrwxrwx 1 root root 0 2019-05-11 07:18:09.277574690 +0200 notify
Once the lmtp socket is there, deferred messages start flowing:
# Look at the time stamps:
root@stt005:/usr/sbin# journalctl | grep -i 1E72D407050E
may 11 07:17:23 stt005 postfix/pickup[745]: 1E72D407050E: uid=117
from=<[email protected]>
may 11 07:17:23 stt005 postfix/cleanup[780]: 1E72D407050E:
message-id=<[email protected]>
may 11 07:17:23 stt005 postfix/qmgr[746]: 1E72D407050E:
from=<[email protected]>, size=15966, nrcpt=1 (queue active)
may 11 07:17:24 stt005 postfix/pipe[856]: 1E72D407050E:
to=<stepc010@workgroup>, relay=cyrus, delay=1.3, delays=0.16/0.23/0/0.9,
dsn=4.3.0, status=deferred (temporary failure. Command output: couldn't connect
to lmtpd: No such file or directory_ 421 4.3.0 deliver: couldn't connect to
lmtpd_ )
may 11 07:27:06 stt005 postfix/qmgr[746]: 1E72D407050E:
from=<[email protected]>, size=15966, nrcpt=1 (queue active)
may 11 07:27:08 stt005 postfix/pipe[1279]: 1E72D407050E:
to=<stepc010@workgroup>, relay=cyrus, delay=586, delays=583/2.1/0/0.1,
dsn=2.0.0, status=sent (delivered via cyrus service)
may 11 07:27:08 stt005 postfix/qmgr[746]: 1E72D407050E: removed
The above makes me think there is some kind of delay when creating the
file «/var/run/cyrus/socket/lmtp» because the file is not there when
log message arises «no such file or directory» so I discarded a issue
with socket permissions.
Greetings,
--
Camaleón
--- End Message ---
--- Begin Message ---
These bugs are probably fixed in recent Cyrus-Imapd releases.
--- End Message ---
