[GELÖST] Postfix - Status: PID file exists but instance is not running!

[Njuguna]

Hallo,

ich überwache einen Postfix-Server auf Debian 12 Linux mit CheckMK. Hier sehe ich circa alle 6 Stunden diese kritischen Einträge:

Code: Alles auswählen

SERVICE ALERT	HARD (CRITICAL)	Status: PID file exists but instance is not running!
SERVICE NOTIFICATION	NOTIFY (CRITICAL)	Status: PID file exists but instance is not running!

Auf dem Mailserver sehe ich das hier:

Code: Alles auswählen

root@mx1 ~ # systemctl status postfix.service 
○ postfix.service - Postfix Mail Transport Agent
     Loaded: loaded (/lib/systemd/system/postfix.service; enabled; preset: enabled)
     Active: inactive (dead) since Thu 2024-05-16 12:05:01 CEST; 6min ago
   Duration: 5h 52min 58.486s
       Docs: man:postfix(1)
    Process: 658474 ExecStart=/bin/true (code=exited, status=0/SUCCESS)
   Main PID: 658474 (code=exited, status=0/SUCCESS)
        CPU: 759us

Mai 16 06:12:02 mx1 systemd[1]: Starting postfix.service - Postfix Mail Transport Agent...
Mai 16 06:12:02 mx1 systemd[1]: Finished postfix.service - Postfix Mail Transport Agent.
Mai 16 12:05:01 mx1 systemd[1]: postfix.service: Deactivated successfully.
Mai 16 12:05:01 mx1 systemd[1]: Stopped postfix.service - Postfix Mail Transport Agent.

Und das hier:

Code: Alles auswählen

 tail -f /var/log/mail.log
2024-05-16T12:04:59.816393+02:00 mx1 postfix/dnsblog[772139]: addr 106.75.36.21 listed by domain zen.spamhaus.org as 127.255.255.254
2024-05-16T12:04:59.913970+02:00 mx1 postfix/smtps/smtpd[774826]: warning: hostname m121-202-154-40.smartone.com does not resolve to address 121.202.154.40: Name or service not known
2024-05-16T12:04:59.914088+02:00 mx1 postfix/smtps/smtpd[774826]: connect from unknown[121.202.154.40]
2024-05-16T12:05:00.094034+02:00 mx1 postfix/smtps/smtpd[774824]: warning: static-23-244-21-196.oh.cpe.breezeline.net[23.244.21.196]: SASL PLAIN authentication failed: (reason unavailable), sasl_username=yunuz@germany.com
2024-05-16T12:05:00.109921+02:00 mx1 postfix/dnsblog[766151]: addr 106.75.36.21 listed by domain hostkarma.junkemailfilter.com as 127.0.1.2
2024-05-16T12:05:00.109999+02:00 mx1 postfix/dnsblog[766151]: addr 106.75.36.21 listed by domain hostkarma.junkemailfilter.com as 127.0.0.2
2024-05-16T12:05:00.348074+02:00 mx1 postfix/smtps/smtpd[774824]: lost connection after AUTH from static-23-244-21-196.oh.cpe.breezeline.net[23.244.21.196]
2024-05-16T12:05:00.348272+02:00 mx1 postfix/smtps/smtpd[774824]: disconnect from static-23-244-21-196.oh.cpe.breezeline.net[23.244.21.196] ehlo=1 auth=0/1 commands=1/2
2024-05-16T12:05:01.486788+02:00 mx1 postfix/postfix-script[778189]: stopping the Postfix mail system
2024-05-16T12:05:01.488988+02:00 mx1 postfix/master[658471]: terminating on signal 15
2024-05-16T12:13:03.204813+02:00 mx1 postfix/postfix-script[781086]: starting the Postfix mail system
2024-05-16T12:13:03.210374+02:00 mx1 postfix/master[781088]: daemon started -- version 3.7.10, configuration /etc/postfix

Regelmässig nach 7 Minuten Stillstand startet der postfix.service wieder von alleine. Für die nächsten 6 Stunden.

Was kann die Ursache dafür sein, dass der Service konstant immer nach 6 Stunden für 7 Minuten stoppt? Das ist ist fast schon gespenstisch.

