Source: dbus-python
Version: 1.2.8-1
Severity: serious
Justification: fails to build from source (but built successfully in the past)
Build-time tests for dbus-python 1.2.8-1 failed on the armhf buildd. I
re-ran the tests 100 times in a loop on the armhf porterbox 'harris'
and they failed 6 times (2 for Python 2 and 4 for Python 3).
>From the log, we can see that there is a race condition: the client exits
before the server sent the expected response to its actions:
INFO:cross-test-client:Binding signal handler for Triggered
INFO:cross-test-client:method/signal: Triggering signal
INFO:cross-test-server:method/signal: client wants me to emit
Triggered(dbus.UInt64(42L)) from dbus.UTF8String('/Where/Ever')
INFO:cross-test-client:method/signal: Trigger() returned
INFO:cross-test-client:signal/callback: Emitting signal to trigger callback
INFO:cross-test-server:signal/callback: Triggered by client (:1.3:/Test):
(dbus.UInt16(42),dbus.Double(23.0))
INFO:cross-test-client:signal/callback: Emitting signal returned
INFO:cross-test-client:signal/callback: Response received
(dbus.UInt16(42),dbus.Double(23.0))
ERROR:cross-test-client:report 1: reply to
org.freedesktop.DBus.Binding.Tests.Trigger didn't arrive
INFO:cross-test-client:asking server to Exit
INFO:cross-test-server:signal/callback: Sent Response
INFO:cross-test-server:client wants me to Exit
INFO:cross-test-server:will quit when idle
INFO:cross-test-client:server says it will exit
INFO:cross-test-client:main loop exited.
INFO:cross-test-server:method/signal: Emitting Triggered(dbus.UInt64(42L)) from
dbus.UTF8String('/Where/Ever')
INFO:cross-test-server:method/signal: Emitted Triggered
INFO:cross-test-server:main loop exited.
dbus-daemon[16779]: [session uid=2912 pid=16779] Reloaded configuration
dbus-daemon[16779]: [session uid=2912 pid=16779] Reloaded configuration
org.freedesktop.DBus.Binding.Tests.Trigger fail 1
The failing test is part of an interface intended to be an
interoperability test between D-Bus language bindings (I think only
dbus-python and dbus-java ever actually implemented it), so the confusing
names unfortunately can't be changed.
* client logs "method/signal: Triggering signal"
* record that a response to Tests.Trigger is expected
* client calls Tests.Trigger() method on server, asynchronously
* server implements Tests.Trigger() as follows:
- log "method/signal: client wants me to emit Triggered(%r) from %r"
- record that Tests.Trigger() was tested
- send back a successful reply to the client, which causes this:
+ client logs "method/signal: Trigger() returned
+ client logs "signal/callback: Emitting signal to trigger callback"
+ client emits signal SignalTests.Trigger(42, 23)
+ client logs "signal/callback: Emitting signal returned"
- next time the server returns to its main loop:
+ log "method/signal: Emitting Triggered(%r) from %r"
+ create an object at the given object path
+ emit SignalTests.Triggered signal from it
+ log "method/signal: Emitted Triggered"
* client responds to SignalTests.Triggered as follows:
- log "method/signal: Triggered(%r) by %r"
- record that a response to Tests.Trigger was received
- do some checks on the parameters
- log "Tests.Trigger pass"
* server responds to SignalTests.Trigger as follows:
- log "signal/callback: Triggered by client (%s:%s): (%r,%r)"
- record that SignalTests.Trigger was tested
- call CallbackTests.Response() method on the client, blocking for a
reply
- log "signal/callback: Sent Response"
* client implements CallbackTests.Response() as follows:
- log "signal/callback: Response received (%r,%r)"
- record that a response to SignalTests.Trigger was received
- check the parameters
- log "SignalTests.Trigger pass"
- check that every expected reply has arrived
- call Tests.Exit() on the server, asynchronously
+ on success, log "server says it will exit" and quit the main loop
+ 1 second later, quit the main loop anyway
There is a race condition here between these chains of events, which as
far as I can tell has existed for at least 10 years:
* server receives Tests.Trigger() and schedules SignalTests.Triggered
* server returns to main loop
* server emits SignalTests.Triggered
* client receives SignalTests.Triggered
and
* server receives Tests.Trigger() and replies with success
* client receives success and emits SignalTests.Trigger
* server receives SignalTests.Trigger and calls CallbackTests.Response()
* client receives CallbackTests.Response() and calls Tests.Exit()
* server receives Tests.Exit() and replies with success
* client quits its main loop
Solution: don't reply to Tests.Trigger() until after the
SignalTests.Triggered signal has been sent. Because the client called
Tests.Trigger() asynchronously, messages are not re-ordered and the reply
arrives after the signal, so the whole chain of events leading up to
"client receives SignalTests.Triggered" happens before
"client receives success and emits SignalTests.Trigger".
smcv
