gelöst: systemd soll permanent mitloggen

[k2]

Hi zusammen,

auf meinem RasPi startet systemd ein Pythonskript als Dienst, der einen Pin überwacht und gelegentlich LEDs schaltet. Das Skript gibt Meldungen auf der Konsole aus, die systemd in das Journal schreibt.

Das Problem dabei ist, dass die Meldungen des Skriptes erst dann im Log landen, wenn das Skript beendet wird...
Da der Dienst aber permanent laufen soll, und auch läuft, passiert das nie. Um das Log zu lesen, muss ich den Dienst stoppen oder neustarten.
journalctl --flush bringt auch nichts.

Hier das Log, während der Dienst läuft und auch perfekt arbeitet:

Code: Alles auswählen

Jun 28 08:12:37 mein-raspi systemd[1]: Started PinDetect StateMachine.

Und hier das Log, nachdem der Dienst beendet wurde. Die Meldungen mit der PID 1107 sollten eigentlich nach dem Start des Dienstes gleich im Log erscheinen:

Code: Alles auswählen

Jun 28 08:12:37 mein-raspi systemd[1]: Started PinDetect StateMachine.
Jun 28 08:46:29 mein-raspi systemd[1]: Stopping PinDetect StateMachine...
Jun 28 08:46:31 mein-raspi StateMachine[1107]: 2021-06-28 08:12:37 state: INIT
Jun 28 08:46:31 mein-raspi StateMachine[1107]: 2021-06-28 08:12:44 state: DETECT
Jun 28 08:46:31 mein-raspi StateMachine[1107]: 2021-06-28 08:12:56 state: ALERT
Jun 28 08:46:31 mein-raspi StateMachine[1107]: 2021-06-28 08:13:06 state: ALARM_SENT
Jun 28 08:46:31 mein-raspi StateMachine[1107]: 2021-06-28 08:13:06 state: DETECT
Jun 28 08:46:31 mein-raspi StateMachine[1107]: 2021-06-28 08:40:33 state: ALERT
Jun 28 08:46:31 mein-raspi StateMachine[1107]: 2021-06-28 08:40:43 state: ALARM_SENT
Jun 28 08:46:31 mein-raspi StateMachine[1107]: 2021-06-28 08:40:43 state: DETECT
Jun 28 08:46:31 mein-raspi systemd[1]: StateMachine.service: Succeeded.
Jun 28 08:46:31 mein-raspi systemd[1]: Stopped PinDetect StateMachine.

Meine Frage: Kann ich irgendwo einstellen, dass die Konsole-Ausgaben sofort ins Log geschrieben werden, oder muss ich die Konsole-Ausgaben irgendwo anders hin schreiben?

Code: Alles auswählen

[Unit]
Description= PinDetect StateMachine
After=syslog.target

[Service]
Type=simple
User=root
Group=root
WorkingDirectory=/opt/PinDetect/bin
ExecStart=/opt/PinDetect/bin/StateMachine.py
SyslogIdentifier=StateMachine
StandardOutput=syslog
StandardError=syslog
Restart=always
RestartSec=3

[Install]
WantedBy=multi-user.target

Vielen Dank vorab für Eure Hilfe

[MSfree]

Üblicherweise wird stdout gepuffert geschrieben. Die Größe des Puffers kann ich dir nicht sagen, dürfte aber irgendwo bei 4-16kByte liegen. Irgendwann ist der Puffer voll und landet dann auch in deinem Log, aber selbst in 4kByte passen rund 50 Zeilen Text.

Du kannst aber versuchen, Python ohne Puffer laufen zu lassen. Solange da keine großen Mengen an Ausgabe entstehen, ist das OK. Will man aber megabyteweise Daten rausschreiben, ist ungepuffertes schreiben extrem ineffizient. Puffern generell abzuschalten ist also nicht empfehlendswert.

Schau dazu mal diesen Link an:
https://stackoverflow.com/questions/107 ... -buffering

[willy4711]

Schau dir mal die /etc/systemd/journald.conf an.

Vermutung: Die Option

Code: Alles auswählen

SyncIntervalSec=

könnte eine Lösung sein.
aus:https://www.freedesktop.org/software/sy ... .conf.html

The timeout before synchronizing journal files to disk. After syncing, journal files are placed in the OFFLINE state. Note that syncing is unconditionally done immediately after a log message of priority CRIT, ALERT or EMERG has been logged. This setting hence applies only to messages of the levels ERR, WARNING, NOTICE, INFO, DEBUG. The default timeout is 5 minutes.

Müsste man mal testen

[MSfree]

Schau dir mal die /etc/systemd/journald.conf an.

Vermutung: Die Option

Code: Alles auswählen

SyncIntervalSec=

könnte eine Lösung sein.

Wenn Python selbst puffert, nützt das wenig. Denn systemd bekommt die Daten erst dann übermittelt, wenn der Pythonpuffer voll ist. Man muß also beim Verursacher (hier Python) ansetzen.

[k2]

Daaanke!

Ein ganz herzliches Dankeschön von mir!
Das Puffern von Python war die Ursache. An jede Print-Ausgabe habe ich ein flush=True als Argument mit angehängt und jetzt es läuft perfekt. Ich rechne mit 10 Logzeilen in der Woche, das sollte der Performance nicht schaden.

Code: Alles auswählen

print("Ausgabetext", flush=True) 

Jetzt erscheinen die einzelnen Logzeilen des Skriptes nach dem Start durch den systemd:

Code: Alles auswählen

Jun 28 10:54:03 mein-raspi systemd[1]: Started PinDetect StateMachine.
Jun 28 10:54:03 mein-raspi StateMachine[4683]: 2021-06-28 10:54:03 state: INIT
Jun 28 10:54:10 mein-raspi StateMachine[4683]: 2021-06-28 10:54:10 state: DETECT
Jun 28 10:54:25 mein-raspi StateMachine[4683]: 2021-06-28 10:54:25 state: ALERT
Jun 28 10:54:35 mein-raspi StateMachine[4683]: 2021-06-28 10:54:35 state: ALARM_SENT
Jun 28 10:54:35 mein-raspi StateMachine[4683]: 2021-06-28 10:54:35 state: DETECT
Jun 28 10:54:53 mein-raspi StateMachine[4683]: 2021-06-28 10:54:53 state: ALERT
Jun 28 10:55:03 mein-raspi StateMachine[4683]: 2021-06-28 10:55:03 state: ALARM_SENT
Jun 28 10:55:04 mein-raspi StateMachine[4683]: 2021-06-28 10:55:04 state: DETECT
Jun 28 11:00:46 mein-raspi systemd[1]: Stopping PinDetect StateMachine...
Jun 28 11:00:48 mein-raspi systemd[1]: StateMachine.service: Succeeded.
Jun 28 11:00:48 mein-raspi systemd[1]: Stopped PinDetect StateMachine.

Da kann man systemd natürlich keine Schuld geben, wenn ich kein Python kann...

Danke nochmals!

[MSfree]

Ich rechne mit 10 Logzeilen in der Woche, das sollte der Performance nicht schaden.

Richtig. Solange es ein paar Zeilen pro Minute sind, ist die Auswirkung auf die Performance durch nicht puffern vernachlässigbar klein, bei 10 Zeilen pro Woche spielt es dann noch weniger eine Rolle.