Grüße

Njuguna

[oln]

Moin,
also autostart ist irgenwo bei dir konfiguriert(CheckMK?). Automatisch macht der Postfix normalerweise das nicht. Ich würde im syslog schauen ob eine Cronjob oder anderes Program den Postfix neu startet und das erst einmal abschalten.
Dann den Postfix anhalten und schauen ob es das Pidfile gibt. --> /var/spool/postfix/pid/master.pid
Lösche das Pidfile und starte den Postfix neu.
Treten dann immer noch die Restarts auf?

[Njuguna]

Moin,
also autostart ist irgenwo bei dir konfiguriert(CheckMK?). Automatisch macht der Postfix normalerweise das nicht. Ich würde im syslog schauen ob eine Cronjob oder anderes Program den Postfix neu startet und das erst einmal abschalten.

CheckMK und Autostart??? Der fragt doch nur über den CheckMK-Agenten die Werte ab, in kürzeren Abständen als 7 Stunden. Cronjobs haben auf dem Postfix nur das Backup und Certbot zur Certificate-Erneuerung.

Das was ich im mail.log Merkwürdiges gefunden hatte, ist das, was ich bereits gepostet hatte. Über 7 Stunden stehen da leider extrem viel Einträge drin. Aber ich sehe noch einmal das Syslog an.
Ich frage ja gezielt danach, weil ich das so auch nicht kenne, dass der der Postfixe-Service regelmässig stoppt und startet.

[Njuguna]

Das habe ich als letzte Aktion gefunden:

Code: Alles auswählen

