sd-bus: make sure type=error messages are also dumped #27

haraldh · 2015-06-02T13:56:04Z

No description provided.

dvdhrm · 2015-06-05T11:02:20Z

Isn't this also missing for method-replies in sd_bus_call()? That is, directly above your log_debug_bus_message() call for type=error we also directly return.

Maybe I'm missing something, but why not move your log_debug_...() call below the memmove() call above? That is, after unlinking the message from the rqueue, we print it.

utezduyar · 2015-06-05T14:29:43Z

Haven't looked at the code but replies work fine:

[root@axis-00408cecff49 /mnt/flash/root]1132# SYSTEMD_LOG_LEVEL=debug busctl tree com.a.b
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 error=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.227 object=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 error=n/a
Sent message type=method_call sender=n/a destination=com.a.b object=/ interface=org.freedesktop.DBus.Introspectable member=Introspect cookie=2 reply_cookie=0 error=n/a
Failed to introspect object / of service com.a.b: The name com.a.b was not provided by any .service files
No objects discovered.

WITH THE PATCH

[root@axis-00408cecff49 /mnt/flash/root]1132# SYSTEMD_LOG_LEVEL=debug busctl tree com.a.b
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 error=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.228 object=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 error=n/a
Sent message type=method_call sender=n/a destination=com.a.b object=/ interface=org.freedesktop.DBus.Introspectable member=Introspect cookie=2 reply_cookie=0 error=n/a
Got message type=error sender=org.freedesktop.DBus destination=:1.228 object=n/a interface=n/a member=n/a cookie=3 reply_cookie=2 error=The name com.a.b was not provided by any .service files
Failed to introspect object / of service com.a.b: The name com.a.b was not provided by any .service files
No objects discovered.

dvdhrm · 2015-06-05T14:44:18Z

Replies work only fine for asynchronously read messages. In those cases, errors also work fine, btw. The bug which is tried to get fixed here is about synchronously read messages. In those cases, neither return nor error messages are printed.

See this example:

david@david-t2 ~ $ SYSTEMD_LOG_LEVEL=7 busctl call org.freedesktop.login1 /org/freedesktop/login1 org.freedesktop.login1.Manager ListSessions
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 error=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.22 object=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 error=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.login1 object=/org/freedesktop/login1 interface=org.freedesktop.login1.Manager member=ListSessions cookie=2 reply_cookie=0 error=n/a
a(susso) 1 "c1" 1000 "david" "seat0" "/org/freedesktop/login1/session/c1"

As you can see, the async Hello message gets a method_return. But the sync ListSessions does not (even though the result is displayed).

utezduyar · 2015-06-06T21:21:46Z

Continuing from harald's pull request instead of creating a new one... Btw, thanks David.

From 2e6520ffd6efbb2bf26462008a4c2371b70c8fb8 Mon Sep 17 00:00:00 2001
From: Umut Tezduyar Lindskog <[email protected]>
Date: Fri, 29 May 2015 09:48:11 +0200
Subject: [PATCH] sd-bus: make sure type=error messages are also dumped

---
 src/libsystemd/sd-bus/sd-bus.c | 23 +++++++++++++----------
 1 file changed, 13 insertions(+), 10 deletions(-)

diff --git a/src/libsystemd/sd-bus/sd-bus.c b/src/libsystemd/sd-bus/sd-bus.c
index edc27ae..096564d 100644
--- a/src/libsystemd/sd-bus/sd-bus.c
+++ b/src/libsystemd/sd-bus/sd-bus.c
@@ -49,6 +49,17 @@
 #include "bus-track.h"
 #include "bus-slot.h"

+#define log_debug_bus_message(m) log_debug("Got message type=%s sender=%s destination=%s object=%s interface=%s member=%s cookie=%" PRIu64 " reply_cookie=%" PRIu64 " error=%s", \
+                  bus_message_type_to_string(m->header->type), \
+                  strna(sd_bus_message_get_sender(m)), \
+                  strna(sd_bus_message_get_destination(m)), \
+                  strna(sd_bus_message_get_path(m)), \
+                  strna(sd_bus_message_get_interface(m)), \
+                  strna(sd_bus_message_get_member(m)), \
+                  BUS_MESSAGE_COOKIE(m), \
+                  m->reply_cookie, \
+                  strna(m->error.message))
+
 static int bus_poll(sd_bus *bus, bool need_more, uint64_t timeout_usec);
 static int attach_io_events(sd_bus *b);
 static void detach_io_events(sd_bus *b);
