[Bug 1704895] [NEW] service output sometimes missing when "User=" used

Kevin Pulo 1704895 at bugs.launchpad.net
Tue Jul 18 00:50:53 UTC 2017


Public bug reported:

This repros on a clean and up-to-date 16.04.2, but not on ubuntu-artful-
daily-amd64-server-20170618, so it looks like this was fixed (possibly
upstream) sometime between 229-4ubuntu17 and 233-6ubuntu3.

Create the test files `/etc/systemd/system/test.service`:
```
[Unit]
Description=test service
After=syslog.target
After=sysinit.target

[Service]
ExecStart=/usr/local/bin/test
User=nobody

[Install]
WantedBy=sysinit.target
```
and `/usr/local/bin/test`:
```bash
#!/bin/sh

echo 'stdout msg'
echo 'stderr msg' 1>&2
# With the next line commented out, rarely see any journal output for the failed service (though it still gets forwarded to syslog every time).
# With the line uncommented, will usually see output, and only occasionally see partial output (1 out of the 2 lines) or no output at all.
#sleep 0.$RANDOM
exit 11
```
(and remember to `chmod a+x /usr/local/bin/test`).

Now as root try to start the service a few times.  It will always fail,
but the bug is that the `stdout msg` and `stderr msg` lines are absent
from the journal.  The expectation is that all lines output by the
failing service should be present - these lines are often critical for
diagnosing why the service has failed to start.  The lines do, however,
always get forwarded to syslog.

```
root at ip-172-31-6-192:~# cat /etc/systemd/system/test.service
[Unit]
Description=test service
After=syslog.target
After=sysinit.target

[Service]
ExecStart=/usr/local/bin/test
User=nobody

[Install]
WantedBy=sysinit.target

root at ip-172-31-6-192:~# cat /usr/local/bin/test
#!/bin/bash

echo 'stdout msg'
echo 'stderr msg' 1>&2
# With the next line commented out, rarely see any journal output for the failed service (though it still gets forwarded to syslog every time).
# With the line uncommented, will usually see output, and only occasionally see partial output (1 out of the 2 lines) or no output at all.
#sleep 0.$RANDOM
exit 11

root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
● test.service - test service
   Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Tue 2017-07-18 00:45:06 UTC; 1s ago
  Process: 23557 ExecStart=/usr/local/bin/test (code=exited, status=11)
 Main PID: 23557 (code=exited, status=11)

Jul 18 00:45:06 ip-172-31-6-192 systemd[1]: Started test service.
Jul 18 00:45:06 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
Jul 18 00:45:06 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
Jul 18 00:45:06 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
● test.service - test service
   Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Tue 2017-07-18 00:45:09 UTC; 1s ago
  Process: 23565 ExecStart=/usr/local/bin/test (code=exited, status=11)
 Main PID: 23565 (code=exited, status=11)

Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: Started test service.
Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
● test.service - test service
   Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Tue 2017-07-18 00:45:11 UTC; 1s ago
  Process: 23573 ExecStart=/usr/local/bin/test (code=exited, status=11)
 Main PID: 23573 (code=exited, status=11)

Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: Started test service.
Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
root at ip-172-31-6-192:~# tail /var/log/syslog
Jul 18 00:45:09 ip-172-31-6-192 test[23565]: stderr msg
Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: Started test service.
Jul 18 00:45:11 ip-172-31-6-192 test[23573]: stdout msg
Jul 18 00:45:11 ip-172-31-6-192 test[23573]: stderr msg
Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
root at ip-172-31-6-192:~#
root at ip-172-31-6-192:~# vim /usr/local/bin/test
root at ip-172-31-6-192:~# cat /usr/local/bin/test
#!/bin/bash

echo 'stdout msg'
echo 'stderr msg' 1>&2
# With the next line commented out, rarely see any journal output for the failed service (though it still gets forwarded to syslog every time).
# With the line uncommented, will usually see output, and only occasionally see partial output (1 out of the 2 lines) or no output at all.
sleep 0.$RANDOM
exit 11

root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
● test.service - test service
   Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Tue 2017-07-18 00:46:51 UTC; 698ms ago
  Process: 23598 ExecStart=/usr/local/bin/test (code=exited, status=11)
 Main PID: 23598 (code=exited, status=11)

Jul 18 00:46:50 ip-172-31-6-192 systemd[1]: Started test service.
Jul 18 00:46:50 ip-172-31-6-192 test[23598]: stdout msg
Jul 18 00:46:50 ip-172-31-6-192 test[23598]: stderr msg
Jul 18 00:46:51 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
Jul 18 00:46:51 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
Jul 18 00:46:51 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
● test.service - test service
   Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Tue 2017-07-18 00:46:52 UTC; 776ms ago
  Process: 23608 ExecStart=/usr/local/bin/test (code=exited, status=11)
 Main PID: 23608 (code=exited, status=11)

Jul 18 00:46:52 ip-172-31-6-192 systemd[1]: Started test service.
Jul 18 00:46:52 ip-172-31-6-192 test[23608]: stdout msg
Jul 18 00:46:52 ip-172-31-6-192 test[23608]: stderr msg
Jul 18 00:46:52 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
Jul 18 00:46:52 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
Jul 18 00:46:52 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
root at ip-172-31-6-192:~#
```

