5

When I write my unit-file I want all output from Exec*-options (ExecStartPre=, ExecStartPost=, ExecStart=, and ExecStopPost=) to be sent to the journal. But apparently the output is buffered in some way so it is in no way certain what will be written to the journal.

In my unit-file (ulftest.service) I have the following section:

...
ExecStartPre=/bin/echo 'Hello'
ExecStartPre=/usr/bin/who
ExecStart=/storage/_test/venv/bin/python /storage/_test/ulftestservice.py
...

So I would expect there to be a list of logged in users (4 of me) and a Hello showing up in the journal apart from the normal Starting, Started, Stopping and Stopped rows.

This is NOT the case. It is totally (for me at least) random if they show up or not.

I wrote a small testloop that restarts the service every 2 seconds:

$ for x in `seq 100`; do echo $x; sudo systemctl restart ulftest.service ; sleep 2; done

After running the thing I get this in the journal:

...
2017-05-10T09:40:36+0000 ulf44 systemd[1]: Started UlfTest, Administrative interface.
2017-05-10T09:40:38+0000 ulf44 systemd[1]: Stopping UlfTest, Administrative interface...
2017-05-10T09:40:38+0000 ulf44 systemd[1]: Stopped UlfTest, Administrative interface.
2017-05-10T09:40:38+0000 ulf44 systemd[1]: Starting UlfTest, Administrative interface...
2017-05-10T09:40:38+0000 ulf44 who[27344]: ulf      pts/0        2017-05-04 09:07 (192.168.0.180)
2017-05-10T09:40:38+0000 ulf44 who[27344]: ulf      pts/1        2017-05-04 12:36 (192.168.0.180)
2017-05-10T09:40:38+0000 ulf44 who[27344]: ulf      pts/2        2017-05-05 06:48 (192.168.0.180)
2017-05-10T09:40:38+0000 ulf44 systemd[1]: Started UlfTest, Administrative interface.
2017-05-10T09:40:40+0000 ulf44 systemd[1]: Stopping UlfTest, Administrative interface...
2017-05-10T09:40:40+0000 ulf44 systemd[1]: Stopped UlfTest, Administrative interface.
2017-05-10T09:40:40+0000 ulf44 systemd[1]: Starting UlfTest, Administrative interface...
2017-05-10T09:40:40+0000 ulf44 systemd[1]: Started UlfTest, Administrative interface.
...
2017-05-10T09:42:00+0000 ulf44 systemd[1]: Stopping UlfTest, Administrative interface...
2017-05-10T09:42:00+0000 ulf44 systemd[1]: Stopped UlfTest, Administrative interface.
2017-05-10T09:42:00+0000 ulf44 systemd[1]: Starting UlfTest, Administrative interface...
2017-05-10T09:42:00+0000 ulf44 who[28161]: ulf      pts/0        2017-05-04 09:07 (192.168.0.180)
2017-05-10T09:42:00+0000 ulf44 who[28161]: ulf      pts/1        2017-05-04 12:36 (192.168.0.180)
2017-05-10T09:42:00+0000 ulf44 who[28161]: ulf      pts/2        2017-05-05 06:48 (192.168.0.180)
2017-05-10T09:42:00+0000 ulf44 who[28161]: ulf      pts/3        2017-05-05 11:44 (192.168.0.180)
2017-05-10T09:42:00+0000 ulf44 systemd[1]: Started UlfTest, Administrative interface.
2017-05-10T09:42:02+0000 ulf44 systemd[1]: Stopping UlfTest, Administrative interface...
2017-05-10T09:42:02+0000 ulf44 systemd[1]: Stopped UlfTest, Administrative interface.
2017-05-10T09:42:02+0000 ulf44 systemd[1]: Starting UlfTest, Administrative interface...
2017-05-10T09:42:02+0000 ulf44 systemd[1]: Started UlfTest, Administrative interface.
...

Notice that for the 100-restarts I get no output from most of the time I get no Hello but I get 2 rounds of output from who but with only one of them complete.

I'm on a fresh Ubuntu 16.04. I also asked a similar and related question on stackoverflow.

Is this a feature, a bug or just something I am totally approaching the wrong way? Please advise me!

Community
  • 1
UlfR
  • 347
  • 6
  • 11
  • I had to introduce a number of `sys.stdout.flush()` calls in my Python code to make it show up directly in the journal. That only applies to your main script, of course, I don't understand why the pre scripts aren't listed. – nafmo Jul 04 '17 at 11:54

2 Answers2

0
man systemd.exec

I think you need to try to use in your unit StandardOutput=journal

 journal connects standard output with the journal which is accessible via journalctl(1). Note that everything that is written to syslog or kmsg (see below) is
           implicitly stored in the journal as well, the specific two options listed below are hence supersets of this one.
c4f4t0r
  • 5,301
  • 3
  • 31
  • 42
  • Thanks, but this is not an issue since its already set, see `/etc/systemd/system.conf` this row: `#DefaultStandardOutput=journal`. It is also shown in my example by the fact that there is output written to the journal occasionally, **but not** always. FYI, I have tried to include `StandardOutput=journal` in the unit-file with the result unchanged. – UlfR May 10 '17 at 13:03
0

Besides flushing the stdin, you can use the unbuffer command from the expect package.i

Your unit file will look something like this:

... [Service] ExecStart=/usr/bin/unbuffer /path/to/your/scripts.py ...

Another option that can give you a bit more control is using stdbuf which calls setvbuf() but this only works if the process you run with it does not call setvbuf() itself to nullify the changes.

dNetGuru
  • 1