Postfix, Dovecot (and others) keep restarting every minute

dassams

Lately I observed, that (at least) Postfix and Dovecot keep restarting (inside their containers) approx. every minute. (See log below). Any idea what could cause this - or how to debug?! The system seems to work fine; but every now and then the services are (of course) not reachable.

Sep 24 14:06:47 1492ccf81503 syslog-ng[153]: syslog-ng starting up; version='3.28.1' Sep 24 14:07:10 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:07:10 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:08:09 1492ccf81503 syslog-ng[157]: syslog-ng starting up; version='3.28.1' Sep 24 14:08:09 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:09:10 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:09:10 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:10:09 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:10:09 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:11:10 1492ccf81503 syslog-ng[147]: syslog-ng starting up; version='3.28.1' Sep 24 14:11:10 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:12:10 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:12:10 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:13:09 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:13:09 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:14:10 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:14:10 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:15:09 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:15:09 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:16:10 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:16:10 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:17:09 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:17:09 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:18:09 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:18:09 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:19:09 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:19:09 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:20:09 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:20:09 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:21:10 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:21:10 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:22:09 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:22:09 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3 Sep 24 14:23:10 1492ccf81503 syslog-ng[146]: syslog-ng starting up; version='3.28.1' Sep 24 14:23:10 1492ccf81503 dovecot: master: Dovecot v2.3.19.1 (9b53102964) starting up for imap, sieve, lmtp, pop3

Sep 24 14:06:42 55e5c86e62cb syslog-ng[10]: syslog-ng starting up; version='3.28.1' Sep 24 14:06:45 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:07:06 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:07:08 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:08:06 55e5c86e62cb syslog-ng[10]: syslog-ng starting up; version='3.28.1' Sep 24 14:08:08 55e5c86e62cb postfix/postfix-script[375]: starting the Postfix mail system Sep 24 14:09:06 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:09:08 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:10:06 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:10:08 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:11:06 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:11:08 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:12:06 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:12:08 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:13:05 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:13:07 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:14:06 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:14:08 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:15:05 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:15:07 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:16:05 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:16:07 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:17:05 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:17:07 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:18:05 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:18:07 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:19:05 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:19:07 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:20:05 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:20:07 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:21:05 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:21:07 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:22:05 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:22:07 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system Sep 24 14:23:06 55e5c86e62cb syslog-ng[9]: syslog-ng starting up; version='3.28.1' Sep 24 14:23:08 55e5c86e62cb postfix/postfix-script[374]: starting the Postfix mail system

dassams

Further analysis shows, that the container is actually restarted every minute and it affects dovecot, postifx and nginx:

