[ist systemd] Buster "send mail on boot" fails

[ingo2]

Seit Upgrade auf Buster bekomme ich keine Mails mehr wenn smartd (nach dem Booten gestartet ist. Dabei hat sich an der /etc/smartd.conf beim Upgrade nicht verändert. Dort steht die Zeile

Code: Alles auswählen

# Send a TEST warning email to admin on startup.
/dev/sda -d sat -m root -M test

Funktionieren tut das allerdings, wenn ich smartd manuell restarte:

Code: Alles auswählen

systemctl restart smartd.service

Dann bekomme ich eine schöne Mail mit:
subject

Code: Alles auswählen

SMART error (EmailTest) detected on host: apu2

body

Code: Alles auswählen

This message was generated by the smartd daemon running on:

   host name:  apu2
   DNS domain: home

The following warning/error was logged by the smartd daemon:

TEST EMAIL from smartd for device: /dev/sda [SAT]

Device info:
TS64GMSA370, S/N:D923310249, FW:P1225CE, 64.0 GB

For details see host's SYSLOG.

So, jetzt dacht ich mir, eventuell ist das Netzwerk zu dem Zeitpunkt nicht verfügbar, deshalb habe ich mir versuchsweise einen cron-job in die crontab eingetragen:

Code: Alles auswählen

@reboot		root	sleep 20 && ( echo "reboot successful" | mail -s reboot root )

Aber auchdas funktioniert nicht - es wird keine Mail versandt.

Der gleiche Befehl im Terminal verschickt problemlos die Test-Mail.

Ist das ein Bug in cron und/oder gar smartmontools - wie kann man das lösen?

Gruß, Ingo

[TomL]

Funktionieren tut das allerdings, wenn ich smartd manuell restarte:

Kann es sein, dass die Unit in der Bootphase gestartet wird, wenn das Netzwerk noch nicht bereit ist? Das müsste man aus dem journal beantworten können. Wäre das so, würde ich eine Abhängigkeit definieren, die die definitive Verfügbarkeit des Netzes feststellt.

[ingo2]

Kann es sein, dass die Unit in der Bootphase gestartet wird, wenn das Netzwerk noch nicht bereit ist? Das müsste man aus dem journal beantworten können.

Ich habe jetzt mal im syslog nachgeschaut, das fänt so an:

Code: Alles auswählen

# cat /var/log/syslog | grep cron

Dec 14 17:14:18 apu2 systemd[1]: Started Trigger anacron every hour.
Dec 14 17:14:18 apu2 systemd[1]: Started Run anacron jobs.
Dec 14 17:14:18 apu2 anacron[464]: Anacron 2.3 started on 2019-12-14
Dec 14 17:14:18 apu2 anacron[464]: Normal exit (0 jobs run)
Dec 14 17:14:18 apu2 systemd[1]: anacron.service: Succeeded.
Dec 14 17:14:19 apu2 cron[515]: (CRON) INFO (pidfile fd = 3)
Dec 14 17:14:19 apu2 cron[515]: (CRON) INFO (Running @reboot jobs)
Dec 14 17:17:01 apu2 CRON[900]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dec 14 17:30:01 apu2 CRON[922]: (root) CMD ([ -x /etc/init.d/anacron ] && if [ ! -d /run/systemd/system ]; then /usr/sbin/invoke-rc.d anacron start >/dev/null; fi)
Dec 14 17:30:43 apu2 systemd[1]: Started Run anacron jobs.
....
usw.

In der 7. Zeile steht explizit "(Running @reboot jobs)", aber mein Befehl wird nicht abgearbeitet

Sicher ist nur: cron startet sehr früh im Bootprozess.
Die Variablen sind auch korrekt gesetzt und sowohl "sleep" als auch "mail" sind im PATH:

Code: Alles auswählen

SHELL=/bin/sh
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin

Aber wenn die anacron-jobs aus der crontab ausgeführt werden, warum mein "@reboot" in der crontab nicht?

Ansonsten habe ich keine irgendwelchen Fehlermeldungen in den Logs gefunden.

So, habe jetzt den Delay auf 90 sec. hochgesetzt (sleep 90) - dann bekomme ich eine Mail!
Damit kann ich das Fehlverhalten von smartd, bzw. systemd zumindest flicken, indem ich das extra als cron-job auführe.

Da sind gleich 3 Dinge im Argen:

1. cron bzw. systemd, der ja die allwissende Oberaufsicht dafür hat, verwirft die Zeile einfach und ohne Eintrag im syslog.

2. Im Fehlerfall sollte eigentlich cron eine Mail darüber verschicken - was er bisher auch immer getan hat - auch die kommt nie an.

3. smartd arbeitet vermutlich auch korrekt, sendet ja bei einem späteren "restart" besagte Mail, nur systemd verschlampt sie im Bootprozeß.

[ironie] Da drängen sich Parallelen zwischen unserem Postdienstleister und systemd auf [/ironie]

[TomL]

2. Im Fehlerfall sollte eigentlich cron eine Mail darüber verschicken - was er bisher auch immer getan hat - auch die kommt nie an.

Ich weiss nicht, wie das bei Dir eingestellt ist, aber cron.service hat bei mir keine Abhängigkeit zum Netzwerk... da würde das ebenfalls zu früh gestartet und somit würde der Mail-Vorgang genauso fehlschlagen. Abgesehen davon halte ich cron hierbei sowieso für keine gute idee. Mit Cron würde das gehen, wenn man die ganze Logik in ein Script packen würde, also Netzwerk prüfen, warten bis es verbunden ist, dann senden.

3. smartd arbeitet vermutlich auch korrekt, sendet ja bei einem späteren "restart" besagte Mail, nur systemd verschlampt sie im Bootprozeß.

Hier hatte ich das Problem vermutet, aber hier liegt imho auch die Lösung. Ich halte die Service-Unit für den richten Weg, ganz ohne Cron... die Service-Unit braucht nur ne Abhängigkeit auf das verbundene Netzwerk... dann wird die sofort funktionieren. Und das meinte ich eigentlich auch, die Antwort liegt ihm Journal. Also enablen und im Journal nachsehen, wie sie in Beziehung zum Netzwerk gestartet wird. Für beide Fragen enhält das Journal die Antwort. Ist es so, wie ich vermute, ist die Lösung einfach. Ganz nebenbei bemerkt,systemd verschlampt die nicht... wenn es das fehlende Netzwerk ist, ist es schlichtweg ein customizing-fehler.

[ingo2]

... die Antwort liegt ihm Journal. Also enablen und im Journal nachsehen, wie sie in Beziehung zum Netzwerk gestartet wird. Für beide Fragen enhält das Journal die Antwort. Ist es so, wie ich vermute, ist die Lösung einfach. Ganz nebenbei bemerkt,systemd verschlampt die nicht... wenn es das fehlende Netzwerk ist, ist es schlichtweg ein customizing-fehler.

Habe jetzt mal mit journalctl nachgesehen, da findet sich nur eine Zeile zur test mail:

Code: Alles auswählen

Dec 14 22:02:55 apu2 smartd[453]: Monitoring 2 ATA/SATA, 0 SCSI/SAS and 0 NVMe devices
Dec 14 22:02:55 apu2 smartd[453]: Executing test of <mail> to root ...
Dec 14 22:02:55 apu2 systemd[1]: Started OpenVPN connection to server.
...
Dec 14 22:02:56 apu2 smartd[453]: Test of <mail> to root: successful

Danach ist dann Funkstille bezüglich dem Mailversand ins Nirvana - die kam nie an.

Das syslog steht das gleiche:

Code: Alles auswählen

Dec 14 22:02:55 apu2 smartd[453]: Executing test of <mail> to root ...
Dec 14 22:02:56 apu2 CRON[529]: (root) CMD (sleep 60 && ( smartctl -H /dev/sda | grep test | mail -s rebooted root ))
Dec 14 22:02:56 apu2 smartd[453]: Test of <mail> to root: successful

Auf 60s habe ich jetzt den Delay im cron-job eingestellt (20s hatten ja nicht gereicht).

Auch in exim's mail queue lagen von den Tests 7 frozen mails - alle gelöscht:

Code: Alles auswählen

# exim -bp | exiqgrep -i | xargs exim -Mrm

Seit ich Debian kenne und nutze, gehören mailx und exim4 zum Grundsystem und haben völlig problemlos funktioniert. Habe jetzt mal noch im Web recherchiert und diesen Beitrag zum aktuellen Problem gefunden. Da steht auch, wie man das zurechtfrickelt:
https://dev.to/setevoy/linux-systemd-un ... tions-5h3k

Das tue ich mir nicht an

Services, die seit Jahren problemlos funktionieren (smartd, mailx, exim4, cron), weil sie alles nötige beinhalten, so zu verbiegen, daß sie mit systemd zusammenarbeiten - das ist ein Rückschritt.

[TomL]

Habe jetzt mal mit journalctl nachgesehen, da findet sich nur eine Zeile zur test mail:

Code: Alles auswählen

Dec 14 22:02:55 apu2 smartd[453]: Monitoring 2 ATA/SATA, 0 SCSI/SAS and 0 NVMe devices
Dec 14 22:02:55 apu2 smartd[453]: Executing test of <mail> to root ...
Dec 14 22:02:55 apu2 systemd[1]: Started OpenVPN connection to server.
...
Dec 14 22:02:56 apu2 smartd[453]: Test of <mail> to root: successful

Und in welchem Verhältnis steht das zur Startzeit des Netzwerks, also ab wann eine IP-Adresse vergeben ist und das Netzwerk verbunden ist? Darum gehts doch die ganze Zeit.... ich war von Anfang an sicher, dass smartd.service gestartet wird.... das failed nur aus einem Grund... und ich glaube, dass es das Netzwerk ist. Wenn es das ist, ist die Lösung einfach... es fehlt nur die Bestätigung, dass es so ist:

Code: Alles auswählen

 journalctl -b | egrep -i "dhcp|smartd"

Da steht auch, wie man das zurechtfrickelt:

So richtig gelungen finde ich das Vorgehen auch nicht... einfach stumpf solange probieren, bis es irgendwann mal klappt, notfalls stundenlang. Ich würde das nicht so lösen

Das tue ich mir nicht an

Also anspruchsvoll is die Lösung nicht... lediglich 2 Zeilen in die Service-Unit einfügen und fertig. Ich würds aus anderen Gründen (s.o.) nicht tun.

Services, die seit Jahren problemlos funktionieren (smartd, mailx, exim4, cron), weil sie alles nötige beinhalten, so zu verbiegen, daß sie mit systemd zusammenarbeiten - das ist ein Rückschritt.

Nein, dafür ist nicht systemd verantwortlich. Wenn ein Admin einen ganz bestimmten Job manuell (!) der Bootphase hinzufügt und dieser Job ganz bestimmte Abhängigkeiten erfordert, dann ist es Aufgabe des Admins, in einem parallel startenden System dafür zu sorgen, dass sein Job nicht zu einem falschen Zeitpunkt gestartet wird... also dann, wenn diese Abhängigkeit noch nicht erfüllt ist. Warum machst Du also nicht das einfachste und schaust im Journal nach, wie sich der Job und das gestartet Netzwerk zueinander verhalten? Ich habe ja jetzt schon mehrfach darauf hingewiesen. Es muss ja einen Grund haben, als fängt man bei dem wahrscheinlichen an ... vor dem Hintergrund, dass die Unit manuell gestartet ja fehlerfrei arbeitet.

[willy4711]

Nur mal, wie es bei mir ist:

Code: Alles auswählen

Dez 15 08:40:49 XFCE smartd[1141]: Device: /dev/sdc [SAT], SMART Usage Attribute: 190 Airflow_Temperature_Cel changed from 74 to 82
Dez 15 08:40:49 XFCE NetworkManager[1133]: <info>  [1576395649.5848] dhcp-init: Using DHCP client 'internal'
Dez 15 08:40:49 XFCE smartd[1141]: Device: /dev/sdd [SAT], SMART Usage Attribute: 190 Airflow_Temperature_Cel changed from 66 to 83
Dez 15 08:40:49 XFCE smartd[1141]: Device: /dev/sdd [SAT], SMART Usage Attribute: 194 Temperature_Celsius changed from 34 to 17
Dez 15 08:40:49 XFCE smartd[1141]: Device: /dev/sde [SAT], SMART Usage Attribute: 194 Temperature_Celsius changed from 123 to 133
Dez 15 08:40:49 XFCE smartd[1141]: Device: /dev/sda [SAT], state written to /var/lib/smartmontools/smartd.Crucial_CT275MX300SSD4-163813F609A4.ata.state
Dez 15 08:40:49 XFCE smartd[1141]: Device: /dev/sdb [SAT], state written to /var/lib/smartmontools/smartd.WDC_WD5000HHTZ_04N21V0-WD_WXN1E32MDENJ.ata.state
Dez 15 08:40:49 XFCE smartd[1141]: Device: /dev/sdc [SAT], state written to /var/lib/smartmontools/smartd.Samsung_SSD_850_PRO_128GB-S24ZNSAG339073V.ata.state
Dez 15 08:40:49 XFCE smartd[1141]: Device: /dev/sdd [SAT], state written to /var/lib/smartmontools/smartd.ST2000DX002_2DV164-Z4ZAJBP4.ata.state
Dez 15 08:40:49 XFCE smartd[1141]: Device: /dev/sde [SAT], state written to /var/lib/smartmontools/smartd.WDC_WD40EFRX_68N32N0-WD_WCC7K4JN915K.ata.state
Dez 15 08:40:52 XFCE NetworkManager[1133]: <info>  [1576395652.3114] dhcp4 (eth0): activation: beginning transaction (timeout in 45 seconds)
Dez 15 08:40:53 XFCE NetworkManager[1133]: <info>  [1576395653.9271] dhcp6 (eth0): activation: beginning transaction (timeout in 45 seconds)

und:

Code: Alles auswählen

~$ systemctl status smartd
● smartmontools.service - Self Monitoring and Reporting Technology (SMART) Daemon
     Loaded: loaded (/lib/systemd/system/smartmontools.service; enabled; vendor preset: enabled)
     Active: active (running) since Sun 2019-12-15 08:40:49 CET; 5h 58min ago
       Docs: man:smartd(8)
             man:smartd.conf(5)
   Main PID: 1141 (smartd)
     Status: "Next check of 5 devices will start at 14:40:49"
      Tasks: 1 (limit: 19043)
     Memory: 4.5M
     CGroup: /system.slice/smartmontools.service
             └─1141 /usr/sbin/smartd -n

und:

Code: Alles auswählen

~$ systemctl status NetworkManager
● NetworkManager.service - Network Manager
     Loaded: loaded (/lib/systemd/system/NetworkManager.service; enabled; vendor preset: enabled)
     Active: active (running) since Sun 2019-12-15 08:40:48 CET; 6h ago
       Docs: man:NetworkManager(8)
   Main PID: 1133 (NetworkManager)
      Tasks: 3 (limit: 19043)
     Memory: 5.9M
     CGroup: /system.slice/NetworkManager.service
             └─1133 /usr/sbin/NetworkManager --no-daemon

Wie man sieht startet der NetworkManager mitten drin, die Aktivierung der Schnittstellen geschieht aber erst,
nachdem sich smartmontools für den Bootvorgang beendet hat.

Nun ist die Frage (ich weiß es nicht) auf welchen Service smartmontools warten soll. Es gibt ja deren drei:

Code: Alles auswählen

$ systemd-analyze blame |grep "net\|Net"
6.143s NetworkManager-wait-online.service                                                       
  85ms NetworkManager.service                                                                   
  32ms networking.service      

[TomL]

Nur mal, wie es bei mir ist:

Das war hilfreich! und mit 3 Sekunden Verzögerung... das kann schon ausschlaggebend sein.

Nun ist die Frage (ich weiß es nicht) auf welchen Service smartmontools warten soll. Es gibt ja deren drei:

Code: Alles auswählen

$ systemd-analyze blame |grep "net\|Net"
6.143s NetworkManager-wait-online.service                                                       
  85ms NetworkManager.service                                                                   
  32ms networking.service      

Das ist tatsächlich ein Problem, deswegen wäre meine Lösung, diese Vielfalt erstmal zu ignorieren und einfach zu gucken, ob das Default-GW erreichbar ist. Dann wärs egal, wie oder von wem das Netzwerk gestartet wurde. Aber erstmal muss er bestätigen, dass wirklich das fehlende Netzwerk die Ursache ist.

[ingo2]

So, zur Frage von TomL.
Nach einem Reboot sieht es so aus:

Code: Alles auswählen

# systemd-analyze blame |grep "net\|Net"
   457ms networking.service

Code: Alles auswählen

Dec 15 13:44:20 apu2 smartd[370]: Executing test of <mail> to root ...
Dec 15 13:44:20 apu2 kernel: IPv6: ADDRCONF(NETDEV_UP): enp1s0: link is not ready
Dec 15 13:44:20 apu2 ifup[385]: Waiting for br0 to get ready (MAXWAIT is 2 seconds).
Dec 15 13:44:20 apu2 smartd[370]: Test of <mail> to root: successful
Dec 15 13:44:20 apu2 systemd[1]: Started Raise network interfaces.
Dec 15 13:44:20 apu2 systemd[1]: Reached target Network.

Aber wirklich nach "draußen" geht das Netzwerk erst viel später:

Code: Alles auswählen

Dec 15 13:44:23 apu2 kernel: br0: port 1(enp1s0) entered forwarding state
Dec 15 13:44:23 apu2 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): br0: link becomes ready