The same steps on the Artful daily result in both lines of output every
time.

Additionally, if the `User=` directive is removed from the test.service
file (and `systemctl daemon-reload`), then the problem also goes away:

```
root at ip-172-31-6-192:~# vim /usr/local/bin/test
root at ip-172-31-6-192:~# vim /etc/systemd/system/test.service
root at ip-172-31-6-192:~# cat /etc/systemd/system/test.service
[Unit]
Description=test service
After=syslog.target
After=sysinit.target

[Service]
ExecStart=/usr/local/bin/test
#User=nobody

[Install]
WantedBy=sysinit.target

root at ip-172-31-6-192:~# cat /usr/local/bin/test
#!/bin/bash

echo 'stdout msg'
echo 'stderr msg' 1>&2
# With the next line commented out, rarely see any journal output for the failed service (though it still gets forwarded to syslog every time).
# With the line uncommented, will usually see output, and only occasionally see partial output (1 out of the 2 lines) or no output at all.
#sleep 0.$RANDOM
exit 11

root at ip-172-31-6-192:~# systemctl daemon-reload
root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
● test.service - test service
   Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Tue 2017-07-18 00:48:11 UTC; 1s ago
  Process: 23731 ExecStart=/usr/local/bin/test (code=exited, status=11)
 Main PID: 23731 (code=exited, status=11)

Jul 18 00:48:11 ip-172-31-6-192 systemd[1]: Started test service.
Jul 18 00:48:11 ip-172-31-6-192 test[23731]: stdout msg
Jul 18 00:48:11 ip-172-31-6-192 test[23731]: stderr msg
Jul 18 00:48:11 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
Jul 18 00:48:11 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
Jul 18 00:48:11 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
● test.service - test service
   Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Tue 2017-07-18 00:48:13 UTC; 1s ago
  Process: 23739 ExecStart=/usr/local/bin/test (code=exited, status=11)
 Main PID: 23739 (code=exited, status=11)

Jul 18 00:48:13 ip-172-31-6-192 systemd[1]: Started test service.
Jul 18 00:48:13 ip-172-31-6-192 test[23739]: stdout msg
Jul 18 00:48:13 ip-172-31-6-192 test[23739]: stderr msg
Jul 18 00:48:13 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
Jul 18 00:48:13 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
Jul 18 00:48:13 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
● test.service - test service
   Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Tue 2017-07-18 00:48:15 UTC; 1s ago
  Process: 23747 ExecStart=/usr/local/bin/test (code=exited, status=11)
 Main PID: 23747 (code=exited, status=11)

Jul 18 00:48:15 ip-172-31-6-192 systemd[1]: Started test service.
Jul 18 00:48:15 ip-172-31-6-192 test[23747]: stdout msg
Jul 18 00:48:15 ip-172-31-6-192 test[23747]: stderr msg
Jul 18 00:48:15 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
Jul 18 00:48:15 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
Jul 18 00:48:15 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
● test.service - test service
   Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Tue 2017-07-18 00:48:16 UTC; 1s ago
  Process: 23755 ExecStart=/usr/local/bin/test (code=exited, status=11)
 Main PID: 23755 (code=exited, status=11)

Jul 18 00:48:16 ip-172-31-6-192 systemd[1]: Started test service.
Jul 18 00:48:16 ip-172-31-6-192 test[23755]: stdout msg
Jul 18 00:48:16 ip-172-31-6-192 test[23755]: stderr msg
Jul 18 00:48:16 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
Jul 18 00:48:16 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
Jul 18 00:48:16 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
root at ip-172-31-6-192:~#
```

