Playback did not resume after seek (synchronized playback)

[stsichler]

Hi,
I just had another issue: the playback did suddenly not resume after a seek operation.
The seek operation was caused by me on the squeezeclient, the playback was synced to my Radio.
Both devices did not resume, although the GUI still showed "playing back" state.

I can't reproduce, so it seems to be some race condition / timing issue, but fortunately, I have a adb logcat of this event:

11-18 19:08:50.675 16235 16235 D SlimprotoSocket: Read command packet: Success(StreamStop)
11-18 19:08:50.676 16235 16235 D LocalPlayer: Playback state change 3 -> 1
11-18 19:08:50.693 16235 16235 D SlimprotoSocket: Read command packet: Success(AudioGain(digitalVolume=true, preamp=255, newLeft=0.4765625, newRight=0.4765625))
11-18 19:08:50.696 16235 16235 D SlimprotoSocket: Sending STMf status (uptime 17m 5.264480990s, position 0s)
11-18 19:08:50.696 16235 16235 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
11-18 19:08:50.698 16235 16235 D SlimprotoSocket: Read command packet: Success(StreamStart(uri=http://192.168.1.40:9000/stream.mp3?player=dc:63:e9:8d:14:c9, method=GET, headers={}, autoStart=false, directStreaming=false, mimeType=audio/mpeg, replayGain=0.5))
11-18 19:08:50.698 16235 16235 D SlimprotoSocket: Sending STMc status (uptime 17m 5.267122344s, position 0s)
11-18 19:08:50.699 16235 16235 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
11-18 19:08:50.731 16235 16235 D LocalPlayer: Playback state change 1 -> 2
11-18 19:08:50.733 16235 16235 D SlimprotoSocket: Read command packet: Success(AudioGain(digitalVolume=true, preamp=255, newLeft=0.4765625, newRight=0.4765625))
11-18 19:08:50.752 16235 16235 D SlimprotoSocket: Sending RESP packet (539 bytes payload)
11-18 19:08:50.827 16235 16235 D LocalPlayer: Playback state change 2 -> 3
11-18 19:08:50.827 16235 16235 D SlimprotoSocket: Sending STMl status (uptime 17m 5.395910741s, position 0s)
11-18 19:08:50.827 16235 16235 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
11-18 19:08:50.952 16235 16235 D SlimprotoSocket: Read command packet: Success(StreamStatus(timestamp=0))
11-18 19:08:50.953 16235 16235 D SlimprotoSocket: Sending STMt status (uptime 17m 5.521372578s, position 0s)
11-18 19:08:50.953 16235 16235 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
11-18 19:08:51.329 16235 16235 D LocalPlaybackService: update notification with state PlayingOrPaused(title=null, paused=true)
11-18 19:08:51.801 16235 16235 D SlimprotoSocket: Sending META packet (26 bytes payload)
11-18 19:08:52.325 16235 16235 D LocalPlaybackService: update notification with state PlayingOrPaused(title=It s No Good, paused=true)
11-18 19:08:55.162 16235 16235 D SlimprotoSocket: Read command packet: Success(StreamStatus(timestamp=0))
11-18 19:08:55.164 16235 16235 D SlimprotoSocket: Sending STMt status (uptime 17m 9.731737213s, position 0s)
11-18 19:08:55.164 16235 16235 D SlimprotoSocket: Sending STAT packet (53 bytes payload)

The code is use was main HEAD of your repo.

[maniac103]

11-18 19:08:50.698 16235 16235 D SlimprotoSocket: Read command packet: Success(StreamStart(uri=http://192.168.1.40:9000/stream.mp3?player=dc:63:e9:8d:14:c9, method=GET, headers={}, autoStart=false, directStreaming=false, mimeType=audio/mpeg, replayGain=0.5))

Here it says the player should start buffering the stream, but pause initially (autoStart=false + directStreaming=false means $autostart=0 in Slimproto terms)

Afterwards there's no strm-u command (for unpausing), so from the log it's expected that playback didn't start. If the radio didn't unpause either it seems like the server didn't send the command (as opposed to the client losing it), so this would need debugging on the server side.

[stsichler]

Hm.... Strange. I just saw something similar:
After adding Log commands in the StreamUnpause handling, it seems the server sometimes sends strange unpause times.
This may be the reason for this issue:

           (...)
           val unpauseDelay = command.unpauseTimestamp - uptime
            if (unpauseDelay.isPositive()) {
                Log.d(TAG, "Delaying unpause for ${unpauseDelay.inWholeMilliseconds} ms")
                delay(unpauseDelay)
            }
            sentBufferReady = true
            Log.d(TAG, "Unpausing at ${(System.nanoTime() - startupTimestampNanos)
                .toDuration(DurationUnit.NANOSECONDS).inWholeMilliseconds} ms")
           (...)

11-23 23:22:27.960  9482  9482 D SlimprotoSocket: Read command packet: Success(StreamStop)
11-23 23:22:28.405  9482  9482 D SlimprotoSocket: Read command packet: Success(AudioGain(digitalVolume=true, preamp=255, newLeft=0.1015625, newRight=0.1015625))
11-23 23:22:28.407  9482  9482 D SlimprotoSocket: Read command packet: Success(StreamStart(uri=http://192.168.1.40:9000/stream.mp3?player=dc:63:e9:8d:14:c9, method=GET, headers={}, autoStart=false, directStreaming=false, mimeType=audio/mpeg, replayGain=0.62109375))
11-23 23:22:28.407  9482  9482 D SlimprotoSocket: Sending STMc status (uptime 8m 51.617609619s, position 0s)
11-23 23:22:28.408  9482  9482 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
11-23 23:22:28.411  9482  9482 D LocalPlayer: Playback state change 1 -> 2
11-23 23:22:28.413  9482  9482 D SlimprotoSocket: Read command packet: Success(AudioGain(digitalVolume=true, preamp=255, newLeft=0.1015625, newRight=0.1015625))
11-23 23:22:28.431  9482  9482 D SlimprotoSocket: Sending RESP packet (539 bytes payload)
11-23 23:22:28.507  9482  9482 D LocalPlayer: Playback state change 2 -> 3
11-23 23:22:28.507  9482  9482 D SlimprotoSocket: Sending STMl status (uptime 8m 51.717541192s, position 0s)
11-23 23:22:28.507  9482  9482 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
11-23 23:22:28.990  9482  9482 D SlimprotoSocket: Read command packet: Success(StreamUnpause(unpauseTimestamp=9m 1.579s))
11-23 23:22:28.990  9482  9482 D LocalPlaybackService: Delaying unpause for 9378 ms
11-23 23:22:29.009  9482  9482 D LocalPlaybackService: update notification with state PlayingOrPaused(title=null, paused=true)
11-23 23:22:29.553  9482  9482 D SlimprotoSocket: Sending META packet (27 bytes payload)
11-23 23:22:30.061  9482  9482 D LocalPlaybackService: update notification with state PlayingOrPaused(title=Forever Young, paused=true)
11-23 23:22:38.372  9482  9482 D LocalPlaybackService: Unpausing at 541582 ms
11-23 23:22:38.398  9482  9482 D SlimprotoSocket: Sending STMs status (uptime 9m 1.588007173s, position 0s)
11-23 23:22:38.398  9482  9482 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
11-23 23:22:38.401  9482  9482 D SlimprotoSocket: Sending STMr status (uptime 9m 1.611269468s, position 0s)
11-23 23:22:38.401  9482  9482 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
11-23 23:22:38.430  9482  9482 D SlimprotoSocket: Read command packet: Success(StreamStatus(timestamp=0))
11-23 23:22:38.431  9482  9482 D SlimprotoSocket: Sending STMt status (uptime 9m 1.641037805s, position 0s)
11-23 23:22:38.431  9482  9482 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
11-23 23:22:38.452  9482  9482 D SlimprotoSocket: Read command packet: Success(StreamStatus(timestamp=0))
11-23 23:22:38.452  9482  9482 D SlimprotoSocket: Sending STMt status (uptime 9m 1.662373639s, position 0s)
11-23 23:22:38.452  9482  9482 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
11-23 23:22:38.457  9482  9482 D SlimprotoSocket: Read command packet: Success(StreamStatus(timestamp=0))
11-23 23:22:38.457  9482  9482 D SlimprotoSocket: Sending STMt status (uptime 9m 1.667771401s, position 0s)
11-23 23:22:38.457  9482  9482 D SlimprotoSocket: Sending STAT packet (53 bytes payload)

But I still don't understand which circumstances lead to this. (unfortunately I don't have a server log of this event)