Als nächstes kommt dann exim4:

Code: Alles auswählen

Dec 15 13:45:21 apu2 systemd[1]: Starting LSB: exim Mail Transport Agent...
Dec 15 13:45:21 apu2 exim4[617]: Starting MTA: exim4.
Dec 15 13:45:21 apu2 systemd[1]: Started LSB: exim Mail Transport Agent.
Dec 15 13:45:21 apu2 systemd[1]: Reached target Multi-User System.

Und bis das System im Heimnetzwerksegment mit ping ansprechbar ist, dauert es noch viel länger - das vorletzte Mal ca. 55 sec.

Das Netzwerk starte ich übrigens mit ifupdown mit Konfiguration in der interfaces, ist eine Bridge aus 3 Ports.

[mat6937]

Und bis das System im Heimnetzwerksegment mit ping ansprechbar ist, dauert es noch viel länger - das vorletzte Mal ca. 55 sec.

Das Netzwerk starte ich übrigens mit ifupdown mit Konfiguration in der interfaces, ist eine Bridge aus 3 Ports.

BTW: Bei mir hilft folgender Eintrag:

Code: Alles auswählen

net.ipv4.ip_nonlocal_bind = 1

für sysctl, dass Dienste starten bzw. verwendet werden können, wenn diese nur an einer externen IP-Adresse lauschen müssen (lt. meiner Konfiguration). In der service-unit dieser Dienste habe ich keine Änderungen gemacht (d. h. diese sind im originalen Zustand).

