systemd timeout on startup after upgrade
Hello *,
I have upgraded today a Debian buster (stable) system to bullseye (still testing). After upgrade I did a complete reboot of the VM.
Dovecot version changed from 1:2.3.4.1-5+deb10u6 to 1:2.3.13+dfsg1-1
systemctl start dovecot now complains
Job for dovecot.service failed because a timeout was exceeded.
As a workaround I set "TimeoutStartSec=infinity" in dovecot.service.
But systemctl status now says:
Active: activating (start) since Sat 2021-04-17 17:53:58 CEST; 1h 23min ago
Dovecot itself is working fine without problems. LMTP accepts new mails and IMAP works. It's just that systemd doestn't notice it running.
Any idea what causes this?
Config is unchanged from the working 2.3.4.1 system.
# doveconf -n # 2.3.13 (89f716dc2): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.13 (cdd19fe3) # OS: Linux 5.10.0-6-cloud-amd64 x86_64 Debian bullseye/sid # Hostname: daedalus.z-51.de auth_master_user_separator = * auth_mechanisms = plain login auth_ssl_username_from_cert = yes auth_verbose = yes auth_verbose_passwords = plain default_vsz_limit = 2 G first_valid_uid = 8 import_environment = TZ last_valid_uid = 8 lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes login_log_format_elements = user=<%u> method=%m rip=%r lip=%l mpid=%e %c ssl_security=%k login_trusted_networks = 127.0.0.1 ::1 mail_gid = mail mail_location = maildir:~/Maildir mail_plugins = acl zlib quota fts fts_xapian mail_privileged_group = mail mail_uid = mail maildir_very_dirty_syncs = yes managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded- character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date index ihave duplicate mime foreverypart extracttext imapsieve vnd.dovecot.imapsieve namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Spam { special_use = \Junk } mailbox Trash { special_use = \Trash } prefix = separator = / } passdb { args = scheme=CRYPT username_format=%Lu /etc/dovecot/users driver = passwd-file } plugin { acl = vfile:/etc/dovecot/global-acls:cache_secs=300 fts = xapian fts_autoindex = yes fts_autoindex_exclude = \Junk fts_autoindex_exclude2 = \Trash fts_xapian = partial=3 full=20 attachments=0 verbose=0 imapsieve_mailbox1_before = file:/var/mail/sieve/report-spam.sieve imapsieve_mailbox1_causes = COPY imapsieve_mailbox1_name = Spam imapsieve_mailbox2_before = file:/var/mail/sieve/report-ham.sieve imapsieve_mailbox2_causes = COPY imapsieve_mailbox2_from = Spam imapsieve_mailbox2_name = * sieve = file:~/sieve;active=~/.dovecot.sieve sieve_before = /var/mail/sieve/before.sieve sieve_global_extensions = +vnd.dovecot.pipe +vnd.dovecot.execute sieve_pipe_bin_dir = /var/mail/sieve sieve_plugins = sieve_imapsieve sieve_extprograms sieve_redirect_envelope_from = recipient sieve_vacation_default_period = 1d stats_refresh = 30 secs stats_track_cmds = yes } postmaster_address = postmaster@z-51.de protocols = " imap lmtp sieve" service auth-worker { user = $default_internal_user } service auth { unix_listener auth-client { group = Debian-exim mode = 0777 user = Debian-exim } unix_listener auth-userdb { group = Debian-exim mode = 0777 user = Debian-exim } vsz_limit = 2 G } service imap-login { inet_listener imap { port = 143 } inet_listener imaps { port = 993 ssl = yes } } service indexer-worker { vsz_limit = 0 } service lmtp { user = mail } service managesieve-login { inet_listener sieve { address = 127.0.0.1 ::1 port = 4190 } service_count = 1 } service managesieve { process_limit = 1024 } service stats { fifo_listener stats-mail { mode = 0600 user = mail } unix_listener stats-writer { user = mail } } ssl = required ssl_cert =
Felix Zielcke said on Sat, 17 Apr 2021 19:37:30 +0200
Hello *,
I have upgraded today a Debian buster (stable) system to bullseye (still testing). After upgrade I did a complete reboot of the VM.
Dovecot version changed from 1:2.3.4.1-5+deb10u6 to 1:2.3.13+dfsg1-1
systemctl start dovecotnow complains Job for dovecot.service failed because a timeout was exceeded.As a workaround I set "TimeoutStartSec=infinity" in dovecot.service. But
systemctl statusnow says:
Systemd's got problems. I use runit to start dovecot.
Without dumping systemd, you can start the runit process supervisor from systemd, and then start any other daemons from runit. I used to use this method (with daemontools instead of the very similar runit) to avoid starting from sysvinit. I don't use systemd, but if I did, I'd use it as little as possible, because it's a very complicated, very ever-scope-expanding moving target.
I don't even call the above described method as a workaround, because I consider systemd the root cause.
SteveT
Steve Litt Spring 2021 featured book: Troubleshooting Techniques of the Successful Technologist http://www.troubleshooters.com/techniques
If systemd doesn't recognize that service has started, that mean probably pid file has other location than previously. You can check what systemd is doing via strace:
strace -s 1024 systemctl start dovecot
W dniu 17 kwi 2021, 19:39, o 19:39, użytkownik Felix Zielcke fzielcke@z-51.de napisał:
Hello *,
I have upgraded today a Debian buster (stable) system to bullseye (still testing). After upgrade I did a complete reboot of the VM.
Dovecot version changed from 1:2.3.4.1-5+deb10u6 to 1:2.3.13+dfsg1-1
systemctl start dovecotnow complains Job for dovecot.service failed because a timeout was exceeded.As a workaround I set "TimeoutStartSec=infinity" in dovecot.service. But
systemctl statusnow says:Active: activating (start) since Sat 2021-04-17 17:53:58 CEST; 1h 23min ago
Dovecot itself is working fine without problems. LMTP accepts new mails and IMAP works. It's just that systemd doestn't notice it running.
Any idea what causes this?
Config is unchanged from the working 2.3.4.1 system.
# doveconf -n # 2.3.13 (89f716dc2): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.13 (cdd19fe3) # OS: Linux 5.10.0-6-cloud-amd64 x86_64 Debian bullseye/sid # Hostname: daedalus.z-51.de auth_master_user_separator = * auth_mechanisms = plain login auth_ssl_username_from_cert = yes auth_verbose = yes auth_verbose_passwords = plain default_vsz_limit = 2 G first_valid_uid = 8 import_environment = TZ last_valid_uid = 8 lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes login_log_format_elements = user=<%u> method=%m rip=%r lip=%l mpid=%e %c ssl_security=%k login_trusted_networks = 127.0.0.1 ::1 mail_gid = mail mail_location = maildir:~/Maildir mail_plugins = acl zlib quota fts fts_xapian mail_privileged_group = mail mail_uid = mail maildir_very_dirty_syncs = yes managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded- character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date index ihave duplicate mime foreverypart extracttext imapsieve vnd.dovecot.imapsieve namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Spam { special_use = \Junk } mailbox Trash { special_use = \Trash } prefix = separator = / } passdb { args = scheme=CRYPT username_format=%Lu /etc/dovecot/users driver = passwd-file } plugin { acl = vfile:/etc/dovecot/global-acls:cache_secs=300 fts = xapian fts_autoindex = yes fts_autoindex_exclude = \Junk fts_autoindex_exclude2 = \Trash fts_xapian = partial=3 full=20 attachments=0 verbose=0 imapsieve_mailbox1_before = file:/var/mail/sieve/report-spam.sieve imapsieve_mailbox1_causes = COPY imapsieve_mailbox1_name = Spam imapsieve_mailbox2_before = file:/var/mail/sieve/report-ham.sieve imapsieve_mailbox2_causes = COPY imapsieve_mailbox2_from = Spam imapsieve_mailbox2_name = * sieve = file:~/sieve;active=~/.dovecot.sieve sieve_before = /var/mail/sieve/before.sieve sieve_global_extensions = +vnd.dovecot.pipe +vnd.dovecot.execute sieve_pipe_bin_dir = /var/mail/sieve sieve_plugins = sieve_imapsieve sieve_extprograms sieve_redirect_envelope_from = recipient sieve_vacation_default_period = 1d stats_refresh = 30 secs stats_track_cmds = yes } postmaster_address = postmaster@z-51.de protocols = " imap lmtp sieve" service auth-worker { user = $default_internal_user } service auth { unix_listener auth-client { group = Debian-exim mode = 0777 user = Debian-exim } unix_listener auth-userdb { group = Debian-exim mode = 0777 user = Debian-exim } vsz_limit = 2 G } service imap-login { inet_listener imap { port = 143 } inet_listener imaps { port = 993 ssl = yes } } service indexer-worker { vsz_limit = 0 } service lmtp { user = mail } service managesieve-login { inet_listener sieve { address = 127.0.0.1 ::1 port = 4190 } service_count = 1 } service managesieve { process_limit = 1024 } service stats { fifo_listener stats-mail { mode = 0600 user = mail } unix_listener stats-writer { user = mail } } ssl = required ssl_cert =
Am Sonntag, dem 18.04.2021 um 01:04 +0200 schrieb Łukasz Szczepański:
If systemd doesn't recognize that service has started, that mean probably pid file has other location than previously. You can check what systemd is doing via strace:
strace -s 1024 systemctl start dovecot
strace doestn't show anything about opening a pid file.
There's a few repeated of these:
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="/org/freedesktop/systemd1/unit/dovecot_2eservice\0\0\0\0\0\0\0\0\2\1s\0\37\0\0\0org.freedesktop.DBus.Properties\0\3\1s\0\21\0\0\0PropertiesChanged\0\0\0\0\0\0\0\7\1s\0\30\0\0\0org.freedesktop.systemd1\0\0\0\0\0\0\0\0\10\1g\0\10sa{sv}as\0\0\0\35\0\0\0org.freedesktop.systemd1.Unit\0\0\0d\3\0\0\v\0\0\0ActiveState\0\1s\0\0\10\0\0\0inactive\0\0\0\0\0\0\0\0\f\0\0\0FreezerState\0\1s\0\7\0\0\0running\0\10\0\0\0SubState\0\1s\0\4\0\0\0dead\0\0\0\0\0\0\0\0\24\0\0\0StateChangeTimestamp\0\1t\0\0\0\0\0\5\252\316m8\300\5\0\35\0\0\0StateChangeTimestampMonotonic\0\1t\0\0\0\0\357v\2604\r\0\0\0\25\0\0\0InactiveExitTimestamp\0\1t\0\0\0\0\214kJZ8\300\5\0\36\0\0\0InactiveExitTimestampMonotonic\0\1t\0\0\0v8,!\r\0\0\0\24\0\0\0ActiveEnterTimestamp\0\1t\0\0\0\0\0\0\0\0\0\0\0\0\0\35\0\0\0ActiveEnterTimestampMonotonic\0\1t\0\0\0\0\0\0\0\0\0\0\0\0\23\0\0\0ActiveExitTimestamp\0\1t\0\0\0\0\0\0\0\0\0\0\0\0\0\0\34\0\0\0ActiveExitTimestampMonotonic\0\1t\0\0\0\0\0\0\0\0\0\0\0\0\0\26\0\0\0InactiveEnterTimestamp\0\1t\0\0\0\5\252\316m8\300\5\0\37\0\0\0InactiveEnterTimestampMonotonic\0\1t\0\0\357v\2604\r\0\0\0\3\0\0\0Job\0\4(uo)\0\0\0\207\360\0\0#\0\0\0/org/freedesktop/systemd1/job/61575\0\0\0\0\0\17\0\0\0ConditionResult\0\1b\0\0\1\0\0\0\0\0\0\0\f\0\0\0AssertResult\0\1b\0\1\0\0\0\22\0\0\0ConditionTimestamp\0\1t\0\0\0\0\0\0\0005l\nn8\300\5\0\33\0\0\0ConditionTimestampMonotonic\0\1t\0\0\0\0\0\0\379\3544\r\0\0\0\17\0\0\0AssertTimestamp\0\1t\0\08l\nn8\300\5\0\30\0\0\0AssertTimest"..., iov_len=1124}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 1124 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\4\1\0013\3\0\0\7\0\0\0\276\0\0\0\1\1o\0000\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 24
And then it ends in a loop with a failing
recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Die Ressource ist zur Zeit nicht verfügbar)
The strange thing is, that strace mentions then even php7.4-fpm. Which should have nothing to do with the systemctl start dovecot?
Anyone here has a bullseye system where this works? Maybe I also should report this to the Debian BTS.
systemd don’t need pid files, and the executable must be started without forking.
Can you show us the content fo the system dovecot.service file. As long as it contains this line, it should be fine:
Type=simple ExecStart=/usr/sbin/dovecot -F
Le 18 avr. 2021 à 07:34, Felix Zielcke fzielcke@z-51.de a écrit :
Am Sonntag, dem 18.04.2021 um 01:04 +0200 schrieb Łukasz Szczepański:
If systemd doesn't recognize that service has started, that mean probably pid file has other location than previously. You can check what systemd is doing via strace:
strace -s 1024 systemctl start dovecot
strace doestn't show anything about opening a pid file.
There's a few repeated of these:
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="/org/freedesktop/systemd1/unit/dovecot_2eservice\0\0\0\0\0\0\0\0\2\1s\0\37\0\0\0org.freedesktop.DBus.Properties\0\3\1s\0\21\0\0\0PropertiesChanged\0\0\0\0\0\0\0\7\1s\0\30\0\0\0org.freedesktop.systemd1\0\0\0\0\0\0\0\0\10\1g\0\10sa{sv}as\0\0\0\35\0\0\0org.freedesktop.systemd1.Unit\0\0\0d\3\0\0\v\0\0\0ActiveState\0\1s\0\0\10\0\0\0inactive\0\0\0\0\0\0\0\0\f\0\0\0FreezerState\0\1s\0\7\0\0\0running\0\10\0\0\0SubState\0\1s\0\4\0\0\0dead\0\0\0\0\0\0\0\0\24\0\0\0StateChangeTimestamp\0\1t\0\0\0\0\0\5\252\316m8\300\5\0\35\0\0\0StateChangeTimestampMonotonic\0\1t\0\0\0\0\357v\2604\r\0\0\0\25\0\0\0InactiveExitTimestamp\0\1t\0\0\0\0\214kJZ8\300\5\0\36\0\0\0InactiveExitTimestampMonotonic\0\1t\0\0\0v8,!\r\0\0\0\24\0\0\0ActiveEnterTimestamp\0\1t\0\0\0\0\0\0\0\0\0\0\0\0\0\35\0\0\0ActiveEnterTimestampMonotonic\0\1t\0\0\0\0\0\0\0\0\0\0\0\0\23\0\0\0ActiveExitTimestamp\0\1t\0\0\0\0\0\0\0\0\0\0\0\0\0\0\34\0\0\0ActiveExitTimestampMonotonic\0\1t\0\0\0\0\0\0\0\0\0\0\0\0\0\26\0\0\0InactiveEnterTimestamp\0\1t\0\0\0\5\252\316m8\300\5\0\37\0\0\0InactiveEnterTimestampMonotonic\0\1t\0\0\357v\2604\r\0\0\0\3\0\0\0Job\0\4(uo)\0\0\0\207\360\0\0#\0\0\0/org/freedesktop/systemd1/job/61575\0\0\0\0\0\17\0\0\0ConditionResult\0\1b\0\0\1\0\0\0\0\0\0\0\f\0\0\0AssertResult\0\1b\0\1\0\0\0\22\0\0\0ConditionTimestamp\0\1t\0\0\0\0\0\0\0005l\nn8\300\5\0\33\0\0\0ConditionTimestampMonotonic\0\1t\0\0\0\0\0\0\379\3544\r\0\0\0\17\0\0\0AssertTimestamp\0\1t\0\08l\nn8\300\5\0\30\0\0\0AssertTimest"..., iov_len=1124}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 1124 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\4\1\0013\3\0\0\7\0\0\0\276\0\0\0\1\1o\0000\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 24
And then it ends in a loop with a failing
recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Die Ressource ist zur Zeit nicht verfügbar)
The strange thing is, that strace mentions then even php7.4-fpm. Which should have nothing to do with the
systemctl start dovecot?Anyone here has a bullseye system where this works? Maybe I also should report this to the Debian BTS.
Am Sonntag, dem 18.04.2021 um 08:17 +0200 schrieb Jean-Daniel:
systemd don’t need pid files, and the executable must be started without forking.
Can you show us the content fo the system dovecot.service file. As long as it contains this line, it should be fine:
Type=simple ExecStart=/usr/sbin/dovecot -F
Just before I saw your mail, I found now a solution.
The original dovecot.service has this:
[Service] Type=notify ExecStart=/usr/sbin/dovecot -F
which according to systemd.service man page needs a sd_notify() call from the running process. So somehow this is broken now?
I changed it to the following and now it works:
[Service] Type=forking ExecStart=/usr/sbin/dovecot
I don't know that much about systemd what of forking/exec/simple would be the best one.
Le 18 avr. 2021 à 08:22, Felix Zielcke fzielcke@z-51.de a écrit :
Am Sonntag, dem 18.04.2021 um 08:17 +0200 schrieb Jean-Daniel:
systemd don’t need pid files, and the executable must be started without forking.
Can you show us the content fo the system dovecot.service file. As long as it contains this line, it should be fine:
Type=simple ExecStart=/usr/sbin/dovecot -F
Just before I saw your mail, I found now a solution.
The original dovecot.service has this:
[Service] Type=notify ExecStart=/usr/sbin/dovecot -F
which according to systemd.service man page needs a sd_notify() call from the running process. So somehow this is broken now?
I changed it to the following and now it works:
[Service] Type=forking ExecStart=/usr/sbin/dovecot
I don't know that much about systemd what of forking/exec/simple would be the best one.
The forking type exists mainly for compatibility with executables that are not able to start without forking.
When an executable as a « foreground » mode, it is usually recommended to use it instead.
The snippet I posted come from the official dovecot ubuntu distribution (from https://repo.dovecot.org https://repo.dovecot.org/) (that’s the one I’m using).
Am Sonntag, dem 18.04.2021 um 08:36 +0200 schrieb Jean-Daniel:
The forking type exists mainly for compatibility with executables that are not able to start without forking.
When an executable as a « foreground » mode, it is usually recommended to use it instead.
The snippet I posted come from the official dovecot ubuntu distribution (from https://repo.dovecot.org https://repo.dovecot.org/) (that’s the one I’m using).
Thanks to every one who brought me on the right track.
I reported this now at the Debian BTS. It looks like it's a Debian specific problem. The package there has a patch to enable notify support.
On 18/04/2021 10:42 Felix Zielcke fzielcke@z-51.de wrote:
Am Sonntag, dem 18.04.2021 um 08:36 +0200 schrieb Jean-Daniel:
The forking type exists mainly for compatibility with executables that are not able to start without forking.
When an executable as a « foreground » mode, it is usually recommended to use it instead.
The snippet I posted come from the official dovecot ubuntu distribution (from https://repo.dovecot.org https://repo.dovecot.org/) (that’s the one I’m using).
Thanks to every one who brought me on the right track.
I reported this now at the Debian BTS. It looks like it's a Debian specific problem. The package there has a patch to enable notify support.
Hi!
This has been fixed in dovecot with
https://github.com/dovecot/core/compare/19e05adc3657d2133412635f1345b53cc210...
It will be released in 2.3.15.
Aki
Am Sonntag, dem 18.04.2021 um 13:51 +0300 schrieb Aki Tuomi:
This has been fixed in dovecot with
https://github.com/dovecot/core/compare/19e05adc3657d2133412635f1345b53cc210...
It will be released in 2.3.15.
Aki
The real problem was my config. Somehow I uncommented the "import_environment = TZ" in dovecot.conf And that needs a NOTIFY_SOCKET added. Now the systemd notify support works without problems.
participants (5)
-
Aki Tuomi
-
Felix Zielcke
-
Jean-Daniel
-
Steve Litt
-
Łukasz Szczepański