View Issue Details

IDProjectCategoryView StatusLast Update
0016924CentOS-7systemdpublic2020-01-15 03:52
Reportervolf 
PriorityhighSeverityminorReproducibilityalways
Status newResolutionopen 
Product Version7.6.1810 
Target VersionFixed in Version 
Summary0016924: systemd
DescriptionIf a systemd service exits quick enough after a message is written to stdout or stderr, it will not be associated with the unit when the program is executed as a non root user.

I encountered this with panics in languages such as go or rust, where they exit right after the error is encountered.

Compiling the cstderr.cpp program (g++ stderr.cpp -o /usr/local/bin/cstderr -std=c++11) in the current form, and running it using the service file, should work. You should see the following when running `journalctl -e -u script -f`

Jan 15 03:35:01 centos7box cstderr[24069]: hello stdout
Jan 15 03:35:01 centos7box cstderr[24069]: hello stderr
Jan 15 03:35:02 centos7box cstderr[24069]: hello stdout 2
Jan 15 03:35:02 centos7box cstderr[24069]: hello stderr 2

If you comment out the 2nd `std::this_thread::sleep_for(std::chrono::seconds(1));` above the return, and re-run the service you should get roughly the same output:

Jan 15 03:36:33 centos7box cstderr[24228]: hello stdout
Jan 15 03:36:33 centos7box cstderr[24228]: hello stderr
Jan 15 03:36:34 centos7box cstderr[24228]: hello stdout 2
Jan 15 03:36:34 centos7box cstderr[24228]: hello stderr 2

Now. If you modify the service file to run the same program (keeping in mind this version does not have the final 1 second sleep) you should see the following when running `journalctl -e -u script -f`

Jan 15 03:39:18 centos7box cstderr[24434]: hello stdout
Jan 15 03:39:18 centos7box cstderr[24434]: hello stderr

At this stage, we only have two lines of output. Switching to using the program name to look up logs (journalctl -e -t cstderr), we get:

Jan 15 03:39:18 centos7box cstderr[24434]: hello stdout
Jan 15 03:39:18 centos7box cstderr[24434]: hello stderr
Jan 15 03:39:19 centos7box cstderr[24434]: hello stdout 2
Jan 15 03:39:19 centos7box cstderr[24434]: hello stderr 2

Now. If we re-add (or uncomment) the 2nd timeout before the return statement, we can see the the 2nd two lines again using `journalctl -e -u script -f`

Jan 15 03:41:42 centos7box cstderr[24601]: hello stdout
Jan 15 03:41:42 centos7box cstderr[24601]: hello stderr
Jan 15 03:41:43 centos7box cstderr[24601]: hello stdout 2
Jan 15 03:41:43 centos7box cstderr[24601]: hello stderr 2

I would expect all output associated with a unit file be associated as such in journald, but it seems that if the program exists too quickly after writing the message- it never gets that association. I cannot reproduce this under systemd 244 running under arch linux.
Steps To Reproduce== Example Program (cstderr.cpp)
#include <iostream>
#include <thread> // std::this_thread::sleep_for
#include <chrono> // std::chrono::seconds

int main()
{
  std::cout << "hello stdout" << std::endl << std::flush;
  std::cerr << "hello stderr" << std::endl << std::flush;

  std::this_thread::sleep_for(std::chrono::seconds(1));

  std::cout << "hello stdout 2" << std::endl << std::flush;
  std::cerr << "hello stderr 2" << std::endl << std::flush;

  std::this_thread::sleep_for(std::chrono::seconds(1));

  return 0;
}

== Example Service
[Unit]
Description=Script
After=network.target

[Service]
User=root
ExecStart=/usr/local/bin/cstderr
Restart=always

[Install]
WantedBy=multi-user.target
TagsNo tags attached.
abrt_hash
URL

Activities

volf

volf

2020-01-15 03:52

reporter   ~0036025

I forgot to include the note under step 3 that you need to modify it to run as another user. Set User=root to something like User=dbus. I've tried using the dbus & postgres user and both show the same issue.

Issue History

Date Modified Username Field Change
2020-01-15 03:45 volf New Issue
2020-01-15 03:52 volf Note Added: 0036025