Jukebox mode: Ultrasonic can fail to send 'start' action; possible race condition
Problem description
I am helping to test the recent implementation of Jukebox mode in Navidrome, currently still under development. See here and here.
I've discovered an issue when testing with Ultrasonic that I'm fairly sure (but not certain) shows an issue with Ultrasonic.
The issue concerns starting playback with an empty queue. Usually this fails. The direct cause is that (as revealed with Wireshark) the start
command is never sent to Navidrome. Ultrasonic does however start polling the Jukebox for a change in status, and if playback is started manually via a different method (e.g. just sending the start command manually with curl), Ultrasonic picks this up and begins to work - including letting you play, pause, and select new songs.
Steps to reproduce
If you want to test the precise thing I'm testing, you will need a build of Navidrome from the latest master branch with these changes applied on top.
- Check that jukebox mode is enabled. Clear the queue in Ultrasonic. Enable logging in Ultrasonic, force stop it, and stop Navidrome. Start both. Double check that the queue is cleared.
- Try to play a song in Ultrasonic.
Please provide a log!
I will link the log below but it appears to be useless. What turned out to be way more useful is a combination of Wireshark and adb logcat. Whenever playback fails, I see the following output in logcat:
10-12 14:13:33.344 23818 23818 W MCImplBase: Controller isn't allowed to call command= 2
10-12 14:13:33.344 23818 23818 W MCImplBase: Controller isn't allowed to call command= 10
10-12 14:13:33.344 23818 23818 W MCImplBase: Controller isn't allowed to call command= 2
10-12 14:13:33.344 23818 23818 W MCImplBase: Controller isn't allowed to call command= 1
The player appears to be failing on the play and pause commands (1 and 2). This is correlated with what I notice from Wireshark - that Ultrasonic fails to send the start
command.
I wasn't able to work out the internal logic of Ultrasonic with a quick look, but this could easily be the source of the problem. Ultrasonic "wants" to send the start command (call play?), but Android says it isn't allowed to. Maybe this is because Android thinks the playback queue is empty?
In any case, Ultrasonic ends up stuck in this state. It needs to send the start
command but won't allow itself to do that. You get similar controller warnings in this state if you try to press the play button.
Sending the start
command manually seems to bypass the issue, because (as long as polling is occurring!) it convinces the controller that the play and pause operations are available. Once fixed, playback is usually stable, but clearing the queue sometimes (but not always?) breaks it again.
Log: ultrasonic.log
System information
Ultrasonic client
- Ultrasonic version: 4.7.1-fdroid
- Android version: 12
- Device info: Samsung Galaxy S10e
Server
- Server name: Navidrome
- Server version: latest vcs + patch
- Protocol used: http
Additional notes
Happy to provide any additional information that would help narrow this down further.