--passthrough: OGG Begin Of Stream missing when playing the same song twice.

[poettig]

Hi,

first of all, thanks for providing this and implementing OGG passthrough recently!
While using it, I had some problems when playing the same song twice (play a song via Player API /play, wait for it to end, then send the same PUT request again) - the ogg begin of stream marker is missing.

Because of that, ffmpeg says "invalid data found" or "codec missing" on the second play. Weirdly enough, ffplay can still play both. If I redirect the ogg stream to a file and play that with ffplay, there are CRC errors appearing on the second play and there is some stuttering.
VLC plays the first one, then skips the second one.

If I play two different songs, everything works fine.

Output of librespot for the same song twice:

[2021-02-25T19:58:28Z INFO  librespot] librespot da0e913 (2021-02-23). Built on 2021-02-24. Build ID: q2qv0LQM
[2021-02-25T19:58:28Z WARN  libmdns::fsm] error sending packet Os { code: 99, kind: AddrNotAvailable, message: "Cannot assign requested address" }
[2021-02-25T19:58:28Z INFO  librespot_core::session] Connecting to AP "gew1-accesspoint-e-fsf3.ap.spotify.com:4070"
[2021-02-25T19:58:29Z INFO  librespot_core::session] Authenticated as "<redacted>" !
[2021-02-25T19:58:29Z INFO  librespot_core::session] Country: "DE"
[2021-02-25T19:58:32Z INFO  librespot_playback::player] Loading <Fertilizer> with Spotify URI <spotify:track:6jypaMkKsoc5npsVzxhksl>
[2021-02-25T19:58:33Z INFO  librespot_audio::passthrough_decoder] Starting passthrough track with serial 3670377013
[2021-02-25T19:58:33Z INFO  librespot_playback::player] <Fertilizer> (39640 ms) loaded
[2021-02-25T19:58:33Z INFO  librespot_audio::passthrough_decoder] end of streaming
[2021-02-25T19:58:33Z INFO  librespot_audio::passthrough_decoder] Seeking to 0
[2021-02-25T19:58:39Z INFO  librespot_audio::passthrough_decoder] end of streaming
[2021-02-25T19:58:39Z INFO  librespot_audio::passthrough_decoder] Seeking to 0

Output of librespot for different songs:

[2021-02-25T19:53:12Z INFO  librespot] librespot da0e913 (2021-02-23). Built on 2021-02-24. Build ID: q2qv0LQM
[2021-02-25T19:53:12Z WARN  libmdns::fsm] error sending packet Os { code: 99, kind: AddrNotAvailable, message: "Cannot assign requested address" }
[2021-02-25T19:53:12Z INFO  librespot_core::session] Connecting to AP "gew1-accesspoint-e-wkt5.ap.spotify.com:4070"
[2021-02-25T19:53:12Z INFO  librespot_core::session] Authenticated as "<redacted>" !
[2021-02-25T19:53:12Z INFO  librespot_core::session] Country: "DE"
[2021-02-25T19:53:17Z INFO  librespot_playback::player] Loading <raindrops (an angel cried)> with Spotify URI <spotify:track:0v2LUO8oTHnkjQ8MmKuXyk>
[2021-02-25T19:53:17Z INFO  librespot_audio::passthrough_decoder] Starting passthrough track with serial 3670061710
[2021-02-25T19:53:17Z INFO  librespot_playback::player] <raindrops (an angel cried)> (37640 ms) loaded
[2021-02-25T19:53:18Z INFO  librespot_audio::passthrough_decoder] end of streaming
[2021-02-25T19:53:18Z INFO  librespot_audio::passthrough_decoder] Seeking to 0
[2021-02-25T19:53:43Z INFO  librespot_playback::player] Loading <Fertilizer> with Spotify URI <spotify:track:6jypaMkKsoc5npsVzxhksl>
[2021-02-25T19:53:43Z INFO  librespot_audio::passthrough_decoder] Starting passthrough track with serial 3670087673
[2021-02-25T19:53:43Z INFO  librespot_playback::player] <Fertilizer> (39640 ms) loaded
[2021-02-25T19:53:44Z INFO  librespot_audio::passthrough_decoder] end of streaming
[2021-02-25T19:53:44Z INFO  librespot_audio::passthrough_decoder] Seeking to 0

Proof that the OggS BOS is missing:

