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@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
** 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
Desktop Bugs, which is subscribed to systemd in Ubuntu.
https://bugs.launchpad.net/bugs/1704895
Title:
service output sometimes missing when "User=" used
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/1704895/+subscriptions
--
desktop-bugs mailing list
desktop-bugs@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/desktop-bugs