419cb77d7839 mailcow/rspamd:1.90 "/docker-entrypoint.…" 6 hours ago Up 6 hours mailcowdockerized-rspamd-mailcow-1 aeafb2844b55 mcuadros/ofelia:latest "/usr/bin/ofelia dae…" 6 hours ago Up 6 hours mailcowdockerized-ofelia-mailcow-1 2f26f86dc586 mailcow/netfilter:1.48 "python3 -u /server.…" 6 hours ago Up 6 hours mailcowdockerized-netfilter-mailcow-1 92364857ef6f mailcow/acme:1.82 "/sbin/tini -g -- /s…" 6 hours ago Up 6 hours mailcowdockerized-acme-mailcow-1 c55fa245f6e7 nginx:mainline-alpine "/docker-entrypoint.…" 6 hours ago Up 59 seconds 0.0.0.0:8080->8080/tcp, :::8080->8080/tcp, 80/tcp, 0.0.0.0:8443->8443/tcp, :::8443->8443/tcp mailcowdockerized-nginx-mailcow-1 1492ccf81503 mailcow/dovecot:1.19 "/docker-entrypoint.…" 6 hours ago Up Less than a second 0.0.0.0:110->110/tcp, :::110->110/tcp, 0.0.0.0:143->143/tcp, :::143->143/tcp, 0.0.0.0:993->993/tcp, :::993->993/tcp, 0.0.0.0:995->995/tcp, :::995->995/tcp, 0.0.0.0:4190->4190/tcp, :::4190->4190/tcp, 127.0.0.1:19991->12345/tcp mailcowdockerized-dovecot-mailcow-1 55e5c86e62cb mailcow/postfix:1.67 "/docker-entrypoint.…" 6 hours ago Up 3 seconds 0.0.0.0:25->25/tcp, :::25->25/tcp, 0.0.0.0:465->465/tcp, :::465->465/tcp, 0.0.0.0:587->587/tcp, :::587->587/tcp, 588/tcp mailcowdockerized-postfix-mailcow-1 58ca1b25a699 mailcow/phpfpm:1.79 "/docker-entrypoint.…" 6 hours ago Up 6 hours 9000/tcp mailcowdockerized-php-fpm-mailcow-1 302258fe9e5a mariadb:10.5 "docker-entrypoint.s…" 6 hours ago Up 6 hours 127.0.0.1:13306->3306/tcp mailcowdockerized-mysql-mailcow-1 dd4d47d99df3 mailcow/clamd:1.54 "/sbin/tini -g -- /c…" 6 hours ago Up 6 hours (healthy) 3310/tcp, 7357/tcp mailcowdockerized-clamd-mailcow-1 3d426ee9ff09 mailcow/sogo:1.111 "/docker-entrypoint.…" 6 hours ago Up 6 hours mailcowdockerized-sogo-mailcow-1 fce47f6a8927 mailcow/solr:1.8.1 "docker-entrypoint.s…" 6 hours ago Up 6 hours 127.0.0.1:18983->8983/tcp mailcowdockerized-solr-mailcow-1 4f6c3cf309b9 mailcow/watchdog:1.96 "/bin/sh -c /watchdo…" 6 hours ago Up 6 hours mailcowdockerized-watchdog-mailcow-1 cf6869d40aa5 mailcow/unbound:1.16 "/docker-entrypoint.…" 6 hours ago Up 6 hours 53/tcp, 53/udp mailcowdockerized-unbound-mailcow-1 c19fc28fc880 mailcow/olefy:1.10 "python3 -u /app/ole…" 6 hours ago Up 6 hours mailcowdockerized-olefy-mailcow-1 54479ef88126 redis:6-alpine "docker-entrypoint.s…" 6 hours ago Up 6 hours 127.0.0.1:7654->6379/tcp mailcowdockerized-redis-mailcow-1 0f8ea7cd70c4 memcached:alpine "docker-entrypoint.s…" 6 hours ago Up 6 hours 11211/tcp mailcowdockerized-memcached-mailcow-1 7bceca17c736 mailcow/dockerapi:1.42 "python3 -u /app/doc…" 6 hours ago Up 6 hours mailcowdockerized-dockerapi-mailcow-1

aaronsmith

Perhaps check /var/log/syslog (or wherever your syslog writes to) and see if any errors are being recorded about the container leading to the restart?

You could also temporarily change the restart policy to give yourself more control over the situation until you sort out the cause:

The docker-compose.yml has “restart: always” configured for each container, you could change to “restart: no” and run docker compose up -d.

docker inspect <container-id> | grep -A 1 RestartPolicy will confirm the container’s configuration is updated.

dassams

That is weird: after 3hrs of continuous restarting of the container, they are now running for 9 hours straight:
[...] mailcow/postfix:1.67 "/docker-entrypoint.…" 12 hours ago Up 9 hours [...]

However, I think it is somewhat network related: only containers which are have a bridged network are affected. (Only by mailcow; other containers don’t show that behavior). Also, syslog shows a lot of network related logs:

