Delay on shutdown of simple-asha

thewierdnut commented 3 months ago

When testing e303de8 on the asha-support branch, I run simple-asha, and I hear audio just fine. After hitting Ctrl-C, it waits for about 20 seconds or so before apparently timing out and quitting with this exception:

$ python3 test/simple-asha 9C:9C:1D:96:2F:5E ~/Music/song.opus 
Looking up ASHA object /org/bluez/hci0/dev_9C_9C_1D_96_2F_5E/asha
Looking up endpoint properties for /org/bluez/hci0/dev_9C_9C_1D_96_2F_5E/asha
Trying to acquire /org/bluez/hci0/dev_9C_9C_1D_96_2F_5E/asha/fd0
Setting initial volume to 32
Acquiring transport
Starting playback, hit Ctrl-C to stop
^CGot interrupt
Traceback (most recent call last):
  File "/home/rian/git/bluez/test/simple-asha", line 164, in <module>
    transport.Release()
  File "/usr/lib/python3/dist-packages/dbus/proxies.py", line 141, in __call__
    return self._connection.call_blocking(self._named_service,
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/dbus/connection.py", line 634, in call_blocking
    reply_message = self.send_message_with_reply_and_block(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
dbus.exceptions.DBusException: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

I can see the ACP stop command being sent, but it is not followed by an AudioStatus notification as expected. This may be behavior specific to my starkey hearing aids.

Here are the bluetoothd logs and btmon captures: shutdown_delay.zip

Of note:

Packet 1102: The AudioStatus CCC is used to subscribe to notification events.
Packet 1349: The AudioControlPoint Start command is sent
Packet 1353: The AudioStatus notification is sent in response to the ACP start
Packet 3501 is where the AudioControlPoint stop command was sent.
I do not see the expected AudioStatus notification in response to the AudioControlPoint stop
Packet 3515 is where it apparently gave up and shut down the connection.

thewierdnut commented 3 months ago

When playback starts, the android implementation sets a playback_started flag, and then clears it when playback is stopped. When it sends AudioControlPoint messages, it sets a command_acked flag to false, and then sets it to true when it gets the AudioStatus notification.

When it receives audio, it checks that both command_acked and playback_started are true. If they are not, then it just drops the audio. This means that when shutting down, it sets playback_started and command_acked to false, but it never ends up checking command_acked for anything.

This doesn't match the behavior as specified in the spec, but hearing device manufacturers will have tested against the android code, so I would trust it better than the spec.

thewierdnut commented 3 months ago

I suspect that you won't be able to drive your state machine using the status notifications. Instead, you should be able to use it to determine if the audio device is ready to receive data after the AudioControlPoint start has been sent.

shermp commented 3 months ago

As a reference point. I think I saw that my Oticon More did send an AudioStatus notification on stop.

thewierdnut commented 3 months ago

I've gotten my (unrelated) asha implementation working using the suggested design.

https://github.com/thewierdnut/asha_pipewire_sink

asymptotic-io / bluez

Delay on shutdown of simple-asha #1