@@ -1992,6 +2003,7 @@ _public_ int sd_bus_call(

                                 memmove(bus->rqueue + i, bus->rqueue + i + 1, sizeof(sd_bus_message*) * (bus->rqueue_size - i - 1));
                                 bus->rqueue_size--;
+                                log_debug_bus_message(incoming);

                                 if (incoming->header->type == SD_BUS_MESSAGE_METHOD_RETURN) {

@@ -2480,16 +2492,7 @@ static int process_message(sd_bus *bus, sd_bus_message *m) {
         bus->current_message = m;
         bus->iteration_counter++;

-        log_debug("Got message type=%s sender=%s destination=%s object=%s interface=%s member=%s cookie=%" PRIu64 " reply_cookie=%" PRIu64 " error=%s",
-                  bus_message_type_to_string(m->header->type),
-                  strna(sd_bus_message_get_sender(m)),
-                  strna(sd_bus_message_get_destination(m)),
-                  strna(sd_bus_message_get_path(m)),
-                  strna(sd_bus_message_get_interface(m)),
-                  strna(sd_bus_message_get_member(m)),
-                  BUS_MESSAGE_COOKIE(m),
-                  m->reply_cookie,
-                  strna(m->error.message));
+        log_debug_bus_message(m);

         r = process_hello(bus, m);
         if (r != 0)
-- 
2.1.4

poettering · 2015-06-08T19:38:33Z

@utezduyar your last patch looks good, can you post this as new PR please refencing this one so that we can merge it?

utezduyar · 2015-06-09T06:50:00Z

Moved to #117
Please close this PR.

This wrapper is used in situations where we don't care about *San reports, we just want to make things work. However, with enabled LSan we might trigger some bogus reports we're definitely not interested in, causing unexpected test fails. Spotted on C8S in TEST-34-DYNAMICUSERMIGRATE: ``` [10654.804162] testsuite-34.sh[56]: + systemctl start testservice-34-check-writable.service Starting testservice-34-check-writable.service... [10655.055969] bash[546]: + set -o pipefail [10655.056127] bash[546]: + declare -a writable_dirs [10655.056234] bash[546]: + readarray -t writable_dirs [10655.060838] bash[548]: ++ find / '(' -path /var/tmp -o -path /tmp -o -path /proc -o -path /dev/mqueue -o -path /dev/shm -o -path /sys/fs/bpf -o -path /dev/.lxc -o -path /sys/devices/system/cpu ')' -prune -o -type d -writable -print [10655.061534] bash[549]: ++ sort -u [10655.688740] bash[547]: ================================================================= [10655.689075] bash[547]: ==547==ERROR: LeakSanitizer: detected memory leaks [10655.689246] bash[547]: Direct leak of 112 byte(s) in 1 object(s) allocated from: [10655.743851] bash[547]: #0 0x7ffff752d364 (/usr/lib64/clang/14.0.0/lib/libclang_rt.asan-powerpc64le.so+0x13d364) (BuildId: 321f4ed1caea6a1a4c37f9272e07275cf16f034d) [10655.744060] bash[547]: #1 0x1000b5d20 in xmalloc (/usr/bin/bash+0xb5d20) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.744224] bash[547]: #2 0x100083338 (/usr/bin/bash+0x83338) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.744393] bash[547]: #3 0x10008847c (/usr/bin/bash+0x8847c) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.744552] bash[547]: #4 0x1000af6ec in redirection_expand (/usr/bin/bash+0xaf6ec) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.744728] bash[547]: #5 0x1000b005c (/usr/bin/bash+0xb005c) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.744886] bash[547]: #6 0x1000b1388 in do_redirections (/usr/bin/bash+0xb1388) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.745051] bash[547]: #7 0x100050484 (/usr/bin/bash+0x50484) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.745208] bash[547]: #8 0x100052160 in execute_command_internal (/usr/bin/bash+0x52160) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.745376] bash[547]: #9 0x100052a10 in execute_command_internal (/usr/bin/bash+0x52a10) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.745536] bash[547]: #10 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.745711] bash[547]: #11 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.745870] bash[547]: #12 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.746038] bash[547]: #13 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.746198] bash[547]: #14 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.746367] bash[547]: #15 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.746548] bash[547]: #16 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.746741] bash[547]: #17 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.746897] bash[547]: #18 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.747067] bash[547]: #19 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.747227] bash[547]: #20 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.747414] bash[547]: #21 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.747573] bash[547]: #22 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.747741] bash[547]: #23 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.747896] bash[547]: #24 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.748064] bash[547]: #25 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.748225] bash[547]: #26 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.748390] bash[547]: #27 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.748553] bash[547]: #28 0x1000bf91c in parse_and_execute (/usr/bin/bash+0xbf91c) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.748717] bash[547]: #29 0x1000311ec (/usr/bin/bash+0x311ec) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.748883] bash[547]: Direct leak of 17 byte(s) in 1 object(s) allocated from: ... ```

This wrapper is used in situations where we don't care about *San reports, we just want to make things work. However, with enabled LSan we might trigger some bogus reports we're definitely not interested in, causing unexpected test fails. Spotted on C8S in TEST-34-DYNAMICUSERMIGRATE: ``` [10654.804162] testsuite-34.sh[56]: + systemctl start testservice-34-check-writable.service Starting testservice-34-check-writable.service... [10655.055969] bash[546]: + set -o pipefail [10655.056127] bash[546]: + declare -a writable_dirs [10655.056234] bash[546]: + readarray -t writable_dirs [10655.060838] bash[548]: ++ find / '(' -path /var/tmp -o -path /tmp -o -path /proc -o -path /dev/mqueue -o -path /dev/shm -o -path /sys/fs/bpf -o -path /dev/.lxc -o -path /sys/devices/system/cpu ')' -prune -o -type d -writable -print [10655.061534] bash[549]: ++ sort -u [10655.688740] bash[547]: ================================================================= [10655.689075] bash[547]: ==547==ERROR: LeakSanitizer: detected memory leaks [10655.689246] bash[547]: Direct leak of 112 byte(s) in 1 object(s) allocated from: [10655.743851] bash[547]: #0 0x7ffff752d364 (/usr/lib64/clang/14.0.0/lib/libclang_rt.asan-powerpc64le.so+0x13d364) (BuildId: 321f4ed1caea6a1a4c37f9272e07275cf16f034d) [10655.744060] bash[547]: #1 0x1000b5d20 in xmalloc (/usr/bin/bash+0xb5d20) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.744224] bash[547]: #2 0x100083338 (/usr/bin/bash+0x83338) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.744393] bash[547]: #3 0x10008847c (/usr/bin/bash+0x8847c) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.744552] bash[547]: #4 0x1000af6ec in redirection_expand (/usr/bin/bash+0xaf6ec) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.744728] bash[547]: #5 0x1000b005c (/usr/bin/bash+0xb005c) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.744886] bash[547]: #6 0x1000b1388 in do_redirections (/usr/bin/bash+0xb1388) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.745051] bash[547]: #7 0x100050484 (/usr/bin/bash+0x50484) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.745208] bash[547]: #8 0x100052160 in execute_command_internal (/usr/bin/bash+0x52160) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.745376] bash[547]: #9 0x100052a10 in execute_command_internal (/usr/bin/bash+0x52a10) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.745536] bash[547]: #10 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.745711] bash[547]: #11 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.745870] bash[547]: #12 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.746038] bash[547]: #13 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.746198] bash[547]: #14 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.746367] bash[547]: systemd#15 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.746548] bash[547]: systemd#16 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.746741] bash[547]: systemd#17 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.746897] bash[547]: systemd#18 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.747067] bash[547]: systemd#19 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.747227] bash[547]: systemd#20 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.747414] bash[547]: systemd#21 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.747573] bash[547]: systemd#22 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.747741] bash[547]: systemd#23 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.747896] bash[547]: systemd#24 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.748064] bash[547]: systemd#25 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.748225] bash[547]: systemd#26 0x100053e38 in execute_command (/usr/bin/bash+0x53e38) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.748390] bash[547]: systemd#27 0x1000529d8 in execute_command_internal (/usr/bin/bash+0x529d8) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.748553] bash[547]: systemd#28 0x1000bf91c in parse_and_execute (/usr/bin/bash+0xbf91c) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.748717] bash[547]: systemd#29 0x1000311ec (/usr/bin/bash+0x311ec) (BuildId: da38eb38f6870bdc2a6ef51c52aa6ce20921fe40) [10655.748883] bash[547]: Direct leak of 17 byte(s) in 1 object(s) allocated from: ... ``` (cherry picked from commit b8dd276)

When check_access() was added, the callback data parameter was changed from a pointer to a double pointer, resulting in a crash when it is accessed when logging an error: #0 __internal_syscall_cancel (a1=a1@entry=0, a2=a2@entry=0, a3=a3@entry=140726176497168, a4=a4@entry=4, a5=a5@entry=0, a6=a6@entry=0, nr=247) at ./nptl/cancellation.c:44 #1 0x00007f5d0ec996ad in __syscall_cancel (a1=a1@entry=0, a2=a2@entry=0, a3=a3@entry=140726176497168, a4=a4@entry=4, a5=a5@entry=0, a6=a6@entry=0, nr=247) at ./nptl/cancellation.c:75 #2 0x00007f5d0ed047ab in __waitid (idtype=idtype@entry=P_ALL, id=id@entry=0, infop=infop@entry=0x7ffd5dc2be10, options=options@entry=4) at ../sysdeps/unix/sysv/linux/waitid.c:29 #3 0x00007f5d0f044412 in freeze () at ../src/basic/process-util.c:2039 #4 0x00005568f181bc2a in freeze_or_exit_or_reboot () at ../src/core/crash-handler.c:55 #5 0x00005568f181be82 in crash (sig=<optimized out>, siginfo=<optimized out>, context=<optimized out>) at ../src/core/crash-handler.c:184 #6 <signal handler called> #7 __strlen_avx2 () at ../sysdeps/x86_64/multiarch/strlen-avx2.S:76 #8 0x00007f5d0ec6e300 in __printf_buffer (buf=buf@entry=0x7ffd5dc2ca90, format=0x7f5d0f196e60 "%s: Failed to acquire credentials: %m", ap=0x7ffd5dc2d3d0, mode_flags=2) at ./stdio-common/vfprintf-process-arg.c:435 #9 0x00007f5d0ec91daf in __vsnprintf_internal (string=string@entry=0x7ffd5dc2cb70 "", maxlen=maxlen@entry=2048, format=format@entry=0x7f5d0f196e60 "%s: Failed to acquire credentials: %m", args=args@entry=0x7ffd5dc2d3d0, mode_flags=mode_flags@entry=2) at ./libio/vsnprintf.c:96 #10 0x00007f5d0ed27044 in ___vsnprintf_chk (s=s@entry=0x7ffd5dc2cb70 "", maxlen=maxlen@entry=2048, flag=flag@entry=1, slen=slen@entry=2048, format=format@entry=0x7f5d0f196e60 "%s: Failed to acquire credentials: %m", ap=ap@entry=0x7ffd5dc2d3d0) at ./debug/vsnprintf_chk.c:34 #11 0x00007f5d0f02de59 in vsnprintf (__s=0x7ffd5dc2cb70 "", __n=2048, __fmt=0x7f5d0f196e60 "%s: Failed to acquire credentials: %m", __ap=0x7ffd5dc2d3d0) at /usr/include/x86_64-linux-gnu/bits/stdio2.h:100 #12 log_internalv (level=7, error=-9, file=0x7f5d0f196643 "src/libsystemd/sd-varlink/sd-varlink.c", line=2853, func=0x7f5d0f1d5ca0 <__func__.62> "sd_varlink_get_peer_uid", format=0x7f5d0f196e60 "%s: Failed to acquire credentials: %m", ap=0x7ffd5dc2d3d0) at ../src/basic/log.c:865 #13 0x00007f5d0f02ded5 in log_internalv (level=<optimized out>, error=<optimized out>, file=<optimized out>, line=<optimized out>, func=<optimized out>, format=<optimized out>, ap=0x7ffd5dc2d3d0) at ../src/basic/log.c:868 #14 0x00007f5d0f02df67 in log_internal (level=<optimized out>, error=<optimized out>, file=<optimized out>, line=<optimized out>, func=<optimized out>, format=<optimized out>) at ../src/basic/log.c:882 #15 0x00007f5d0f10a135 in sd_varlink_get_peer_uid (v=0x7f5d0f5ab110 <__func__.44>, ret=ret@entry=0x7ffd5dc2d4f0) at ../src/libsystemd/sd-varlink/sd-varlink.c:2853 #16 0x00007f5d0f50c29e in audit_callback (auditdata=0x7ffd5dc2d698, cls=<optimized out>, msgbuf=0x55692366e77d "", msgbufsize=995) at ../src/core/selinux-access.c:65 #17 0x00007f5d0f716079 in avc_suppl_audit (ptr=0x7ffd5dc2d698, class=95, buf=<optimized out>, len=<optimized out>) at ./src/avc_internal.h:101 #18 avc_audit (ssid=0x5569237f2890, tsid=0x556922d7f4b0, tclass=<optimized out>, requested=<optimized out>, avd=<optimized out>, result=0, a=0x7ffd5dc2d698) at ./src/avc.c:721 #19 0x00007f5d0f716367 in avc_has_perm (ssid=0x5569237f2890, tsid=0x556922d7f4b0, tclass=tclass@entry=95, requested=4, aeref=aeref@entry=0x0, auditdata=auditdata@entry=0x7ffd5dc2d698) at ./src/avc.c:836 #20 0x00007f5d0f718b0a in selinux_check_access (scon=scon@entry=0x55692384cbc0 "system_u:system_r:policykit_t:s0", tcon=tcon@entry=0x556922c98a20 "system_u:object_r:systemd_networkd_unit_t:s0", class=class@entry=0x7f5d0f580b9e "service", perm=perm@entry=0x7f5d0f580cc0 "status", aux=aux@entry=0x7ffd5dc2d698) at ./src/checkAccess.c:64 #21 0x00007f5d0f50bf7e in check_access (scon=0x55692384cbc0 "system_u:system_r:policykit_t:s0", tcon=0x556922c98a20 "system_u:object_r:systemd_networkd_unit_t:s0", tclass=0x7f5d0f580b9e "service", permission=permission@entry=0x7f5d0f580cc0 "status", audit_info=<optimized out>, audit_info@entry=0x7ffd5dc2d720, error=error@entry=0x7ffd5dc2d880) at ../src/core/selinux-access.c:229 #22 0x00007f5d0f5100a1 in mac_selinux_access_check_bus_internal (message=<optimized out>, unit=<optimized out>, permission=0x7f5d0f580cc0 "status", function=0x7f5d0f5ab110 <__func__.44> "method_get_unit_by_pidfd", error=0x7ffd5dc2d880) at ../src/core/selinux-access.c:329 #23 0x00007f5d0f4a024b in method_get_unit_by_pidfd (message=0x5569236d9010, userdata=<optimized out>, error=0x7ffd5dc2d880) at ../src/core/dbus-manager.c:657 #24 0x00007f5d0f0c9bd0 in method_callbacks_run (bus=0x5569238684e0, m=0x5569236d9010, c=<optimized out>, require_fallback=false, found_object=0x7ffd5dc2d947) at ../src/libsystemd/sd-bus/bus-objects.c:413 #25 object_find_and_run (bus=bus@entry=0x5569238684e0, m=m@entry=0x5569236d9010, p=<optimized out>, require_fallback=require_fallback@entry=false, found_object=found_object@entry=0x7ffd5dc2d947) at ../src/libsystemd/sd-bus/bus-objects.c:1323 #26 0x00007f5d0f0cafa2 in bus_process_object (bus=0x5569238684e0, m=0x5569236d9010) at ../src/libsystemd/sd-bus/bus-objects.c:1443 systemd#27 0x00007f5d0f0d8c3e in process_message (bus=0x5569238684e0, m=0x5569236d9010) at ../src/libsystemd/sd-bus/sd-bus.c:3006 systemd#28 process_running (bus=0x5569238684e0, ret=0x0) at ../src/libsystemd/sd-bus/sd-bus.c:3048 systemd#29 bus_process_internal (bus=bus@entry=0x5569238684e0, ret=ret@entry=0x0) at ../src/libsystemd/sd-bus/sd-bus.c:3275 systemd#30 0x00007f5d0f0d9099 in sd_bus_process (bus=bus@entry=0x5569238684e0, ret=ret@entry=0x0) at ../src/libsystemd/sd-bus/sd-bus.c:3302 systemd#31 0x00007f5d0f0db3ec in io_callback (s=<optimized out>, fd=<optimized out>, revents=<optimized out>, userdata=0x5569238684e0) at ../src/libsystemd/sd-bus/sd-bus.c:3643 systemd#32 0x00007f5d0f0a53d9 in source_dispatch (s=s@entry=0x5569236dea60) at ../src/libsystemd/sd-event/sd-event.c:4163 systemd#33 0x00007f5d0f0a563d in sd_event_dispatch (e=<optimized out>, e@entry=0x5569232f6c00) at ../src/libsystemd/sd-event/sd-event.c:4782 systemd#34 0x00007f5d0f0a6d38 in sd_event_run (e=<optimized out>, timeout=18446744073709551615) at ../src/libsystemd/sd-event/sd-event.c:4843 systemd#35 0x00007f5d0f4f7871 in manager_loop (m=m@entry=0x5569232f8250) at ../src/core/manager.c:3310 systemd#36 0x00005568f181517d in invoke_main_loop (m=0x5569232f8250, saved_rlimit_nofile=0x7ffd5dc2dcb0, saved_rlimit_memlock=0x7ffd5dc2dca0, ret_retval=<synthetic pointer>, ret_fds=0x7ffd5dc2dc78, ret_switch_root_dir=<synthetic pointer>, ret_switch_root_init=<synthetic pointer>, ret_error_message=0x7ffd5dc2dc90) at ../src/core/main.c:2140 systemd#37 main (argc=<optimized out>, argv=0x7ffd5dc2dfe8) at ../src/core/main.c:3351 Follow-up for fe3f2ac

When check_access() was added, the callback data parameter was changed from a pointer to a double pointer, resulting in a crash when it is accessed when logging an error: #0 __internal_syscall_cancel (a1=a1@entry=0, a2=a2@entry=0, a3=a3@entry=140726176497168, a4=a4@entry=4, a5=a5@entry=0, a6=a6@entry=0, nr=247) at ./nptl/cancellation.c:44 #1 0x00007f5d0ec996ad in __syscall_cancel (a1=a1@entry=0, a2=a2@entry=0, a3=a3@entry=140726176497168, a4=a4@entry=4, a5=a5@entry=0, a6=a6@entry=0, nr=247) at ./nptl/cancellation.c:75 #2 0x00007f5d0ed047ab in __waitid (idtype=idtype@entry=P_ALL, id=id@entry=0, infop=infop@entry=0x7ffd5dc2be10, options=options@entry=4) at ../sysdeps/unix/sysv/linux/waitid.c:29 #3 0x00007f5d0f044412 in freeze () at ../src/basic/process-util.c:2039 #4 0x00005568f181bc2a in freeze_or_exit_or_reboot () at ../src/core/crash-handler.c:55 #5 0x00005568f181be82 in crash (sig=<optimized out>, siginfo=<optimized out>, context=<optimized out>) at ../src/core/crash-handler.c:184 #6 <signal handler called> #7 __strlen_avx2 () at ../sysdeps/x86_64/multiarch/strlen-avx2.S:76 #8 0x00007f5d0ec6e300 in __printf_buffer (buf=buf@entry=0x7ffd5dc2ca90, format=0x7f5d0f196e60 "%s: Failed to acquire credentials: %m", ap=0x7ffd5dc2d3d0, mode_flags=2) at ./stdio-common/vfprintf-process-arg.c:435 #9 0x00007f5d0ec91daf in __vsnprintf_internal (string=string@entry=0x7ffd5dc2cb70 "", maxlen=maxlen@entry=2048, format=format@entry=0x7f5d0f196e60 "%s: Failed to acquire credentials: %m", args=args@entry=0x7ffd5dc2d3d0, mode_flags=mode_flags@entry=2) at ./libio/vsnprintf.c:96 #10 0x00007f5d0ed27044 in ___vsnprintf_chk (s=s@entry=0x7ffd5dc2cb70 "", maxlen=maxlen@entry=2048, flag=flag@entry=1, slen=slen@entry=2048, format=format@entry=0x7f5d0f196e60 "%s: Failed to acquire credentials: %m", ap=ap@entry=0x7ffd5dc2d3d0) at ./debug/vsnprintf_chk.c:34 #11 0x00007f5d0f02de59 in vsnprintf (__s=0x7ffd5dc2cb70 "", __n=2048, __fmt=0x7f5d0f196e60 "%s: Failed to acquire credentials: %m", __ap=0x7ffd5dc2d3d0) at /usr/include/x86_64-linux-gnu/bits/stdio2.h:100 #12 log_internalv (level=7, error=-9, file=0x7f5d0f196643 "src/libsystemd/sd-varlink/sd-varlink.c", line=2853, func=0x7f5d0f1d5ca0 <__func__.62> "sd_varlink_get_peer_uid", format=0x7f5d0f196e60 "%s: Failed to acquire credentials: %m", ap=0x7ffd5dc2d3d0) at ../src/basic/log.c:865 #13 0x00007f5d0f02ded5 in log_internalv (level=<optimized out>, error=<optimized out>, file=<optimized out>, line=<optimized out>, func=<optimized out>, format=<optimized out>, ap=0x7ffd5dc2d3d0) at ../src/basic/log.c:868 #14 0x00007f5d0f02df67 in log_internal (level=<optimized out>, error=<optimized out>, file=<optimized out>, line=<optimized out>, func=<optimized out>, format=<optimized out>) at ../src/basic/log.c:882 #15 0x00007f5d0f10a135 in sd_varlink_get_peer_uid (v=0x7f5d0f5ab110 <__func__.44>, ret=ret@entry=0x7ffd5dc2d4f0) at ../src/libsystemd/sd-varlink/sd-varlink.c:2853 #16 0x00007f5d0f50c29e in audit_callback (auditdata=0x7ffd5dc2d698, cls=<optimized out>, msgbuf=0x55692366e77d "", msgbufsize=995) at ../src/core/selinux-access.c:65 #17 0x00007f5d0f716079 in avc_suppl_audit (ptr=0x7ffd5dc2d698, class=95, buf=<optimized out>, len=<optimized out>) at ./src/avc_internal.h:101 #18 avc_audit (ssid=0x5569237f2890, tsid=0x556922d7f4b0, tclass=<optimized out>, requested=<optimized out>, avd=<optimized out>, result=0, a=0x7ffd5dc2d698) at ./src/avc.c:721 #19 0x00007f5d0f716367 in avc_has_perm (ssid=0x5569237f2890, tsid=0x556922d7f4b0, tclass=tclass@entry=95, requested=4, aeref=aeref@entry=0x0, auditdata=auditdata@entry=0x7ffd5dc2d698) at ./src/avc.c:836 #20 0x00007f5d0f718b0a in selinux_check_access (scon=scon@entry=0x55692384cbc0 "system_u:system_r:policykit_t:s0", tcon=tcon@entry=0x556922c98a20 "system_u:object_r:systemd_networkd_unit_t:s0", class=class@entry=0x7f5d0f580b9e "service", perm=perm@entry=0x7f5d0f580cc0 "status", aux=aux@entry=0x7ffd5dc2d698) at ./src/checkAccess.c:64 #21 0x00007f5d0f50bf7e in check_access (scon=0x55692384cbc0 "system_u:system_r:policykit_t:s0", tcon=0x556922c98a20 "system_u:object_r:systemd_networkd_unit_t:s0", tclass=0x7f5d0f580b9e "service", permission=permission@entry=0x7f5d0f580cc0 "status", audit_info=<optimized out>, audit_info@entry=0x7ffd5dc2d720, error=error@entry=0x7ffd5dc2d880) at ../src/core/selinux-access.c:229 #22 0x00007f5d0f5100a1 in mac_selinux_access_check_bus_internal (message=<optimized out>, unit=<optimized out>, permission=0x7f5d0f580cc0 "status", function=0x7f5d0f5ab110 <__func__.44> "method_get_unit_by_pidfd", error=0x7ffd5dc2d880) at ../src/core/selinux-access.c:329 #23 0x00007f5d0f4a024b in method_get_unit_by_pidfd (message=0x5569236d9010, userdata=<optimized out>, error=0x7ffd5dc2d880) at ../src/core/dbus-manager.c:657 #24 0x00007f5d0f0c9bd0 in method_callbacks_run (bus=0x5569238684e0, m=0x5569236d9010, c=<optimized out>, require_fallback=false, found_object=0x7ffd5dc2d947) at ../src/libsystemd/sd-bus/bus-objects.c:413 #25 object_find_and_run (bus=bus@entry=0x5569238684e0, m=m@entry=0x5569236d9010, p=<optimized out>, require_fallback=require_fallback@entry=false, found_object=found_object@entry=0x7ffd5dc2d947) at ../src/libsystemd/sd-bus/bus-objects.c:1323 #26 0x00007f5d0f0cafa2 in bus_process_object (bus=0x5569238684e0, m=0x5569236d9010) at ../src/libsystemd/sd-bus/bus-objects.c:1443 #27 0x00007f5d0f0d8c3e in process_message (bus=0x5569238684e0, m=0x5569236d9010) at ../src/libsystemd/sd-bus/sd-bus.c:3006 #28 process_running (bus=0x5569238684e0, ret=0x0) at ../src/libsystemd/sd-bus/sd-bus.c:3048 #29 bus_process_internal (bus=bus@entry=0x5569238684e0, ret=ret@entry=0x0) at ../src/libsystemd/sd-bus/sd-bus.c:3275 #30 0x00007f5d0f0d9099 in sd_bus_process (bus=bus@entry=0x5569238684e0, ret=ret@entry=0x0) at ../src/libsystemd/sd-bus/sd-bus.c:3302 #31 0x00007f5d0f0db3ec in io_callback (s=<optimized out>, fd=<optimized out>, revents=<optimized out>, userdata=0x5569238684e0) at ../src/libsystemd/sd-bus/sd-bus.c:3643 #32 0x00007f5d0f0a53d9 in source_dispatch (s=s@entry=0x5569236dea60) at ../src/libsystemd/sd-event/sd-event.c:4163 #33 0x00007f5d0f0a563d in sd_event_dispatch (e=<optimized out>, e@entry=0x5569232f6c00) at ../src/libsystemd/sd-event/sd-event.c:4782 #34 0x00007f5d0f0a6d38 in sd_event_run (e=<optimized out>, timeout=18446744073709551615) at ../src/libsystemd/sd-event/sd-event.c:4843 #35 0x00007f5d0f4f7871 in manager_loop (m=m@entry=0x5569232f8250) at ../src/core/manager.c:3310 #36 0x00005568f181517d in invoke_main_loop (m=0x5569232f8250, saved_rlimit_nofile=0x7ffd5dc2dcb0, saved_rlimit_memlock=0x7ffd5dc2dca0, ret_retval=<synthetic pointer>, ret_fds=0x7ffd5dc2dc78, ret_switch_root_dir=<synthetic pointer>, ret_switch_root_init=<synthetic pointer>, ret_error_message=0x7ffd5dc2dc90) at ../src/core/main.c:2140 #37 main (argc=<optimized out>, argv=0x7ffd5dc2dfe8) at ../src/core/main.c:3351 Follow-up for fe3f2ac

sd-bus: make sure type=error messages are also dumped

62a53c6

zonque assigned poettering Jun 2, 2015

zonque added the sd-bus label Jun 2, 2015

zonque closed this Jun 9, 2015

haraldh deleted the [email protected] branch July 21, 2018 07:22

pabs3 mentioned this pull request Jul 17, 2020

session dbus-daemon crashed (SIGABRT) in libnss-systemd #15859

Closed

This was referenced Sep 23, 2020

core dump on systemd-udevd #14862

Closed

Assertion 'n_rehashed == n_entries(h)' failed at src/basic/hashmap.c:1206, function resize_buckets() #11497

Closed

elschman mentioned this pull request Oct 20, 2020

transient hostname received from dhcp server (option 12) is not set for longer period. goes away after a minute or two #17402

Closed

jcg190701 mentioned this pull request Dec 8, 2020

systemd coredump when it comes to unit_name_to_prefix or unit_name_to_type #17897

Closed

gaoyi1988 mentioned this pull request Dec 28, 2020

daemon-reexec coredump #18099

Closed

JetXujing mentioned this pull request Sep 8, 2021

core: fix free undefined pointer when strdup failed in the first loop #20662

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

sd-bus: make sure type=error messages are also dumped #27

sd-bus: make sure type=error messages are also dumped #27

Uh oh!

haraldh commented Jun 2, 2015

Uh oh!

dvdhrm commented Jun 5, 2015

Uh oh!

utezduyar commented Jun 5, 2015

Uh oh!

dvdhrm commented Jun 5, 2015

Uh oh!

utezduyar commented Jun 6, 2015

Uh oh!

poettering commented Jun 8, 2015

Uh oh!

utezduyar commented Jun 9, 2015

Uh oh!

Reviewers

Assignees

Labels

Milestone

Development

Uh oh!

5 participants

Uh oh!

sd-bus: make sure type=error messages are also dumped #27

sd-bus: make sure type=error messages are also dumped #27

Uh oh!

Conversation

haraldh commented Jun 2, 2015

Uh oh!

dvdhrm commented Jun 5, 2015

Uh oh!

utezduyar commented Jun 5, 2015

WITH THE PATCH

Uh oh!

dvdhrm commented Jun 5, 2015

Uh oh!

utezduyar commented Jun 6, 2015

Uh oh!

poettering commented Jun 8, 2015

Uh oh!

utezduyar commented Jun 9, 2015

Uh oh!

Reviewers

Assignees

Labels

Milestone

Development

Uh oh!

5 participants