Seek and playback errors

[Esbylion]

I've been having new issues with playing certain files through Squeezeclient. It appears to be specific FLAC files that have trouble. I only encounter this problem when using local playback on Squeezeclient, they work fine through other LMS (and non-LMS) players.

The easiest way to recreate the issue is to seek through one of the files in question. Playback starts just fine, but seeking through the song at all results in a 'Problem: Can't open file' error. This error can also occur after several minutes of uninterrupted playback, without seeking, but I am not able to recreate that as consistently.

Here is the logcat output from when the error occurs.

01-29 12:09:03.485  9186  9186 D SlimprotoSocket: Read command packet: Success(StreamStop)
01-29 12:09:03.485  9186  9186 D LocalPlayer: Playback state change 3 -> 1
01-29 12:09:03.487  9186 10905 D MediaCodec: keep callback message for reclaim
01-29 12:09:03.487  9186 32387 I CCodecConfig: query failed after returning 9 values (BAD_INDEX)
01-29 12:09:03.488  9186 32387 W Codec2Client: query -- param skipped: index = 1342179345.
01-29 12:09:03.488  9186 32387 W Codec2Client: query -- param skipped: index = 2415921170.
01-29 12:09:03.488  9186 32387 D CCodecBufferChannel: [c2.android.flac.decoder#215] start: updating output delay 0
01-29 12:09:03.488  3004  3004 I MediaPlayerList: updateMediaForAudioPlayback: Active player is playing, drop it
01-29 12:09:03.489  9186 32387 D CCodecBufferChannel: [c2.android.flac.decoder#215] MediaCodec discarded an unknown buffer
01-29 12:09:03.489  9186 32387 D CCodecBufferChannel: [c2.android.flac.decoder#215] MediaCodec discarded an unknown buffer
01-29 12:09:03.489  9186 32387 D CCodecBufferChannel: [c2.android.flac.decoder#215] MediaCodec discarded an unknown buffer
01-29 12:09:03.489  9186 32387 D CCodecBufferChannel: [c2.android.flac.decoder#215] MediaCodec discarded an unknown buffer
01-29 12:09:03.490  9186 32387 I hw-BpHwBinder: onLastStrongRef automatically unlinking death recipients
01-29 12:09:03.490  9186  9186 D SlimprotoSocket: Sending STMf status (uptime 10h 48m 13.945548184s, position 0s)
01-29 12:09:03.490  9186  9186 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
01-29 12:09:03.491  9186  9186 D SlimprotoSocket: Read command packet: Success(AudioGain(digitalVolume=true, preamp=255, left=0.1015625, right=0.1015625))
01-29 12:09:03.491  1854 15361 I hw-BpHwBinder: onLastStrongRef automatically unlinking death recipients
01-29 12:09:03.492  1854 15361 I hw-BpHwBinder: onLastStrongRef automatically unlinking death recipients
01-29 12:09:03.492  9186  9186 D SlimprotoSocket: Read command packet: Success(StreamStart(uri=http://192.168.42.10:9000/stream.mp3?player=9e:33:9d:52:87:af, method=GET, headers={}, autoStart=true, directStreaming=false, mimeType=audio/flac, replayGain=1.0))
01-29 12:09:03.492  9186  9186 D SlimprotoSocket: Sending STMc status (uptime 10h 48m 13.947927455s, position 0s)
01-29 12:09:03.492  9186  9186 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
01-29 12:09:03.493  1854 15361 D BufferPoolAccessor2.0: bufferpool2 0xb4000073ec2ba6e8 : 0(0 size) total buffers - 0(0 size) used buffers - 0/0 (recycle/alloc) - 0/0 (fetch/transfer)
01-29 12:09:03.493  1854 15361 D BufferPoolAccessor2.0: Destruction - bufferpool2 0xb4000073ec2ba6e8 cached: 0/0M, 0/0% in use; allocs: 0, 0% recycled; transfers: 0, 0% unfetched
01-29 12:09:03.494  9186  9186 D LocalPlayer: Playback state change 1 -> 2
01-29 12:09:03.495  9186  9186 D SlimprotoSocket: Read command packet: Success(AudioGain(digitalVolume=true, preamp=255, left=0.1015625, right=0.1015625))
01-29 12:09:03.506  9186  9186 D SlimprotoSocket: Sending RESP packet (537 bytes payload)
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal: Playback error
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:   x1.k: Source error
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:       at x1.f0.t(r8-map-id-7904d4a5ea84ab9eb40139435f9d9a5a256c68654640ce704f9378d71d2e13ee:17)
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:       at x1.f0.handleMessage(r8-map-id-7904d4a5ea84ab9eb40139435f9d9a5a256c68654640ce704f9378d71d2e13ee:483)
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:       at android.os.Handler.dispatchMessage(Handler.java:103)
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:       at android.os.Looper.loopOnce(Looper.java:232)
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:       at android.os.Looper.loop(Looper.java:317)
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:       at android.os.HandlerThread.run(HandlerThread.java:85)
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:   Caused by: e2.t1: None of the available extractors (c, d, b, d, m, q, b, y, d, c0, f, d, a, c, b, t, a, a, a, b, a) could read the stream. {contentIsMalformed=false, dataType=1}
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:   sniff failures: [NoDeclaredBrand, NoDeclaredBrand]
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:       at a0.c.z(r8-map-id-7904d4a5ea84ab9eb40139435f9d9a5a256c68654640ce704f9378d71d2e13ee:215)
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:       at e2.w0.a(r8-map-id-7904d4a5ea84ab9eb40139435f9d9a5a256c68654640ce704f9378d71d2e13ee:192)
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:       at h2.k.run(r8-map-id-7904d4a5ea84ab9eb40139435f9d9a5a256c68654640ce704f9378d71d2e13ee:35)
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1154)
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:652)
01-29 12:09:03.547  9186 10905 E ExoPlayerImplInternal:       at java.lang.Thread.run(Thread.java:1563)
01-29 12:09:03.548  9186  9186 D LocalPlayer: Playback state change 2 -> 1
01-29 12:09:03.548  9186  9186 D SlimprotoSocket: Sending STMn status (uptime 10h 48m 14.003359590s, position 0s)
01-29 12:09:03.548  9186  9186 D SlimprotoSocket: Sending STAT packet (53 bytes payload)
01-29 12:09:03.576  9186  9186 D SlimprotoSocket: Read command packet: Success(StreamStop)

And here is the error from the server log
[26-01-29 01:09:03.6241] Slim::Player::Squeezebox2::statHandler (156) Error: 9e:33:9d:52:87:af: Decoder does not support file format, code 0

[LaurentVitalis]

Same here.
If you ever find a way to fix this, I would be SUPER interested to know how.
I ported your code to Android Automotive OS and have the same problem (obviously).

[maniac103]

Root cause obviously is ExoPlayer not liking the stream: e2.t1: None of the available extractors (c, d, b, d, m, q, b, y, d, c0, f, d, a, c, b, t, a, a, a, b, a) could read the stream. {contentIsMalformed=false, dataType=1} (I'll disable obfuscation in the next release to make the stack traces more clear). Due to that error we send STMn (format unsupported) to the server, which in turn causes the quoted server error message.
Why ExoPlayer chokes here isn't clear to me, but I don't really have deep knowledge about ExoPlayers internal workings either :-/

[LaurentVitalis]

What I did found was that when playing a track normally, the header starts with 66 4C 61 43 (fLaC).
When seeking in the same track, the header was FF F8 C9 1C CE A3 B0 4E EA DC FA EC EF E1 EC, not fLaC !
ExoPlayer was unable to recognize the header start, especially since the mime-type was audio/x-flac.
I'm trying to understand what's happening. (transcoding ?)

[LaurentVitalis]

Well, it appears FF F8 C9 1C CE A3 B0 4E EA DC FA EC EF E1 EC is the start of a FLAC audio frame.
When seeking, LMS does not re-send all the track header for nothing.
ExoPlayer is not able to deal with that.
I'll investigate further.