[TomL]

Wie man sieht startet der NetworkManager mitten drin, die Aktivierung der Schnittstellen geschieht aber erst, nachdem sich smartmontools für den Bootvorgang beendet hat.

Das muss ein zufälliges Ergebnis sein, meine smartd.service hat keine Abhängigkeiten definiert:

# systemctl cat smartd.service

Code: Alles auswählen

# /lib/systemd/system/smartd.service
[Unit]
Description=Self Monitoring and Reporting Technology (SMART) Daemon
Documentation=man:smartd(8) man:smartd.conf(5)

[Service]
EnvironmentFile=-/etc/default/smartmontools
ExecStart=/usr/sbin/smartd -n $smartd_opts
ExecReload=/bin/kill -HUP $MAINPID
StandardOutput=syslog

[Install]
WantedBy=multi-user.target

Sieht die standardmäßig immer so aus?

[ingo2]

Sieht die standardmäßig immer so aus?

Ist bei mir identisch.

[JTH]

Wenn du den üblicherweise empohlenen Weg, einen Service nach konfiguriertem Netzwerk zu starten, ausprobieren möchtest:

1. Code: Alles auswählen

   # systemctl edit smartd.service

2. Code: Alles auswählen

   [Unit]
   After=network-online.target
   Wants=network-online.target
   

   einfügen.