2024-05-17T06:05:00.867877+02:00 mx1 postfix/smtps/smtpd[1130253]: Anonymous TLS connection established from 121-44-71-69.tpgi.com.au[121.44.71.69]: TLSv1.2 with cipher ECDHE-ECDSA-AES256-GCM-SHA384 (256/256 bits)
2024-05-17T06:05:01.020354+02:00 mx1 postfix/smtpd[1142747]: disconnect from unknown[106.75.130.189] ehlo=1 mail=1 rcpt=0/1 quit=1 commands=3/4
2024-05-17T06:05:01.814154+02:00 mx1 CRON[1142749]: (root) CMD (/usr/local/bin/fuglu_service)
2024-05-17T06:05:01.823353+02:00 mx1 systemd[1]: postfix.service: Deactivated successfully.
2024-05-17T06:05:01.823515+02:00 mx1 systemd[1]: Stopped postfix.service - Postfix Mail Transport Agent.
2024-05-17T06:05:01.839958+02:00 mx1 systemd[1]: Stopping postfix@-.service - Postfix Mail Transport Agent (instance -)...
2024-05-17T06:05:01.846236+02:00 mx1 systemd[1]: Stopping rspamd.service - rapid spam filtering system...
2024-05-17T06:05:01.883590+02:00 mx1 postfix/postfix-script[1142760]: stopping the Postfix mail system
2024-05-17T06:05:01.887281+02:00 mx1 mariadbd[913]: 2024-05-17  6:05:01 10148 [Warning] Aborted connection 10148 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T06:05:01.887362+02:00 mx1 mariadbd[913]: 2024-05-17  6:05:01 10147 [Warning] Aborted connection 10147 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T06:05:01.887466+02:00 mx1 mariadbd[913]: 2024-05-17  6:05:01 10145 [Warning] Aborted connection 10145 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T06:05:01.887501+02:00 mx1 mariadbd[913]: 2024-05-17  6:05:01 10144 [Warning] Aborted connection 10144 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading comm2024-05-17T06:05:00.867877+02:00 mx1 postfix/smtps/smtpd[1130253]: Anonymous TLS connection established from 121-44-71-69.tpgi.com.au[121.44.71.69]: TLSv1.2 with cipher ECDHE-ECDSA-AES256-GCM-SHA384 (256/256 bits)
2024-05-17T06:05:01.020354+02:00 mx1 postfix/smtpd[1142747]: disconnect from unknown[106.75.130.189] ehlo=1 mail=1 rcpt=0/1 quit=1 commands=3/4
2024-05-17T06:05:01.814154+02:00 mx1 CRON[1142749]: (root) CMD (/usr/local/bin/fuglu_service)
2024-05-17T06:05:01.823353+02:00 mx1 systemd[1]: postfix.service: Deactivated successfully.
2024-05-17T06:05:01.823515+02:00 mx1 systemd[1]: Stopped postfix.service - Postfix Mail Transport Agent.
2024-05-17T06:05:01.839958+02:00 mx1 systemd[1]: Stopping postfix@-.service - Postfix Mail Transport Agent (instance -)...
2024-05-17T06:05:01.846236+02:00 mx1 systemd[1]: Stopping rspamd.service - rapid spam filtering system...
2024-05-17T06:05:01.883590+02:00 mx1 postfix/postfix-script[1142760]: stopping the Postfix mail system
2024-05-17T06:05:01.887281+02:00 mx1 mariadbd[913]: 2024-05-17  6:05:01 10148 [Warning] Aborted connection 10148 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T06:05:01.887362+02:00 mx1 mariadbd[913]: 2024-05-17  6:05:01 10147 [Warning] Aborted connection 10147 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T06:05:01.887466+02:00 mx1 mariadbd[913]: 2024-05-17  6:05:01 10145 [Warning] Aborted connection 10145 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T06:05:01.887501+02:00 mx1 mariadbd[913]: 2024-05-17  6:05:01 10144 [Warning] Aborted connection 10144 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T06:05:01.887544+02:00 mx1 mariadbd[913]: 2024-05-17  6:05:01 10146 [Warning] Aborted connection 10146 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T06:05:01.895333+02:00 mx1 postfix/master[1023473]: terminating on signal 15
2024-05-17T06:05:01.897071+02:00 mx1 postfix/postfix-script[1142763]: waiting for the Postfix mail system to terminate
2024-05-17T06:05:02.065910+02:00 mx1 systemd[1]: rspamd.service: Deactivated successfully.
2024-05-17T06:05:02.066326+02:00 mx1 systemd[1]: Stopped rspamd.service - rapid spam filtering system.
2024-05-17T06:05:02.066681+02:00 mx1 systemd[1]: rspamd.service: Consumed 21.504s CPU time.
2024-05-17T06:05:02.120029+02:00 mx1 systemd[1]: Stopping dovecot.service - Dovecot IMAP/POP3 email server...
2024-05-17T06:05:02.904462+02:00 mx1 systemd[1]: postfix@-.service: Deactivated successfully.
2024-05-17T06:05:02.904599+02:00 mx1 systemd[1]: Stopped postfix@-.service - Postfix Mail Transport Agent (instance -).
2024-05-17T06:05:02.904769+02:00 mx1 systemd[1]: postfix@-.service: Consumed 1min 11.565s CPU time.
2024-05-17T06:05:03.776153+02:00 mx1 systemd[1]: Started check-mk-agent@6603-760-999.service - Checkmk agent (PID 760/UID 999).unication packets)
2024-05-17T06:05:01.887544+02:00 mx1 mariadbd[913]: 2024-05-17  6:05:01 10146 [Warning] Aborted connection 10146 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T06:05:01.895333+02:00 mx1 postfix/master[1023473]: terminating on signal 15
2024-05-17T06:05:01.897071+02:00 mx1 postfix/postfix-script[1142763]: waiting for the Postfix mail system to terminate
2024-05-17T06:05:02.065910+02:00 mx1 systemd[1]: rspamd.service: Deactivated successfully.
2024-05-17T06:05:02.066326+02:00 mx1 systemd[1]: Stopped rspamd.service - rapid spam filtering system.
2024-05-17T06:05:02.066681+02:00 mx1 systemd[1]: rspamd.service: Consumed 21.504s CPU time.
2024-05-17T06:05:02.120029+02:00 mx1 systemd[1]: Stopping dovecot.service - Dovecot IMAP/POP3 email server...
2024-05-17T06:05:02.904462+02:00 mx1 systemd[1]: postfix@-.service: Deactivated successfully.
2024-05-17T06:05:02.904599+02:00 mx1 systemd[1]: Stopped postfix@-.service - Postfix Mail Transport Agent (instance -).
2024-05-17T06:05:02.904769+02:00 mx1 systemd[1]: postfix@-.service: Consumed 1min 11.565s CPU time.
2024-05-17T06:05:03.776153+02:00 mx1 systemd[1]: Started check-mk-agent@6603-760-999.service - Checkmk agent (PID 760/UID 999).

