Bug 1639482

Summary:	journalctl reports a totally useless ' The start-up result is RESULT.' and "Failed with result 'exit-code'.
Product:	[Fedora] Fedora	Reporter:	Valdis Kletnieks <valdis.kletnieks>
Component:	systemd	Assignee:	systemd-maint
Status:	CLOSED ERRATA	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	rawhide	CC:	lnykryn, msekleta, ssahani, s, systemd-maint, zbyszek
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	systemd-239-6.git9f3aed1.fc29 systemd-238-10.git438ac26.fc28	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2018-11-01 15:06:46 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Valdis Kletnieks 2018-10-15 20:23:40 UTC

Description of problem:
I run 'journalctl -xb' while trying to troubleshoot a boot-time issue. And *every single thing* that gets started reports:

-- The start-up result is RESULT.

15:43:09 [~] journalctl -xb | grep 'start-up result' | wc -l
196
15:43:21 [~] journalctl -xb | grep 'start-up result' | grep -v RESULT | wc -l
0

And I know that at least one unit failed (due to not having a kernel module):

15:48:20 0 [~]1 journalctl -xb -u vboxdrv.service
-- Logs begin at Thu 2014-05-29 11:18:59 EDT, end at Mon 2018-10-15 15:48:36 EDT. --
Oct 15 15:31:10 turing-police.cc.vt.edu systemd[1]: Starting VirtualBox Linux kernel module...
-- Subject: Unit vboxdrv.service has begun start-up
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit vboxdrv.service has begun starting up.
Oct 15 15:31:10 turing-police.cc.vt.edu vboxdrv.sh[1212]: vboxdrv.sh: Starting VirtualBox services.
Oct 15 15:31:10 turing-police.cc.vt.edu vboxdrv.sh[1285]: Starting VirtualBox services.
Oct 15 15:31:11 turing-police.cc.vt.edu vboxdrv.sh[1212]: vboxdrv.sh: failed: modprobe vboxnetadp failed. Please use 'dmesg' to find out why.
Oct 15 15:31:11 turing-police.cc.vt.edu systemd[1]: vboxdrv.service: Control process exited, code=exited status=1
Oct 15 15:31:11 turing-police.cc.vt.edu systemd[1]: vboxdrv.service: Failed with result 'exit-code'.
Oct 15 15:31:11 turing-police.cc.vt.edu systemd[1]: Failed to start VirtualBox Linux kernel module.
-- Subject: Unit vboxdrv.service has failed
-- Defined-By: systemd
-- Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit vboxdrv.service has failed.
-- 
-- The result is RESULT.

And it *STILL* says 'RESULT'. If it's not going to print useful info, don't bother printing it at all.

Oh, I take that back:

15:50:55 [~] journalctl -xb | grep result | sort | uniq -c
      1 -- The result is RESULT.
    197 -- The start-up result is RESULT.
      1 Oct 15 15:31:10 turing-police.cc.vt.edu systemd[1]: dbxtool.service: Failed with result 'exit-code'.
      1 Oct 15 15:31:11 turing-police.cc.vt.edu systemd[1]: vboxdrv.service: Failed with result 'exit-code'.
      1 Oct 15 15:31:34 turing-police.cc.vt.edu systemd[1552]: at-spi-dbus-bus.service: Failed with result 'exit-code'.

In one case, it doesn't put 'start-up' in the output.

While we're at it - "Failed with result 'exit-code'."  That's another useless message - I then have to find a *different* line of output in order to actually see what the error was. It presumably knows the exit code, so "Failed with result 'exit-code=97'." would be easy enough to do.  Not so bad if you're already looking at that unit's output - but makes life a lot harder if you're automating log scanning....

Version-Release number of selected component (if applicable):
systemd-239-5.fc30.x86_64

How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 1 Zbigniew Jędrzejewski-Szmek 2018-10-15 20:56:29 UTC

Re "RESULT": https://github.com/systemd/systemd/pull/10413

Re "Failed with result 'exit-code'.": the details about what failed are logged earlier. E.g. here I have:
Sep 23 21:52:16 krowka systemd[1]: dkms.service: Main process exited, code=exited, status=127/n/a
Sep 23 21:52:16 krowka systemd[1]: dkms.service: Failed with result 'exit-code'.
Sep 23 21:52:16 krowka systemd[1]: Failed to start Builds and install new kernel modules through DKMS.

The details about the failing binary are logged first, and the details about the failure are not propagated to the outer code. This is on purpose — higher levels don't care about the low-level details. 'exit-code' means that the service failed because some binary returned an error, as opposed to e.g. it being terminated by a signal.

Comment 2 Fedora Update System 2018-10-29 01:52:09 UTC

systemd-239-6.git9f3aed1.fc29 has been submitted as an update to Fedora 29. https://bodhi.fedoraproject.org/updates/FEDORA-2018-c402eea18b

Comment 3 Fedora Update System 2018-10-29 14:58:36 UTC

systemd-238-10.git438ac26.fc28 has been submitted as an update to Fedora 28. https://bodhi.fedoraproject.org/updates/FEDORA-2018-24bd6c9d4a

Comment 4 Fedora Update System 2018-10-31 17:30:40 UTC

systemd-238-10.git438ac26.fc28 has been pushed to the Fedora 28 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-24bd6c9d4a

Comment 5 Fedora Update System 2018-10-31 18:50:48 UTC

systemd-239-6.git9f3aed1.fc29 has been pushed to the Fedora 29 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-c402eea18b

Comment 6 Fedora Update System 2018-11-01 15:06:46 UTC

systemd-239-6.git9f3aed1.fc29 has been pushed to the Fedora 29 stable repository. If problems still persist, please make note of it in this bug report.

Comment 7 Fedora Update System 2018-11-04 22:08:35 UTC

systemd-238-10.git438ac26.fc28 has been pushed to the Fedora 28 stable repository. If problems still persist, please make note of it in this bug report.