Sep 18 20:11:20 bender systemd[1]: run-docker-netns-99c02238aac0.mount: Succeeded.
Sep 18 20:11:20 bender systemd[944473]: run-docker-netns-99c02238aac0.mount: Succeeded.
Sep 18 20:11:20 bender dockerd[958519]: time="2022-09-18T20:11:20.068975588+02:00" level=error msg="getEndpointFromStore for eid 66a4c25f7cde327d0aa3114f1a359891eebac40ebe08d1655deaa7c2a50a589a failed while trying to build sandbox for cleanup: could not find endpoint 66a4c25f7cde327d0aa3114f1a359891eebac40ebe08d1655deaa7c2a50a589a: []"
Sep 18 20:11:20 bender dockerd[958519]: time="2022-09-18T20:11:20.069008475+02:00" level=info msg="Removing stale sandbox 99c02238aac06155f1b02c1fdb777da74cd701a2f470a44194c29bc579081cda (a4ff61481ee7a8bbe3250e3b0fea54a7919559caff2c4f74b597b2835dc23fbe)"
Sep 18 20:11:20 bender dockerd[958519]: time="2022-09-18T20:11:20.069255888+02:00" level=warning msg="Failed deleting endpoint 66a4c25f7cde327d0aa3114f1a359891eebac40ebe08d1655deaa7c2a50a589a: failed to get endpoint from store during Delete: could not find endpoint 66a4c25f7cde327d0aa3114f1a359891eebac40ebe08d1655deaa7c2a50a589a: []\n"
Sep 18 20:11:20 bender systemd[944473]: run-docker-netns-99c02238aac0.mount: Succeeded.
Sep 18 20:11:20 bender systemd[1]: run-docker-netns-99c02238aac0.mount: Succeeded.
Sep 18 20:11:20 bender systemd[1]: run-docker-netns-f95cbc442ad7.mount: Succeeded.
Sep 18 20:11:20 bender systemd[944473]: run-docker-netns-f95cbc442ad7.mount: Succeeded.
Sep 18 20:11:20 bender dockerd[958519]: time="2022-09-18T20:11:20.199600946+02:00" level=info msg="Removing stale sandbox f95cbc442ad777876fc7fd43fa8cc697fcb991531d926907a2cacf963ee02775 (911b4207a8a3b449e9a783a70fdd3de68651b2f4ce16fcc7d6e67bbbe2c81479)"
Sep 18 20:11:20 bender dockerd[958519]: time="2022-09-18T20:11:20.352924751+02:00" level=warning msg="Error (Unable to complete atomic operation, key modified) deleting object [endpoint 411410b001ab6f50a0c44d5f1d6c9b5857451172a5dd619a6f520f6466cdd17c 032d3602454e8768dc6b41c7bdf7bdacb6050aa343da8b6494b7305176e3bd1b], retrying...."
Sep 18 20:11:20 bender kernel: [3660360.033566] br-mailcow: port 16(vethd877f30) entered disabled state
Sep 18 20:11:20 bender kernel: [3660360.035885] device vethd877f30 left promiscuous mode
Sep 18 20:11:20 bender kernel: [3660360.037530] br-mailcow: port 16(vethd877f30) entered disabled state
Sep 18 20:11:20 bender systemd[944473]: run-docker-netns-f95cbc442ad7.mount: Succeeded.
Sep 18 20:11:20 bender systemd[1]: run-docker-netns-f95cbc442ad7.mount: Succeeded.
Sep 18 20:11:20 bender systemd[944473]: run-docker-netns-fd113937694a.mount: Succeeded.
Sep 18 20:11:20 bender systemd[1]: run-docker-netns-fd113937694a.mount: Succeeded.
Sep 18 20:11:20 bender dockerd[958519]: time="2022-09-18T20:11:20.624486108+02:00" level=info msg="Removing stale sandbox fd113937694a1ef6a640c66f3bc9154acab0d7067c7dfb73d7417de69be3eef5 (3296bddb329d6e8357f187408a911ed4f162f9408d564c48da52949e1889db9e)"
Sep 18 20:11:20 bender kernel: [3660360.350882] br-2c6fc6123e9e: port 1(veth13e8452) entered disabled state
Sep 18 20:11:20 bender kernel: [3660360.352265] device veth13e8452 left promiscuous mode
Sep 18 20:11:20 bender kernel: [3660360.353277] br-2c6fc6123e9e: port 1(veth13e8452) entered disabled state
Sep 18 20:11:20 bender systemd[1]: run-docker-netns-fd113937694a.mount: Succeeded.
Sep 18 20:11:20 bender systemd[944473]: run-docker-netns-fd113937694a.mount: Succeeded.
Sep 18 20:11:20 bender systemd[1]: run-docker-netns-47d5a246b97b.mount: Succeeded.
Sep 18 20:11:20 bender systemd[944473]: run-docker-netns-47d5a246b97b.mount: Succeeded.

As of now, I cannot reproduce that behavior (but remember it started out of the blue…)

Thank’s for your help and ideas!

MrChrisRodriguez

@dassams did this issue crop up again and/or you ever figure out the root cause? We’re currently facing this as well and are about to dig in but I was hoping you may have already diagnosed and resolved it.

dassams

Yes… and bit embarassing:
A maliciously setup cron job handling/copying certs triggered a restart of postfix, dovecot and nginx every minute on a specific date of the month.

MrChrisRodriguez

dassams Thanks for coming back to update – appreciate it.

dassams

Sure. Did you figure out the cause for your restarts?
Which containers are affected?

MrChrisRodriguez

dassams currently we’re seeing Postfix and Dovecot restarting. We’re going to dig into the investigation tomorrow so either my coworker Helder or I will be sure to circle back when we’ve dug in further!

esackbauer

I had this recently because I renew the certificates outside of mailcow, and one of the certificates I copied to mailcow had wrong DNS names (SAN) in it.