Und hier findet der Start wieder statt:

Code: Alles auswählen

2024-05-17T06:09:01.815401+02:00 mx1 CRON[1144083]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
2024-05-17T06:09:03.848715+02:00 mx1 systemd[1]: Started check-mk-agent@6611-760-999.service - Checkmk agent (PID 760/UID 999).
2024-05-17T06:09:03.854373+02:00 mx1 systemd[1]: Starting phpsessionclean.service - Clean php session files...
2024-05-17T06:09:04.268660+02:00 mx1 systemd[1]: phpsessionclean.service: Deactivated successfully.
2024-05-17T06:09:04.268741+02:00 mx1 systemd[1]: Finished phpsessionclean.service - Clean php session files.
2024-05-17T06:09:04.538865+02:00 mx1 dbus-daemon[595]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.33802' (uid=0 pid=1144282 comm="timedatectl show")
2024-05-17T06:09:04.571967+02:00 mx1 systemd[1]: Starting systemd-timedated.service - Time & Date Service...
2024-05-17T06:09:04.599924+02:00 mx1 dbus-daemon[595]: [system] Successfully activated service 'org.freedesktop.timedate1'
2024-05-17T06:09:04.599999+02:00 mx1 systemd[1]: Started systemd-timedated.service - Time & Date Service.
2024-05-17T06:09:04.604490+02:00 mx1 systemd[1]: check-mk-agent@6611-760-999.service: Deactivated successfully.
2024-05-17T06:09:13.316188+02:00 mx1 systemd[1]: Starting postfix@-.service - Postfix Mail Transport Agent (instance -)...
2024-05-17T06:09:13.608490+02:00 mx1 postfix/postfix-script[1144454]: starting the Postfix mail system
2024-05-17T06:09:13.613932+02:00 mx1 postfix/master[1144456]: daemon started -- version 3.7.10, configuration /etc/postfix
2024-05-17T06:09:13.614905+02:00 mx1 systemd[1]: Started postfix@-.service - Postfix Mail Transport Agent (instance -).
2024-05-17T06:09:13.671893+02:00 mx1 systemd[1]: Starting postfix.service - Postfix Mail Transport Agent...
2024-05-17T06:09:13.673154+02:00 mx1 systemd[1]: Finished postfix.service - Postfix Mail Transport Agent.
2024-05-17T06:09:13.679106+02:00 mx1 systemd[1]: Started rspamd.service - rapid spam filtering system.
2024-05-17T06:09:13.685260+02:00 mx1 systemd[1]: Starting dovecot.service - Dovecot IMAP/POP3 email server...
2024-05-17T06:09:13.709084+02:00 mx1 rspamd[1144462]: 2024-05-17 06:09:13 #1144462(main) <1dd133>; main; main: rspamd 3.4 is loading configuration, build id: release
2024-05-17T06:09:13.732546+02:00 mx1 systemd[1]: Started dovecot.service - Dovecot IMAP/POP3 email server.
2024-05-17T06:09:14.677021+02:00 mx1 systemd[1]: Started check-mk-agent@6612-760-999.service - Checkmk agent (PID 760/UID 999).

[Njuguna]

Dann den Postfix anhalten und schauen ob es das Pidfile gibt. --> /var/spool/postfix/pid/master.pid
Lösche das Pidfile und starte den Postfix neu.
Treten dann immer noch die Restarts auf?

Ich habe das jetzt so umgesetzt. Der Postfix läuft wieder und das Pidfile ist neu. Jetzt warte ich mal ab.

[Njuguna]

Also trotz des manuellen Neustarts kam um 12.05 Uhr der nächste Shutdown:

Code: Alles auswählen

