Last ~10 seconds of each track not played

[jsopenrb]

Right before the end of each track, the controlling device is sending Load command which makes the player jump right to the next track without waiting for the current track to finish. This happens when controlling from both Android and Windows.

[jsopenrb]

Looks like the issue is caused by librespot sending Notify response without waiting for the track to Load. It is less noticable when the track is already cached.

[michaelherger]

@jsopenrb - have you found a solution to this issue?

[jsopenrb]

@michaelherger, no yet and I'm not sure where to look as well. I thought it might be caused by rpi3 not having an exact 44.1 clock, but for 5 minute track the time difference is less than 0.5 seconds. I need to check again, but I think this was working normally under x86 VM.

[michaelherger]

I think it depends on the backend, rather than the platform. My guess is that as soon as librespot has finished receiving a track, it tells the controller "done". Which triggers the controller to start playback of the next song.

Eg. I used the stdio backend to pipe all data to a file. It only takes about 10-15s to complete the download of a single track. Therefore the Spotify application would jumpt to the next track after only this duration. The effect is less obvious of course if you're using a backend with a smaller buffer. The file to which I've piped the output would have the full track, though.

[jsopenrb]

Yes, there's also an end_of_track event which notifies Spotify that track has finished playing, but in my case it's not triggered, the server sends Load command before end_of_track happens.

[jsopenrb]

From what I can tell from spirc communication - Windows client sends two notification events: one to ack the load command, another when loading is complete. I've added an additional track_loaded event, but I'm still not 100% sure that it is needed.

The thing that helped was to set custom period and buffer settings in Alsa backend setup (it also helped with massive lag of skip commands). This leads to requirement of a config file instead of command line options so backends and mixers can have their own specific configuration options.

[michaelherger]

@jsopenrb - did you adjust the buffer size in Alsa itself, or in librespot's Alsa backend?

[jsopenrb]

@michaelherger, I've made changes in alsa backend. It's not compatible with current librespot version as I'm using alsa-sys crate which has required functions to implement hardware volume control.

[michaelherger]

Ok, I've tried to better understand what is going on here. Here are two log snippets I collected. The first one is of a session where I let the tracks play without interaction:

DEBUG:librespot::player: command=Play
DEBUG:librespot::spirc: kMessageTypeNotify "spotty" 3a0adf3c1fe24cb49d181ffffb7327095371c9bd 17 1497540930365
DEBUG:librespot::player: command=Load(SpotifyId(u128 { high: 11853336379687193445, low: 13647316676641263930 }), true, 0)
INFO:librespot::player: Loading track "Slangpolska"
DEBUG:librespot::spirc: kMessageTypeNotify "spotty" 3a0adf3c1fe24cb49d181ffffb7327095371c9bd 18 1497540935777
DEBUG:librespot::audio_file: Downloading file 0045222a58a17ea0605a18937c43357fc589f5ef
INFO:librespot::player: Track "Slangpolska" loaded
DEBUG:librespot::player: command=Load(SpotifyId(u128 { high: 7394549753284087693, low: 11368811147055792677 }), true, 0)
DEBUG:librespot::spirc: kMessageTypeNotify "spotty" 3a0adf3c1fe24cb49d181ffffb7327095371c9bd 19 1497540943381
INFO:librespot::player: Loading track "Victa"
DEBUG:librespot::audio_file: Downloading file 7462498e02f0d32a7f269ef69a9c4829f07e0f07
INFO:librespot::player: Track "Victa" loaded
DEBUG:librespot::spirc: kMessageTypePause "iPhone 7" abc97b01bf1c3e20ea740135074490462057ea2e 23 0
DEBUG:librespot::player: command=Pause
DEBUG:librespot::spirc: kMessageTypeNotify "spotty" 3a0adf3c1fe24cb49d181ffffb7327095371c9bd 20 1497540950025

After the kMessageTypePlay message we'd get no other message from Spirc. Yet the player would switch to the next track as soon as the first one had been fully loaded. As I piped the output to /dev/null, this happened within seconds.

The second log is from when I pressed the Next button in the controlling Spotify app on my phone:

DEBUG:librespot::player: command=Play
DEBUG:librespot::spirc: kMessageTypeNotify "spotty" 3a0adf3c1fe24cb49d181ffffb7327095371c9bd 21 1497540956920
DEBUG:librespot::spirc: kMessageTypeNext "iPhone 7" abc97b01bf1c3e20ea740135074490462057ea2e 25 0
DEBUG:librespot::player: command=Load(SpotifyId(u128 { high: 3898055584147063188, low: 11468514843262420360 }), true, 0)
INFO:librespot::player: Loading track "The Little Ones"
DEBUG:librespot::spirc: kMessageTypeNotify "spotty" 3a0adf3c1fe24cb49d181ffffb7327095371c9bd 22 1497540960053
DEBUG:librespot::audio_file: Downloading file 4ce420f00b38d6c2ee532c1b9aadd4da64465721
INFO:librespot::player: Track "The Little Ones" loaded
DEBUG:librespot::spirc: kMessageTypeNext "iPhone 7" abc97b01bf1c3e20ea740135074490462057ea2e 26 0
DEBUG:librespot::player: command=Load(SpotifyId(u128 { high: 18381146370269790374, low: 11475003542592466878 }), true, 0)
INFO:librespot::player: Loading track "Bad Asses"
DEBUG:librespot::spirc: kMessageTypeNotify "spotty" 3a0adf3c1fe24cb49d181ffffb7327095371c9bd 23 1497540971646
DEBUG:librespot::audio_file: Downloading file d2f267b3e41b83ce766a6dba8dded8ee1d9f4501
INFO:librespot::player: Track "Bad Asses" loaded
DEBUG:librespot::spirc: kMessageTypePause "iPhone 7" abc97b01bf1c3e20ea740135074490462057ea2e 27 0
DEBUG:librespot::player: command=Pause
DEBUG:librespot::spirc: kMessageTypeNotify "spotty" 3a0adf3c1fe24cb49d181ffffb7327095371c9bd 24 1497540972884

Now this one's different. We would get a kMessageTypeNext message before the player loads the new track. In this case it's ok that the player does stop playback of the currently playing track, and start playback of the new one.

I was wondering whether it would be possible to modify the player to only end playback if there had been a spirc event. Otherwise just let the track end before starting playback of the new one?