Title: Queue double-advance after natural end of track - next track is loaded then immediately abandoned, every second track skipped (Qobuz)
ENVIRONMENT
Volumio 4.119, Raspberry Pi 4 Model B Rev 1.4, MPD 0.24.6, USB DAC (Topping D10s), Qobuz plugin, wired LAN. Standard Qobuz album queue (16/44.1), no shuffle, no repeat.
SYMPTOM
When a track finishes playing naturally, the next track in the queue is resolved and loaded, then abandoned within about 1 second, and playback jumps to the track after it. The result is that every second track in the queue is silently skipped. Observed repeatedly across one evening (queue positions 1 and 3 skipped in one session; positions 9 and 11 in an earlier session, same signature). Manually tapping the skipped track in the queue plays it perfectly, so the track, the Qobuz stream and the audio chain are all fine - only the automatic end-of-track handoff fails.
WHAT THE LOGS SHOW (journalctl, volumio service)
The next track’s stream URL is resolved and added to MPD successfully. MPD then reports a “stop” state (the natural end of the previous track). CoreStateMachine::syncState receives stateService=stop while currentStatus=play, runs “play index undefined”, and advances the queue a second time - past the track it just loaded.
Trace 1 (23:54:29 - position 1 skipped after position 0 finished):
23:54:29 ControllerMpd::sendMpdCommand add “https://streaming-qobuz-std.akamaized.net/file?...eid=20793726…”
23:54:29 STATE SERVICE {“status”:“stop”,“position”:null,“seek”:null,…}
23:54:29 CURRENT POSITION 1
23:54:29 CoreStateMachine::syncState stateService stop
23:54:29 CoreStateMachine::syncState currentStatus play
23:54:29 CoreStateMachine::play index undefined
23:54:29 CorePlayQueue::getTrack 2
23:54:29 ControllerQobuz::clearAddPlayTrack ← now loading position 2 instead
23:54:30 ControllerMpd::sendMpdCommand stop / clear / load+add eid=20793727 / play
23:54:31 STATE SERVICE {“status”:“play”,“position”:0,…} CURRENT POSITION 2
Trace 2 (23:59:13 - position 3 skipped after position 2 finished, identical sequence):
23:59:13 ControllerMpd::sendMpdCommand add “https://…eid=20793728…”
23:59:13 STATE SERVICE {“status”:“stop”,…} CURRENT POSITION 3
23:59:13 CoreStateMachine::syncState stateService stop
23:59:13 CoreStateMachine::syncState currentStatus play
23:59:13 CoreStateMachine::play index undefined
23:59:13 ControllerQobuz::clearAddPlayTrack ← loads position 4
23:59:14 STATE SERVICE {“status”:“play”,“position”:0,“duration”:231,…} CURRENT POSITION 4
RULED OUT
- The track itself: the same tracks play in full when selected manually from the queue, and one of them (eid 20793726) played in full earlier the same evening through the same automatic handoff.
- USB/DAC: an xhci_hcd “Transfer event for disabled endpoint” kernel message fires at every track handoff including all successful ones - chronic transition noise, not correlated with the skips.
- mpd.log shows “exception: No such playlist” once or twice at every transition, successful or not - also uncorrelated.
INTERPRETATION
This looks like a race in the end-of-track handoff: the “previous track ended” stop event is processed after the next track has already been queued, and the state machine treats the stop as belonging to the newly loaded track (“play index undefined”), advancing again. Timing-dependent, which would explain intermittent reports.
REPRODUCIBILITY
The pattern was predicted in advance and the next occurrence was observed on schedule: with position 4 playing, we predicted position 5 would be loaded and abandoned at the natural end of track - at 00:03:06 position 5 started, at 00:03:10 it was abandoned (4 seconds) and position 6 began playing. Three occurrences captured in one session (positions 1, 3, 5), each with the identical log signature.
SURVIVES FULL POWER CYCLE
After a complete shutdown overnight and cold boot the next morning (7+ minutes uptime, all services freshly started, library and mounts intact), the very first natural end-of-track handoff reproduced the bug identically: position 0 finished, position 1 (the same eid 20793726) was resolved and added to MPD, the stop/play state mismatch fired “play index undefined”, and playback jumped to position 2. Log signature byte-for-byte identical to the previous evening’s traces (Aug 09 11:43:49). This rules out accumulated state and confirms the race is structural.
LOG UPLOAD (sent from the /dev page seconds after an occurrence): http://logs.volumio.org/volumio/wPmaVug.html
Device UID: aa1480b30ceac8c9f2374c671111d5eb
Additional occurrences after the report above was written: the alternating pattern continued this morning - positions 1, 3, 5 and 7 of the same queue were each skipped at natural end-of-track (7 confirmed skips across two days and a full power cycle).