ProblemType: Bug
DistroRelease: Ubuntu 16.04
Package: systemd 229-4ubuntu17
ProcVersionSignature: User Name 4.4.0-1020.29-aws 4.4.67
Uname: Linux 4.4.0-1020-aws x86_64
ApportVersion: 2.20.1-0ubuntu2.9
Architecture: amd64
Date: Tue Jul 18 00:25:54 2017
Ec2AMI: ami-e94e5e8a
Ec2AMIManifest: (unknown)
Ec2AvailabilityZone: ap-southeast-2b
Ec2InstanceType: t2.micro
Ec2Kernel: unavailable
Ec2Ramdisk: unavailable
Lsusb: Error: command ['lsusb'] failed with exit code 1:
MachineType: Xen HVM domU
ProcEnviron:
 TERM=xterm-256color
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=en_US.UTF-8
 SHELL=/bin/bash
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-4.4.0-1020-aws root=LABEL=cloudimg-rootfs ro console=tty1 console=ttyS0
SourcePackage: systemd
SystemdDelta:
 [EXTENDED]   /lib/systemd/system/rc-local.service → /lib/systemd/system/rc-local.service.d/debian.conf
 [EXTENDED]   /lib/systemd/system/systemd-timesyncd.service → /lib/systemd/system/systemd-timesyncd.service.d/disable-with-time-daemon.conf
 [MASKED]     /etc/udev/rules.d/60-cdrom_id.rules → /lib/udev/rules.d/60-cdrom_id.rules
 
 3 overridden configuration files found.
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 02/16/2017
dmi.bios.vendor: Xen
dmi.bios.version: 4.2.amazon
dmi.chassis.type: 1
dmi.chassis.vendor: Xen
dmi.modalias: dmi:bvnXen:bvr4.2.amazon:bd02/16/2017:svnXen:pnHVMdomU:pvr4.2.amazon:cvnXen:ct1:cvr:
dmi.product.name: HVM domU
dmi.product.version: 4.2.amazon
dmi.sys.vendor: Xen

** Affects: systemd (Ubuntu)
     Importance: Undecided
         Status: New


** Tags: amd64 apport-bug ec2-images xenial

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to systemd in Ubuntu.
https://bugs.launchpad.net/bugs/1704895

Title:
  service output sometimes missing when "User=" used

Status in systemd package in Ubuntu:
  New

