[Pkg-utopia-maintainers] Bug#898158: dbus-python: FTBFS on armhf 6% of the time: reply to org.freedesktop.DBus.Binding.Tests.Trigger didn't arrive

[Simon McVittie]

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