3. Speichern, je nach Default-Editor.

Nun ist die Frage (ich weiß es nicht) auf welchen Service smartmontools warten soll. Es gibt ja deren drei:

Code: Alles auswählen

$ systemd-analyze blame |grep "net\|Net"
6.143s NetworkManager-wait-online.service                                                       
  85ms NetworkManager.service                                                                   
  32ms networking.service      

Das ist tatsächlich ein Problem, deswegen wäre meine Lösung, diese Vielfalt erstmal zu ignorieren und einfach zu gucken, ob das Default-GW erreichbar ist. Dann wärs egal, wie oder von wem das Netzwerk gestartet wurde.

Obiges funktioniert in den meisten – nicht allen – Fällen, sowohl mit ifupdown (/etc/network/interface), NetworkManager als auch systemd-networkd.

[TomL]

Obiges funktioniert in den meisten – nicht allen – Fällen, sowohl mit ifupdown (/etc/network/interface), NetworkManager als auch systemd-networkd.

Ja, ist aber leider immer auch so ein bisschen ein Glücksspiel.... weil es keine eindeutige Definition dafür gibt, was network-online.target tatsächlich bedeutet. Aber einen Versuch isses allemal wert. Wenn es das Problem löst, wars richtig.

[JTH]

Obiges funktioniert in den meisten – nicht allen – Fällen, sowohl mit ifupdown (/etc/network/interface), NetworkManager als auch systemd-networkd.

Ja, ist aber leider immer auch so ein bisschen ein Glücksspiel....

Genau. Deshalb die Einschränkung.

[ingo2]

Leute, ich muß Pause machen:

Habe natürlich gleich den Vorschlag von JTH ausprobiert und nur die Mail von meinem cron-job erhalten.
Dann in exim's mail-queue nachgeschaut:
Die Testmail von smartd ist dort vorhanden und "frozen". Die Mail aufgetaut und erneut verschicken lassen: wird wieder nicht versandt. Ursache:

Code: Alles auswählen

exim4 -v -M 1igZOC-00009F-43

SMTP error from remote mail server after MAIL FROM:<> SIZE=3231: 550-Requested action not taken: mailbox unavailable\n550 Sender address is not allowed.

GMX nimmt keine Mails mehr von mir an mich selbst an.

Also das muß jetzt erstmal Ruhe einkehren oder ich muß unter einer anderen Identität verschicken.