Bug 198453 - bluez generates spurious DBUS messages, causing unexpected syslog events
Summary: bluez generates spurious DBUS messages, causing unexpected syslog events
Status: NEW
Alias: None
Product: Drivers
Classification: Unclassified
Component: Bluetooth (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: linux-bluetooth@vger.kernel.org
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-01-11 21:20 UTC by faminebadger
Modified: 2018-02-09 14:50 UTC (History)
2 users (show)

See Also:
Kernel Version: 4.14.12
Subsystem:
Regression: No
Bisected commit-id:


Attachments
Fix replying to messages marked with NOREPLY (1.79 KB, patch)
2018-01-28 17:21 UTC, Luiz Von Dentz
Details | Diff

Description faminebadger 2018-01-11 21:20:53 UTC
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".
Comment 1 faminebadger 2018-01-11 21:22:47 UTC
> Note, once again, both process_message (stack frame #4) and
> g_dbus_pending_property_success (stack frame #4)

Should read:

> Note, once again, both process_message (stack frame #4) and
> g_dbus_pending_property_success (stack frame #0)

Sorry!
Comment 2 faminebadger 2018-01-28 01:32:17 UTC
Seems nobody is interested in this, despite the effort I put in to track down the source of the problem.
Comment 3 Luiz Von Dentz 2018-01-28 17:21:12 UTC
Created attachment 273905 [details]
Fix replying to messages marked with NOREPLY
Comment 4 Luiz Von Dentz 2018-01-30 18:05:28 UTC
Any chance to get the above patch tested?
Comment 5 faminebadger 2018-02-02 00:32:16 UTC
Sure, I can try it out - I just need to remove my temporary logcheck rule and build with the patch.

I'll try and do it this weekend.
Comment 6 faminebadger 2018-02-07 18:27:33 UTC
Yes, this prevents the error on my system.  It's fine for a patch for now - but I also think that the question I raised regarding the apparently two contradictory designs that both exist in the code should be considered.

Note You need to log in before you can comment on or make changes to this bug.