Debian macht sich hervorragend als Web- und Mailserver. Schau auch in den "
Tipps und Tricks"-Bereich.
-
Njuguna
- Beiträge: 99
- Registriert: 28.03.2023 09:47:30
Beitrag
von Njuguna » 16.05.2024 12:20:38
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
Zuletzt geändert von
Njuguna am 17.05.2024 15:58:10, insgesamt 1-mal geändert.
-
oln
- Beiträge: 533
- Registriert: 05.01.2021 09:41:24
Beitrag
von oln » 17.05.2024 08:14:15
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
- Beiträge: 99
- Registriert: 28.03.2023 09:47:30
Beitrag
von Njuguna » 17.05.2024 08:48:14
oln hat geschrieben: 17.05.2024 08:14:15
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
- Beiträge: 99
- Registriert: 28.03.2023 09:47:30
Beitrag
von Njuguna » 17.05.2024 09:01:01
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
- Beiträge: 99
- Registriert: 28.03.2023 09:47:30
Beitrag
von Njuguna » 17.05.2024 09:11:13
oln hat geschrieben: 17.05.2024 08:14:15
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
- Beiträge: 99
- Registriert: 28.03.2023 09:47:30
Beitrag
von Njuguna » 17.05.2024 13:50:46
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
- Beiträge: 4050
- Registriert: 04.06.2015 01:17:27
- Lizenz eigener Beiträge: MIT Lizenz
Beitrag
von heisenberg » 17.05.2024 15:14:15
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
- Beiträge: 99
- Registriert: 28.03.2023 09:47:30
Beitrag
von Njuguna » 17.05.2024 15:21:37
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!