Bug description:
  This repros on a clean and up-to-date 16.04.2, but not on ubuntu-
  artful-daily-amd64-server-20170618, so it looks like this was fixed
  (possibly upstream) sometime between 229-4ubuntu17 and 233-6ubuntu3.

  Create the test files `/etc/systemd/system/test.service`:
  ```
  [Unit]
  Description=test service
  After=syslog.target
  After=sysinit.target

  [Service]
  ExecStart=/usr/local/bin/test
  User=nobody

  [Install]
  WantedBy=sysinit.target
  ```
  and `/usr/local/bin/test`:
  ```bash
  #!/bin/sh

  echo 'stdout msg'
  echo 'stderr msg' 1>&2
  # With the next line commented out, rarely see any journal output for the failed service (though it still gets forwarded to syslog every time).
  # With the line uncommented, will usually see output, and only occasionally see partial output (1 out of the 2 lines) or no output at all.
  #sleep 0.$RANDOM
  exit 11
  ```
  (and remember to `chmod a+x /usr/local/bin/test`).

  Now as root try to start the service a few times.  It will always
  fail, but the bug is that the `stdout msg` and `stderr msg` lines are
  absent from the journal.  The expectation is that all lines output by
  the failing service should be present - these lines are often critical
  for diagnosing why the service has failed to start.  The lines do,
  however, always get forwarded to syslog.

  ```
  root at ip-172-31-6-192:~# cat /etc/systemd/system/test.service
  [Unit]
  Description=test service
  After=syslog.target
  After=sysinit.target

  [Service]
  ExecStart=/usr/local/bin/test
  User=nobody

  [Install]
  WantedBy=sysinit.target

  root at ip-172-31-6-192:~# cat /usr/local/bin/test
  #!/bin/bash

  echo 'stdout msg'
  echo 'stderr msg' 1>&2
  # With the next line commented out, rarely see any journal output for the failed service (though it still gets forwarded to syslog every time).
  # With the line uncommented, will usually see output, and only occasionally see partial output (1 out of the 2 lines) or no output at all.
  #sleep 0.$RANDOM
  exit 11

  root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
  ● test.service - test service
     Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Tue 2017-07-18 00:45:06 UTC; 1s ago
    Process: 23557 ExecStart=/usr/local/bin/test (code=exited, status=11)
   Main PID: 23557 (code=exited, status=11)

  Jul 18 00:45:06 ip-172-31-6-192 systemd[1]: Started test service.
  Jul 18 00:45:06 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
  Jul 18 00:45:06 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
  Jul 18 00:45:06 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
  root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
  ● test.service - test service
     Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Tue 2017-07-18 00:45:09 UTC; 1s ago
    Process: 23565 ExecStart=/usr/local/bin/test (code=exited, status=11)
   Main PID: 23565 (code=exited, status=11)

  Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: Started test service.
  Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
  Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
  Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
  root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
  ● test.service - test service
     Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Tue 2017-07-18 00:45:11 UTC; 1s ago
    Process: 23573 ExecStart=/usr/local/bin/test (code=exited, status=11)
   Main PID: 23573 (code=exited, status=11)

  Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: Started test service.
  Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
  Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
  Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
  root at ip-172-31-6-192:~# tail /var/log/syslog
  Jul 18 00:45:09 ip-172-31-6-192 test[23565]: stderr msg
  Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
  Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
  Jul 18 00:45:09 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
  Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: Started test service.
  Jul 18 00:45:11 ip-172-31-6-192 test[23573]: stdout msg
  Jul 18 00:45:11 ip-172-31-6-192 test[23573]: stderr msg
  Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
  Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
  Jul 18 00:45:11 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
  root at ip-172-31-6-192:~#
  root at ip-172-31-6-192:~# vim /usr/local/bin/test
  root at ip-172-31-6-192:~# cat /usr/local/bin/test
  #!/bin/bash

  echo 'stdout msg'
  echo 'stderr msg' 1>&2
  # With the next line commented out, rarely see any journal output for the failed service (though it still gets forwarded to syslog every time).
  # With the line uncommented, will usually see output, and only occasionally see partial output (1 out of the 2 lines) or no output at all.
  sleep 0.$RANDOM
  exit 11

  root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
  ● test.service - test service
     Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Tue 2017-07-18 00:46:51 UTC; 698ms ago
    Process: 23598 ExecStart=/usr/local/bin/test (code=exited, status=11)
   Main PID: 23598 (code=exited, status=11)

  Jul 18 00:46:50 ip-172-31-6-192 systemd[1]: Started test service.
  Jul 18 00:46:50 ip-172-31-6-192 test[23598]: stdout msg
  Jul 18 00:46:50 ip-172-31-6-192 test[23598]: stderr msg
  Jul 18 00:46:51 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
  Jul 18 00:46:51 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
  Jul 18 00:46:51 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
  root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
  ● test.service - test service
     Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Tue 2017-07-18 00:46:52 UTC; 776ms ago
    Process: 23608 ExecStart=/usr/local/bin/test (code=exited, status=11)
   Main PID: 23608 (code=exited, status=11)

  Jul 18 00:46:52 ip-172-31-6-192 systemd[1]: Started test service.
  Jul 18 00:46:52 ip-172-31-6-192 test[23608]: stdout msg
  Jul 18 00:46:52 ip-172-31-6-192 test[23608]: stderr msg
  Jul 18 00:46:52 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
  Jul 18 00:46:52 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
  Jul 18 00:46:52 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
  root at ip-172-31-6-192:~#
  ```

  The same steps on the Artful daily result in both lines of output
  every time.

  Additionally, if the `User=` directive is removed from the
  test.service file (and `systemctl daemon-reload`), then the problem
  also goes away:

  ```
  root at ip-172-31-6-192:~# vim /usr/local/bin/test
  root at ip-172-31-6-192:~# vim /etc/systemd/system/test.service
  root at ip-172-31-6-192:~# cat /etc/systemd/system/test.service
  [Unit]
  Description=test service
  After=syslog.target
  After=sysinit.target

  [Service]
  ExecStart=/usr/local/bin/test
  #User=nobody

  [Install]
  WantedBy=sysinit.target

  root at ip-172-31-6-192:~# cat /usr/local/bin/test
  #!/bin/bash

  echo 'stdout msg'
  echo 'stderr msg' 1>&2
  # With the next line commented out, rarely see any journal output for the failed service (though it still gets forwarded to syslog every time).
  # With the line uncommented, will usually see output, and only occasionally see partial output (1 out of the 2 lines) or no output at all.
  #sleep 0.$RANDOM
  exit 11

  root at ip-172-31-6-192:~# systemctl daemon-reload
  root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
  ● test.service - test service
     Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Tue 2017-07-18 00:48:11 UTC; 1s ago
    Process: 23731 ExecStart=/usr/local/bin/test (code=exited, status=11)
   Main PID: 23731 (code=exited, status=11)

  Jul 18 00:48:11 ip-172-31-6-192 systemd[1]: Started test service.
  Jul 18 00:48:11 ip-172-31-6-192 test[23731]: stdout msg
  Jul 18 00:48:11 ip-172-31-6-192 test[23731]: stderr msg
  Jul 18 00:48:11 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
  Jul 18 00:48:11 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
  Jul 18 00:48:11 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
  root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
  ● test.service - test service
     Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Tue 2017-07-18 00:48:13 UTC; 1s ago
    Process: 23739 ExecStart=/usr/local/bin/test (code=exited, status=11)
   Main PID: 23739 (code=exited, status=11)

  Jul 18 00:48:13 ip-172-31-6-192 systemd[1]: Started test service.
  Jul 18 00:48:13 ip-172-31-6-192 test[23739]: stdout msg
  Jul 18 00:48:13 ip-172-31-6-192 test[23739]: stderr msg
  Jul 18 00:48:13 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
  Jul 18 00:48:13 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
  Jul 18 00:48:13 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
  root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
  ● test.service - test service
     Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Tue 2017-07-18 00:48:15 UTC; 1s ago
    Process: 23747 ExecStart=/usr/local/bin/test (code=exited, status=11)
   Main PID: 23747 (code=exited, status=11)

  Jul 18 00:48:15 ip-172-31-6-192 systemd[1]: Started test service.
  Jul 18 00:48:15 ip-172-31-6-192 test[23747]: stdout msg
  Jul 18 00:48:15 ip-172-31-6-192 test[23747]: stderr msg
  Jul 18 00:48:15 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
  Jul 18 00:48:15 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
  Jul 18 00:48:15 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
  root at ip-172-31-6-192:~# systemctl start test ; sleep 1 ; systemctl status test
  ● test.service - test service
     Loaded: loaded (/etc/systemd/system/test.service; disabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Tue 2017-07-18 00:48:16 UTC; 1s ago
    Process: 23755 ExecStart=/usr/local/bin/test (code=exited, status=11)
   Main PID: 23755 (code=exited, status=11)

  Jul 18 00:48:16 ip-172-31-6-192 systemd[1]: Started test service.
  Jul 18 00:48:16 ip-172-31-6-192 test[23755]: stdout msg
  Jul 18 00:48:16 ip-172-31-6-192 test[23755]: stderr msg
  Jul 18 00:48:16 ip-172-31-6-192 systemd[1]: test.service: Main process exited, code=exited, status=11/n/a
  Jul 18 00:48:16 ip-172-31-6-192 systemd[1]: test.service: Unit entered failed state.
  Jul 18 00:48:16 ip-172-31-6-192 systemd[1]: test.service: Failed with result 'exit-code'.
  root at ip-172-31-6-192:~#
  ```

  ProblemType: Bug
  DistroRelease: Ubuntu 16.04
  Package: systemd 229-4ubuntu17
  ProcVersionSignature: User Name 4.4.0-1020.29-aws 4.4.67
  Uname: Linux 4.4.0-1020-aws x86_64
  ApportVersion: 2.20.1-0ubuntu2.9
  Architecture: amd64
  Date: Tue Jul 18 00:25:54 2017
  Ec2AMI: ami-e94e5e8a
  Ec2AMIManifest: (unknown)
  Ec2AvailabilityZone: ap-southeast-2b
  Ec2InstanceType: t2.micro
  Ec2Kernel: unavailable
  Ec2Ramdisk: unavailable
  Lsusb: Error: command ['lsusb'] failed with exit code 1:
  MachineType: Xen HVM domU
  ProcEnviron:
   TERM=xterm-256color
   PATH=(custom, no user)
   XDG_RUNTIME_DIR=<set>
   LANG=en_US.UTF-8
   SHELL=/bin/bash
  ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-4.4.0-1020-aws root=LABEL=cloudimg-rootfs ro console=tty1 console=ttyS0
  SourcePackage: systemd
  SystemdDelta:
   [EXTENDED]   /lib/systemd/system/rc-local.service → /lib/systemd/system/rc-local.service.d/debian.conf
   [EXTENDED]   /lib/systemd/system/systemd-timesyncd.service → /lib/systemd/system/systemd-timesyncd.service.d/disable-with-time-daemon.conf
   [MASKED]     /etc/udev/rules.d/60-cdrom_id.rules → /lib/udev/rules.d/60-cdrom_id.rules
   
   3 overridden configuration files found.
  UpgradeStatus: No upgrade log present (probably fresh install)
  dmi.bios.date: 02/16/2017
  dmi.bios.vendor: Xen
  dmi.bios.version: 4.2.amazon
  dmi.chassis.type: 1
  dmi.chassis.vendor: Xen
  dmi.modalias: dmi:bvnXen:bvr4.2.amazon:bd02/16/2017:svnXen:pnHVMdomU:pvr4.2.amazon:cvnXen:ct1:cvr:
  dmi.product.name: HVM domU
  dmi.product.version: 4.2.amazon
  dmi.sys.vendor: Xen

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/1704895/+subscriptions



More information about the foundations-bugs mailing list