service output sometimes missing when "User=" used

[Kevin Pulo]

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@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@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@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@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@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@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@ip-172-31-6-192:~#
root@ip-172-31-6-192:~# vim /usr/local/bin/test
root@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@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@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@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@ip-172-31-6-192:~# vim /usr/local/bin/test
root@ip-172-31-6-192:~# vim /etc/systemd/system/test.service
root@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@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@ip-172-31-6-192:~# systemctl daemon-reload
root@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@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@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@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@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

[Dan Streetman (ddstreet)]

please reopen if this is still an issue