bgrep -x 4f6767530002 /tmp/tworunsdifferent.ogg 
0000000: 4f67 6753 0002                           OggS..
013f73d: 4f67 6753 0002                           OggS..
bgrep -x 4f6767530002 /tmp/tworunssame.ogg 
0000000: 4f67 6753 0002                           OggS..

librespot command line:

/librespot --initial-volume 100 --enable-volume-normalisation --normalisation-gain-type track -n test --disable-audio-cache --bitrate 320 --backend pipe --passthrough

Everything was run on the most recent dev commit.

[Johannesd3]

cc @philippe44

[philippe44]

Having only one BOS is on purpose: when you seek within a track, it is all concatenated in the same stream. Only when you move to another track is a new stream started. So, re-playing the same track falls under that former category. Now, it should not fail and I will investigate why.

Having said that, I can change the logic so that every seek starts a new stream, so the same track would be cut into multiple streams everytime the user seeks into it. It does not really matter to me, not sure one is more logical than the other.

Opinions?

[philippe44]

So, I've made another version that treats puts every seek segment in a different stream. You're probably right, it is more user friendly at least you see all the segments clearly separated in the resulting file.

You can have a look here https://github.com/philippe44/librespot/tree/passthrough-update and tell me what you think

[poettig]

Sorry for not getting back on your call for opinions, I could not find the time to answer.

First of all, your explanation makes sense, I did not realize that playing the same song twice in a row actually just leads to seeking back to 0 instead of starting a new stream.
Thanks for implementing a second version which starts a new stream for seeks - I can confirm that it works and I now have two OggS BOS on your branch when replaying the same song, but only one on the dev branch. Getting back to the alleged problems that ffplay had on the second run, I can say that I must have messed something up here. My Re-Test with the dev branch version showed no such problems anymore, both your branch and the dev branch played no problem this time.

In further comparison, I tried what happens when recording 2 replays of the same song to a file with both implementations, then playing those files with VLC.

• Your version: When seeking from the first half of the file into the second one, it fails to do so and just seeks ahead a few seconds in the first half. If I seek back from the second half into the first one, it also fails with "ogg stream serial mismatch". I guess that makes sense as the two Ogg streams probably have different identifiers.
• Dev Branch version: There are no problems seeking between both halves of the recording, sometimes it stutters a bitter directly after the seek.

This could be a point for NOT starting a new stream every seek.

However, I first noticed this problem while trying to read the Ogg streams from librespot via another program. For a clean start per song, I tried to scan along the librespot output until I found the next Ogg BOS marker - which ultimately failed every time when replaying a song because there was no BOS mark. This might be a reason to use the new version.

When just instantly playing the the librespot output with ffplay and seeking in the spotify web client, everything works very nicely - with both versions.

In the end, I can't say whats the right call here. It feels more expectable to me that a skip in play would lead to a "new stream", but there also seem be some problems caused by it (see the vlc problem on the recording). My knowledge about audio codecs is very, very superficial and the thing I experimented with still does not work correctly when there is a new Ogg BOS on song start when playing different songs. So this might not even be the root cause and it is more likely that I'm doing something wrong.

[philippe44]

Thanks - I've tried with VLC and it seems to struggle a bit with Ogg that contain multiple streams I think. It shows a single track with the concatenated duration, but you can't skip beyond the file that is currently played. You can skip close to its end, let VLC move to the next one and only then you can seek within this next one. I'm not sure exactly what's happening here, but I think this is VLC.

I feel that I should stick with new version that has a stream per seek, as said above, it looks better for user and it's more simple code as well.

[philippe44]

The only thing that is not fully clean now is the "skip" issue where I cannot set a "EoS" flag for the last packet because decoders don't know that it will be the last one. The only non-hacky option I can think of would be for the player to tell the decoder that it is about to destroy it and accept a "last packet" (maybe a last_packet() method).

Now I don't know where to put that exactly. As said before, I've made several mistakes in this PR because I've spent way too much of my limited time (and capabilities :-)) on "how" versus "what" because I'm trying to learn Rust. That's interesting but not easy at all and it has dramatically increased my design error rate.

Still, now that I've made modifications in all backends for better integration, maybe implementing that last_packet could be a good (and clean) idea. Perhaps, @sashahilton00 @plietar you could give me a hint where the "last gasp" could be implemented.

[Johannesd3]

Is it solved by #664?

[poettig]

It is, I'll close the issue :) Thanks again!