Abort when killing dbus service and monitoring bus

[benzea]

I was doing some bus monitoring using dbus-monitor with various watches. I am not sure I can still recover the exact watch expression and I changed it around quite a bit before. In the end I hit Ctrl+C on the service I was debugging (not dbus-monitor), and dbus-broker died with the following.

Nov 17 11:27:24 ben-x1c7 dbus-broker-launch[9968]: dbus-broker: ../src/bus/match.c:1016: match_registry_deinit: Assertion `c_assert_result && "c_rbtree_is_empty(&registry->monitor_tree)"' failed.
Nov 17 11:27:25 ben-x1c7 dbus-broker-launch[9950]: ERROR launcher_run @ ../src/launch/launcher.c +1407: Return code 1
Nov 17 11:27:25 ben-x1c7 dbus-broker-launch[9950]:       run @ ../src/launch/main.c +152
Nov 17 11:27:25 ben-x1c7 dbus-broker-launch[9950]:       main @ ../src/launch/main.c +178
Nov 17 11:27:25 ben-x1c7 dbus-broker-launch[9950]: Exiting due to fatal error: -131

The backtrace is pretty boring to be honest.

Thread 1 (Thread 0x7f4acd959e40 (LWP 9968)):
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00007f4acda44895 in __GI_abort () at abort.c:79
#2  0x00007f4acda44769 in __assert_fail_base (fmt=0x7f4acdbb20b8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55b5393cc258 "c_assert_result && \"c_rbtree_is_empty(&registry->monitor_tree)\"", file=0x55b5393cbe86 "../src/bus/match.c", line=1016, function=<optimized out>) at assert.c:92
#3  0x00007f4acda53e76 in __GI___assert_fail (assertion=assertion@entry=0x55b5393cc258 "c_assert_result && \"c_rbtree_is_empty(&registry->monitor_tree)\"", file=file@entry=0x55b5393cbe86 "../src/bus/match.c", line=line@entry=1016, function=function@entry=0x55b5393cc350 <__PRETTY_FUNCTION__.5> "match_registry_deinit") at assert.c:101
#4  0x000055b5393b3b28 in match_registry_deinit (registry=registry@entry=0x55b53a888a10) at ../src/bus/match.c:1016
#5  0x000055b5393b5423 in peer_free (peer=peer@entry=0x55b53a887fe0) at ../src/bus/peer.c:357
#6  0x000055b5393b5801 in peer_dispatch (file=<optimized out>) at ../src/bus/peer.c:229
#7  0x000055b5393bec20 in dispatch_context_dispatch (ctx=ctx@entry=0x55b53a42ae28) at ../src/util/dispatch.c:343
#8  0x000055b5393a5538 in broker_run (broker=0x55b53a42ace0) at ../src/broker/broker.c:219
#9  0x000055b5393a477d in run () at ../src/broker/main.c:242
#10 main (argc=<optimized out>, argv=<optimized out>) at ../src/broker/main.c:268

I did have a watch both on the well-known name and the actual client name for the service that I killed (i.e. got removed). Maybe it has to do with the fact that both were watched either as sender or destination in some way.

[benzea]

Not sure if that is any useful, but here is some more stuff from the peer:

(gdb) print *peer
$2 = {bus = 0x55b53a42ad10, user = 0x55b53a42bcc0, pid = 1133095, gids = 0x55b53a7df7b0, n_gids = 2, seclabel = 0x55b53a7b5e20 "unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023", n_seclabel = 53, charges = {{
      usage = 0x0, slot = 0, charge = 0}, {usage = 0x0, slot = 0, charge = 0}, {usage = 0x0, slot = 0, charge = 0}}, id = 3510, registry_node = {__parent_and_flags = 94236859465832, left = 0x0, right = 0x0}, 
  listener_link = {next = 0x55b53a888080, prev = 0x55b53a888080}, connection = {socket = {user = 0x55b53a42bcc0, fd = 119, shutdown = true, reset = true, hup_in = true, hup_out = true, in = {queue = {user = 0x55b53a42bcc0, 
          charge_data = {usage = 0x0, slot = 0, charge = 0}, charge_fds = {usage = 0x0, slot = 0, charge = 0}, data = 0x55b53a888158 "l\001", data_size = 2048, data_start = 0, data_end = 0, data_cursor = 0, fds = 0x0, 
          pending = {charge_data = {usage = 0x55b53a543bb0, slot = 0, charge = 16}, charge_fds = {usage = 0x0, slot = 0, charge = 0}, data = 0x55b53a888958, n_data = 16, n_copied = 0, fds = 0x0}, 
          buffer = "l\001\000\001\227\000\000\000\256\000\000\000|\000\000\000\001\001o\000\025\000\000\000/org/freedesktop/DBus\000\000\000\002\001s\000\024\000\000\000org.freedesktop.DBus\000\000\000\000\006\001s\000\024\000\000\000org.freedesktop.DBus\000\000\000\000\b\001g\000\001s\000\000\003\001s\000\v\000\000\000RemoveMatch\000\000\000\000\000\222\000\000\000type='signal',sender='org.freedesktop.DBus',interfac"...}, header = {
          endian = 108 'l', type = 1 '\001', flags = 0 '\000', version = 1 '\001', n_body = 151, serial = 174, n_fields = 124}, message = 0x0}, out = {queue = {next = 0x55b53a888970, prev = 0x55b53a888970}, pending = {
          next = 0x55b53a888980, prev = 0x55b53a888980}}}, socket_file = {context = 0x55b53a42ae28, ready_link = {next = 0x55b53a42ae28, prev = 0x55b53a56df98}, fn = 0x55b5393b5500 <peer_dispatch>, fd = 119, 
      user_mask = 16, kernel_mask = 21, events = 21}, sasl_server = {state = 1, fds_allowed = true, uid = 0, ok_response = "OK 8821277458a0c75aebcd8ada13c93c36"}, sasl_client = {state = 0}, server = true, 
    authenticated = true}, registered = false, monitor = false, policy = 0x55b53a59f5e0, owned_names = {ownership_tree = {root = 0x0}}, sender_matches = {subscription_tree = {root = 0x0}, monitor_tree = {
      root = 0x55b53a777670}}, name_owner_changed_matches = {subscription_tree = {root = 0x0}, monitor_tree = {root = 0x0}}, owned_matches = {rule_tree = {root = 0x0}, destinations_link = {next = 0x55b53a888a38, 
      prev = 0x55b53a888a38}}, replies = {reply_tree = {root = 0x0}}, owned_replies = {reply_list = {next = 0x55b53a888a50, prev = 0x55b53a888a50}}}

(gdb) print -elements unlimited -- peer->connection->socket->in->queue->buffer 
$4 = "l\001\000\001\227\000\000\000\256\000\000\000|\000\000\000\001\001o\000\025\000\000\000/org/freedesktop/DBus\000\000\000\002\001s\000\024\000\000\000org.freedesktop.DBus\000\000\000\000\006\001s\000\024\000\000\000org.freedesktop.DBus\000\000\000\000\b\001g\000\001s\000\000\003\001s\000\v\000\000\000RemoveMatch\000\000\000\000\000\222\000\000\000type='signal',sender='org.freedesktop.DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',path='/org/freedesktop/DBus',arg0=':1.3558'\000l\001\000\001\f\000\000\000\251\000\000\000}\000\000\000\001\001o\000\025\000\000\000/org/freedesktop/DBus\000\000\000\002\001s\000\024\000\000\000org.freedesktop.DBus\000\000\000\000\006\001s\000\024\000\000\000org.freedesktop.DBus\000\000\000\000\b\001g\000\001s\000\000\003\001s\000\f\000\000\000GetNameOwner\000\000\000\000\a\000\000\000:1.3558\000\000\000/org/freedesktop/DBus\000\000\000\002\001s\000\024\000\000\000org.freedesktop.DBus\000\000\000\000\006\001s\000\024\000\000\000org.freedesktop.DBus\000\000\000\000\b\001g\000\001s\000\000\003\001s\000\f\000\000\000GetNameOwner\000\000\000\000\a\000\000\000:1.3520\000l-stages\" access=\"read\"/>\n    <property type=\"s\" name=\"scan-type\" access=\"read\"/>\n  </interface>\n</node>\n\000    <arg type=\"s\" name=\"interface_name\" direction=\"in\"/>\n      <arg type=\"s\" name=\"property_name\" direction=\"in\"/>\n      <arg type=\"v\" name=\"value\" direction=\"in\"/>\n    </method>\n    <signal name=\"PropertiesChanged\">\n      <arg type=\"s\" name=\"interface_name\"/>\n      <arg type=\"a{sv}\" name=\"changed_properties\"/>\n      <arg type=\"as\" name=\"invalidated_properties\"/>\n    </signal>\n  </interface>\n  <interface name=\"org.freedesktop.DBus.Introspectable\">\n    <method name=\"Introspect\">\n      <arg type=\"s\" name=\"xml_data\" direction=\"out\"/>\n    </method>\n  </interface>\n  <interface name=\"org.freedesktop.DBus.Peer\">\n    <method name=\"Ping\"/>\n    <method name=\"GetMachineId\">\n      <arg type=\"s\" name=\"machine_uuid\" direction=\"out\"/>\n    </method>\n  </interface>\n  <interface name=\"net.reactivated.Fprint.Device\">\n    <method name=\"ListEnrolledFingers\">\n      <arg type=\"s\" name=\"username\" direction=\"in\"/>\n      <arg type=\"as\" name=\"enrolled_fingers\" direction=\"out\"/>\n    </method>\n    <method name=\"DeleteEnrolledFingers\">\n      <arg type=\"s\" name=\"username\" direction=\"in\"/>\n    </method>\n    <method name=\"DeleteEnrolledFingers2\"/>\n    <method name=\"Claim\">\n      <arg type=\"s\" name=\"username\" direction=\"in\"/>\n    </method>\n    <method name=\"Release\"/>\n    <method name=\"VerifyStart\">\n      <arg type=\"s\" name=\"finger_name\" direction=\"in\"/>\n    </method>\n"

Happy to throw over the coredump, but unfortunately it is a custom build of dbus-broker that I had added some extra debugging printing into …

[dvdhrm]

Thanks a lot for the many details! I have a suspicion, and I already pushed out a PR to try to fix this. I have not tested it, yet, so I will report back when done.

[dvdhrm]

I think this is fixed with 697882a. Feel free to re-open this, in case it is not!

Thanks a lot for the detailed report!

[benzea]

Thanks a lot! That was a pretty quick turn around :)