Bug 68212

Summary: systemctl status should show what is trying to start the service
Product: dbus Reporter: Pacho Ramos <pachoramos1>
Component: coreAssignee: D-Bus Maintainers <dbus>
Status: RESOLVED FIXED QA Contact: D-Bus Maintainers <dbus>
Severity: enhancement    
Priority: low CC: bugzilla, chengwei.yang.cn, msniko14
Version: 1.5   
Hardware: All   
OS: All   
Whiteboard:
i915 platform: i915 features:
Attachments: bus: Add sender name to systemd bus activation log messages
bus: Add sender name to bus activation log messages
bus: Add LSM label to connection loginfo string

Description Pacho Ramos 2013-08-17 07:49:48 UTC
I am getting this:
ago 17 09:44:27 localhost dbus-daemon[222]: dbus[222]: [system] Activating via systemd: service name='org.freedesktop.ConsoleKit' unit='console-kit-da
emon.service'
ago 17 09:44:27 localhost dbus-daemon[222]: dbus[222]: [system] Activation via systemd failed for unit 'console-kit-daemon.service': Unit console-kit-
daemon.service': Unit console-kit-daemon.service failed to load: No such file or directory. See system logs a

The problem is that I cannot know what is trying to start that unit file from dbus, and I think that info could be useful :/

Thanks a lot!
Comment 1 Zbigniew Jedrzejewski-Szmek 2013-08-19 14:42:17 UTC
Agreed.
Comment 2 Lennart Poettering 2013-09-12 17:18:27 UTC
Not following? You want that D-Bus logs what the client is that requested the bus activation? That sounds like a bug to file against dbus daemon, no? Reassigning...
Comment 3 Pacho Ramos 2013-09-12 18:24:02 UTC
I want to have a reference of what service is starting other one, in this example, what service is starting consolekit
Comment 4 Chengwei Yang 2013-09-22 09:11:43 UTC
(In reply to comment #3)
> I want to have a reference of what service is starting other one, in this
> example, what service is starting consolekit

I think it's not useful as you expected to know who is the client to request service from a well-known service, say consolekit.

Given that anyone may send request to consolekit, for example, you can do that manually with 'dbus-send'.

And the error log is quite precise, No such file or directory. That means there is no such systemd unit in corresponding systemd session, system wide or user session wide.
Comment 5 Pacho Ramos 2013-09-22 09:19:01 UTC
Related with error, I know that I don't have the unit file, but would like to know what app is still needing it (as maybe it's wrongly configured or...)
Comment 6 Philip Withnall 2016-10-01 14:11:11 UTC
Created attachment 126943 [details] [review]
bus: Add sender name to systemd bus activation log messages

This clarifies
   Activating via systemd: service name='A' unit='B'
to
   Activating via systemd: service name='A' unit='B' sender='blah'
Comment 7 Simon McVittie 2016-10-03 10:02:39 UTC
Comment on attachment 126943 [details] [review]
bus: Add sender name to systemd bus activation log messages

Review of attachment 126943 [details] [review]:
-----------------------------------------------------------------

> Add sender name to systemd bus activation log messages

If this was accurate, I'd complain that we should be covering the two non-systemd activation paths (fork-and-exec, and fork-and-exec the dbus-daemon-launch-helper). But in fact you already did, so please change the commit message subject instead :-)

It's OK to only mention the systemd code path in the commit message body, since the others are analogous. I'd prefer a slightly more realistic example though - perhaps service name com.example.Example resulting in systemd unit example.service, activated by :1.23 uid 1000 pid 123 comm "whatever-activat" (to demonstrate the truncation to 16 characters that is implicit in us using the /proc/$pid/comm interface).

::: bus/activation.c
@@ +1969,3 @@
>                                 service_name,
> +                               entry->systemd_service,
> +                               dbus_message_get_sender (activation_message));

"requested by" might be clearer than "sender".

I think we might be better off extracting information from the @connection rather than the @activation_message: then we could use

("... requested by '%s' (%s)",
 ...,
 bus_connection_get_name (connection),
 bus_connection_get_loginfo (connection))

If whatever-activated-it activates com.example.Example, this would give you

    Activating via systemd: service name='com.example.Example' unit='example.service' requested by ':1.23' (uid=1000 pid=123 comm="whatever-activat")

which is a better start for debugging the situation.

comm is not a security feature (any process can change its /proc/$pid/comm by issuing the PR_SET_NAME prctl in its main thread, AIUI) but it's useful for debugging non-malicious situations.

The reason I don't think the unique name is necessarily enough is that I'm thinking about this case:

    Activating via systemd: service name='com.example.Example' unit='example.service' requested by ':1.23' (uid=1000 pid=123 comm="dbus-send")

in which :1.23 will have fallen off the bus by the time you get round to looking for more information - but at least with comm quoted, you know you need to be looking for some shell script or something calling dbus-send.

If you want to add _dbus_connection_get_linux_security_label() to the loginfo (where it succeeds, i.e. where LSMs are used), as a related patch, I wouldn't say no.

@@ +1990,4 @@
>            if (!retval)
>              {
>                bus_context_log (activation->context,
> +                               DBUS_SYSTEM_LOG_INFO, "Failed to activate via systemd: service name='%s' unit='%s' sender='%s'",

I don't think we necessarily need to mention the sender here, because we already blamed them once, when activation started (and you don't seem to have mentioned them for failures on the non-systemd code path).
Comment 8 Philip Withnall 2016-10-05 10:54:11 UTC
Created attachment 127023 [details] [review]
bus: Add sender name to bus activation log messages

Updated commit message, added loginfo, and dropped one of the changed messages.
Comment 9 Philip Withnall 2016-10-05 10:54:50 UTC
Created attachment 127024 [details] [review]
bus: Add LSM label to connection loginfo string

If it is set (i.e. if an LSM is in use) this will make it appear in various places in log output.

With SELinux, for example, this appends something like:
   label="system_u:object_r:unlabeled_t:s0"

This commit partially rearranges the code which sets the loginfo string, so that it consistently puts a space between fields, and not one at the end.
Comment 10 Simon McVittie 2016-10-05 13:53:33 UTC
Comment on attachment 127023 [details] [review]
bus: Add sender name to bus activation log messages

Review of attachment 127023 [details] [review]:
-----------------------------------------------------------------

Looks good
Comment 11 Simon McVittie 2016-10-05 13:54:45 UTC
Comment on attachment 127024 [details] [review]
bus: Add LSM label to connection loginfo string

Review of attachment 127024 [details] [review]:
-----------------------------------------------------------------

Thanks, this looks ideal.
Comment 12 Philip Withnall 2016-11-21 11:50:32 UTC
Whoops, I forgot to close this. The patches were pushed a while ago as 203a1e50940025a3e4ea675604a7db29d1fd71ae and 12a893b2ebcfe3af6d2a10c269565c105ed8f9d0, and were in the 1.11.6 release.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.