2024-05-17T12:05:01.838020+02:00 mx1 systemd[1]: Stopped postfix.service - Postfix Mail Transport Agent.
2024-05-17T12:05:01.860208+02:00 mx1 systemd[1]: Stopping postfix@-.service - Postfix Mail Transport Agent (instance -)...
2024-05-17T12:05:01.868160+02:00 mx1 systemd[1]: Stopping rspamd.service - rapid spam filtering system...
2024-05-17T12:05:01.909604+02:00 mx1 postfix/postfix-script[1265143]: stopping the Postfix mail system
2024-05-17T12:05:01.925787+02:00 mx1 postfix/master[1206163]: terminating on signal 15
2024-05-17T12:05:01.926286+02:00 mx1 mariadbd[913]: 2024-05-17 12:05:01 11069 [Warning] Aborted connection 11069 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T12:05:01.926394+02:00 mx1 mariadbd[913]: 2024-05-17 12:05:01 11068 [Warning] Aborted connection 11068 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T12:05:01.926428+02:00 mx1 mariadbd[913]: 2024-05-17 12:05:01 11067 [Warning] Aborted connection 11067 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T12:05:01.926461+02:00 mx1 mariadbd[913]: 2024-05-17 12:05:01 11066 [Warning] Aborted connection 11066 to db: 'postfix' user: 'postfix' host: 'localhost' (Got an error reading communication packets)
2024-05-17T12:05:01.927971+02:00 mx1 systemd[1]: postfix@-.service: Deactivated successfully.
2024-05-17T12:05:01.928793+02:00 mx1 systemd[1]: Stopped postfix@-.service - Postfix Mail Transport Agent (instance -).
2024-05-17T12:05:01.929094+02:00 mx1 systemd[1]: postfix@-.service: Consumed 38.844s CPU time.
2024-05-17T12:05:02.111702+02:00 mx1 systemd[1]: rspamd.service: Deactivated successfully.
2024-05-17T12:05:02.114047+02:00 mx1 systemd[1]: Stopped rspamd.service - rapid spam filtering system.
2024-05-17T12:05:02.114411+02:00 mx1 systemd[1]: rspamd.service: Consumed 25.836s CPU time.
2024-05-17T12:05:02.156038+02:00 mx1 systemd[1]: Stopping dovecot.service - Dovecot IMAP/POP3 email server...
2024-05-17T12:05:03.378725+02:00 mx1 systemd[1]: dovecot.service: Deactivated successfully.
2024-05-17T12:05:03.378913+02:00 mx1 systemd[1]: Stopped dovecot.service - Dovecot IMAP/POP3 email server.
2024-05-17T12:05:03.378969+02:00 mx1 systemd[1]: dovecot.service: Consumed 1min 14.915s CPU time.
2024-05-17T12:05:03.937388+02:00 mx1 systemd[1]: Started check-mk-agent@7324-760-999.service - Checkmk agent (PID 760/UID 999).

Drei Minuten später lief er wieder:

Code: Alles auswählen

# systemctl status postfix.service 
● postfix.service - Postfix Mail Transport Agent
     Loaded: loaded (/lib/systemd/system/postfix.service; enabled; preset: enabled)
     Active: active (exited) since Fri 2024-05-17 12:07:03 CEST; 1h 42min ago
       Docs: man:postfix(1)
    Process: 1265961 ExecStart=/bin/true (code=exited, status=0/SUCCESS)
   Main PID: 1265961 (code=exited, status=0/SUCCESS)
        CPU: 1ms

[heisenberg]

terminating on signal 15

Ich denke auch, dass das irgend ein Script ist, dass dem Postfix das Signal zum Beenden schickt. Ich würde mich da Mal auf die Suche begeben nach ...

... cron jobs
... ssh logins
... Scripte/Programme die auf dem System dauerhaft laufen und den Postfix überwachen wollen (monit?)

[Njuguna]

Okay, ich bin fündig geworden:

Code: Alles auswählen

# cat  /usr/local/bin/fuglu_service
#!/bin/bash

s=$((0 + $RANDOM % 10))
systemctl stop postfix.service
systemctl stop rspamd.service
systemctl stop dovecot.service
sleep ${s}m
systemctl start postfix.service
systemctl start rspamd.service
systemctl start dovecot.service

und das war tatsächlich auf alle sechs Stunden und fünf Minuten nach Voll eingestellt.

Vielen Dank für die Anregungen!