Bug 198453

I get this sort of message regularly in my logcheck reports:

> Jan 11 20:32:04 gentoo dbus-daemon[2520]: [system] Rejected send message, 0
> matched rules; type="method_return", sender=":1.34" (uid=0 pid=27198
> comm="/var/tmp/portage/net-wireless/bluez-5.47-r1/work/b")
> interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0"
> destination=":1.35" (uid=1000 pid=27229 comm="python3.5 ")

Which is DBUS rejecting a bluetoothd response to a request from a user application (blueman-applet in my case).

This python snippet reproduces it:

> Python 3.5.4 (default, Jan  6 2018, 03:17:39) 
> [GCC 7.2.0] on linux
> Type "help", "copyright", "credits" or "license" for more information.
> >>> from blueman.bluez.Manager import Manager
> >>> mgr=Manager()
> >>> adpt=mgr.get_adapters()
> >>> print(adpt[0].get("Powered"))
> False
> >>> adpt[0].set("Powered", False)

That last line results in the error being sent to the syslog.

I debugged it a little, and I have come to the conclusion that this is because bluetoothd is generating a DBUS message response even when one has not been requested (i.e. the NO_REPLY flag) - and so DBUS policy blocks the message and raises the error.

It seems that, somewhat strangely, there are two places in the bluez code that can generate a response message.  The first is object.c:process_message.  This function correctly checks the NO_REPLY flag (dbus_message_get_no_reply), and discards the prepared response if it is set.

However, following the code deeper, it seems the set operation itself - object.c:g_dbus_pending_property_success - can also directly send to the bus instead of returning a prepared message as would be expected given the behaviour of the above caller function -  eventual caller (process_message).

Here's the full call stack:
> #0  g_dbus_pending_property_success (id=id@entry=7) at gdbus/object.c:456
> #1  0x00005555555b28c6 in property_set_mode (adapter=0x555555850860,
> setting=setting@entry=1, value=<optimized out>, 
>     id=7) at src/adapter.c:2625
> #2  0x00005555555b2a96 in property_set_powered (property=<optimized out>,
> iter=<optimized out>, id=<optimized out>, 
>     user_data=<optimized out>) at src/adapter.c:2711
> #3  0x00005555555dce58 in properties_set (connection=0x555555847ac0,
> message=0x55555584eff0, user_data=<optimized out>)
>     at gdbus/object.c:922
> #4  0x00005555555dd226 in process_message (connection=0x555555847ac0,
> message=0x55555584eff0, 
>     method=0x555555833b68 <properties_methods+40>, iface_user_data=<optimized
>     out>) at gdbus/object.c:256
> #5  0x00005555555dd6b2 in generic_message (connection=0x555555847ac0,
> message=0x55555584eff0, user_data=<optimized out>)
>     at gdbus/object.c:1080
> #6  0x00007ffff789e953 in _dbus_object_tree_dispatch_and_unlock () from
> /usr/lib64/libdbus-1.so.3
> #7  0x00007ffff788ef0b in dbus_connection_dispatch () from
> /usr/lib64/libdbus-1.so.3
> #8  0x00005555555da1cd in message_dispatch (data=0x555555847ac0) at
> gdbus/mainloop.c:72
> #9  0x00007ffff7b10645 in g_main_context_dispatch () from
> /usr/lib64/libglib-2.0.so.0
> #10 0x00007ffff7b109e8 in g_main_context_iterate.isra () from
> /usr/lib64/libglib-2.0.so.0
> #11 0x00007ffff7b10cf2 in g_main_loop_run () from /usr/lib64/libglib-2.0.so.0
> #12 0x000055555559b60d in main (argc=<optimized out>, argv=<optimized out>)
> at src/main.c:781

Note, once again, both process_message (stack frame #4) and g_dbus_pending_property_success (stack frame #4) contain code to send a response to the message, but only the latter checks the NO_REPLY flag.

It seems to me that the code was designed for the methods called by process_message to return a response to the caller, not generate it themselves, and somewhere this idea has been broken.

I haven't checked whether there are any code paths that could generate a double message (that is, send one now as well as return one to caller), but if so this would also generate a DBUS error (as the second response would no longer be a "requested reply".