Bug 81019 - if unit's process exits non-zero no more logging for that unit until reboot
Summary: if unit's process exits non-zero no more logging for that unit until reboot
Status: RESOLVED WONTFIX
Alias: None
Product: systemd
Classification: Unclassified
Component: general (show other bugs)
Version: unspecified
Hardware: All Linux (All)
: low normal
Assignee: systemd-bugs
QA Contact: systemd-bugs
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-07-07 22:40 UTC by Piotr Staszewski
Modified: 2018-03-09 08:00 UTC (History)
0 users

See Also:
i915 platform:
i915 features:


Attachments

Description Piotr Staszewski 2014-07-07 22:40:25 UTC
If you have a unit that Execs a process that doesn't handle SIGTERM, that is exists non-zero on it, logging will stop working after first `systemctl stop` or `systemctl restart`.

There will be logging since the initial start (either by `systemctl start` or if start on boot if `enable`d) till the non-zero exit. After that `start`ing or `restart`ing will succeed but no logging will be performed. This will be regardless of Standard*= options, as I have tested them.

I haven't tested if logging will work if the Execed process craps out and dies non-zero (that is 'dies on its own', as oppossed to any of the `systemctl` commands), but above behaviour is still a bug. Logging should *always* work, regardless of the exit status and exit conditions. I do logging not because I fancy having TB of data, but because I want *error* situations to be written down. And a process exiting non-zero should not mean 'no more logging for this unit during this boot!'.

Versions and stuff:

Linux rpi 3.12.23-1-ARCH #1 PREEMPT Fri Jun 27 01:32:04 MDT 2014 armv6l GNU/Linux
local/libsystemd 214-2.1

Service file:
[Unit]
Description=DNS blackhole
After=network.target

[Service]
ExecStart=/home/user/adhole -t 250ms 192.168.0.3 192.168.0.21 blacklist.txt
WorkingDirectory=/home/user
Restart=always

[Install]
WantedBy=multi-user.target

AdHole that doesn't do SIGTERM:
https://github.com/drbig/adhole/tree/6b464386a99c50474eba5c735bb833c998cffddd

AdHole that does SIGTERM:
https://github.com/drbig/adhole/blob/a18f491c82bd0d485c69c290583329781cf94d24
Comment 1 Lennart Poettering 2014-08-18 21:26:10 UTC
What precisely do you mean by "logging"? syslog()? or stdout/stderr logging?

My logging always works fine ehre, regardless if syslo() or stdout/stderr style logging, and regardless how many times i restart a service...

Can you tell me exactly what I need to do to reproduce the issue?
Comment 2 Piotr Staszewski 2014-08-20 11:53:15 UTC
I did some more testing today, and my results are weird, but I suspect it's due to my peculiar setup.
I have /var/log as a tmpfs ('tmpfs /var/log tmpfs defaults,noatime,nodiratime,mode=0755,size=16M 0 0').

0. Testing software
Simple printf() loop, binary at /home/user/test-logging:

#include <stdio.h>
#include <unistd.h>

int main(int argc, char *argv[]) {
  int counter = 0;

  while (1) {
    printf("<5>Counter: %d\n", counter);
    fflush(stdout);
    sleep(3);
    counter++;
  }
}

Service file, saved at /etc/systemd/system/test-logging.service:

[Unit]
Description=Logging tester
After=network.target

[Service]
ExecStart=/home/user/test-logging
WorkingDirectory=/home/user
Restart=always

[Install]
WantedBy=multi-user.target

1. Test one
Systemd and journald have been running since boot, where journald.conf has:

[Journal]
Storage=persistent
SyncIntervalSec=30m
SystemMaxUse=8M

At shell:
systemctl start test-logging
systemctl status test-logging - did it a couple of times, no counter output logged whatsoever
systemctl stop test-logging

2. Test two
Modified journald.conf to have only:

[Journal]
SystemMaxUse=8M

At shell:
systemctl restart systemd-journald
systemctl start test-logging
systemctl status test-logging - did it a couple of times, counter output is being logged as intended
systemctl restart test-logging
systemctl status test-logging - still logging as it should
systemctl stop test-logging

3. Test three
So I added back my two custom options to journald.conf:

[Journal]
Storage=persistent
SyncIntervalSec=30m
SystemMaxUse=8M

At shell:
systemctl restart systemd-journald
systemctl start test-logging
systemctl status test-logging - did it a couple of times, logging well as in the previous test!
systemctl stop test-logging


In a way my problem seems to be solved, though I do not understand exactly why the logging works as the above tests show. My guess is that the tmpfs /var/log with Storage=persistent causes some trouble on boot and systemd is not logging; then restarting it without the Storage options invokes some setup code, so that from that point the logging works regardless of Storage or SyncIntervalSec values...

Please feel free to close this issue if the above behaviour is a known condition/intended feature etc.
Comment 3 Lennart Poettering 2014-08-26 20:12:23 UTC
Hmm, btw, we log to /run/log/journal (which is a tmpfs) if you leave Storage=volatile... It's weird, to make /var/log/ a tmpfs, if there's already /run/log for that...
Comment 4 Zbigniew Jedrzejewski-Szmek 2018-03-09 08:00:43 UTC
Closing all stale bugs with NEEDINFO. Please open a new bug at https://github.com/systemd/issues if the problem still occurs.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.