[GH-ISSUE #54] Last ~10 seconds of each track not played #43

Closed
opened 2026-02-27 19:28:30 +03:00 by kerem · 11 comments
Owner

Originally created by @sashahilton00 on GitHub (Jan 29, 2018).
Original GitHub issue: https://github.com/librespot-org/librespot/issues/54

Issue by jsopenrb
Tuesday Apr 18, 2017 at 16:59 GMT
Originally opened as https://github.com/plietar/librespot/issues/175


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.

Originally created by @sashahilton00 on GitHub (Jan 29, 2018). Original GitHub issue: https://github.com/librespot-org/librespot/issues/54 <a href="https://github.com/jsopenrb"><img src="https://avatars0.githubusercontent.com/u/19466116?v=4" align="left" width="96" height="96" hspace="10"></img></a> **Issue by [jsopenrb](https://github.com/jsopenrb)** _Tuesday Apr 18, 2017 at 16:59 GMT_ _Originally opened as https://github.com/plietar/librespot/issues/175_ ---- 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.
kerem 2026-02-27 19:28:30 +03:00
Author
Owner

@sashahilton00 commented on GitHub (Jan 29, 2018):

Comment by jsopenrb
Thursday Apr 20, 2017 at 11:10 GMT


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.

<!-- gh-comment-id:361262481 --> @sashahilton00 commented on GitHub (Jan 29, 2018): <a href="https://github.com/jsopenrb"><img src="https://avatars0.githubusercontent.com/u/19466116?v=4" align="left" width="48" height="48" hspace="10"></img></a> **Comment by [jsopenrb](https://github.com/jsopenrb)** _Thursday Apr 20, 2017 at 11:10 GMT_ ---- 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.
Author
Owner

@sashahilton00 commented on GitHub (Jan 29, 2018):

Comment by michaelherger
Friday May 12, 2017 at 05:29 GMT


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

<!-- gh-comment-id:361262502 --> @sashahilton00 commented on GitHub (Jan 29, 2018): <a href="https://github.com/michaelherger"><img src="https://avatars3.githubusercontent.com/u/2789989?v=4" align="left" width="48" height="48" hspace="10"></img></a> **Comment by [michaelherger](https://github.com/michaelherger)** _Friday May 12, 2017 at 05:29 GMT_ ---- @jsopenrb - have you found a solution to this issue?
Author
Owner

@sashahilton00 commented on GitHub (Jan 29, 2018):

Comment by jsopenrb
Friday May 12, 2017 at 06:21 GMT


@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.

<!-- gh-comment-id:361262522 --> @sashahilton00 commented on GitHub (Jan 29, 2018): <a href="https://github.com/jsopenrb"><img src="https://avatars0.githubusercontent.com/u/19466116?v=4" align="left" width="48" height="48" hspace="10"></img></a> **Comment by [jsopenrb](https://github.com/jsopenrb)** _Friday May 12, 2017 at 06:21 GMT_ ---- @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.
Author
Owner

@sashahilton00 commented on GitHub (Jan 29, 2018):

Comment by michaelherger
Friday May 12, 2017 at 07:13 GMT


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.

<!-- gh-comment-id:361262544 --> @sashahilton00 commented on GitHub (Jan 29, 2018): <a href="https://github.com/michaelherger"><img src="https://avatars3.githubusercontent.com/u/2789989?v=4" align="left" width="48" height="48" hspace="10"></img></a> **Comment by [michaelherger](https://github.com/michaelherger)** _Friday May 12, 2017 at 07:13 GMT_ ---- 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.
Author
Owner

@sashahilton00 commented on GitHub (Jan 29, 2018):

Comment by jsopenrb
Friday May 12, 2017 at 07:48 GMT


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.

<!-- gh-comment-id:361262574 --> @sashahilton00 commented on GitHub (Jan 29, 2018): <a href="https://github.com/jsopenrb"><img src="https://avatars0.githubusercontent.com/u/19466116?v=4" align="left" width="48" height="48" hspace="10"></img></a> **Comment by [jsopenrb](https://github.com/jsopenrb)** _Friday May 12, 2017 at 07:48 GMT_ ---- 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.
Author
Owner

@sashahilton00 commented on GitHub (Jan 29, 2018):

Comment by jsopenrb
Thursday May 25, 2017 at 07:16 GMT


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.

<!-- gh-comment-id:361262601 --> @sashahilton00 commented on GitHub (Jan 29, 2018): <a href="https://github.com/jsopenrb"><img src="https://avatars0.githubusercontent.com/u/19466116?v=4" align="left" width="48" height="48" hspace="10"></img></a> **Comment by [jsopenrb](https://github.com/jsopenrb)** _Thursday May 25, 2017 at 07:16 GMT_ ---- 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.
Author
Owner

@sashahilton00 commented on GitHub (Jan 29, 2018):

Comment by michaelherger
Tuesday Jun 13, 2017 at 10:14 GMT


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

<!-- gh-comment-id:361262624 --> @sashahilton00 commented on GitHub (Jan 29, 2018): <a href="https://github.com/michaelherger"><img src="https://avatars3.githubusercontent.com/u/2789989?v=4" align="left" width="48" height="48" hspace="10"></img></a> **Comment by [michaelherger](https://github.com/michaelherger)** _Tuesday Jun 13, 2017 at 10:14 GMT_ ---- @jsopenrb - did you adjust the buffer size in Alsa itself, or in librespot's Alsa backend?
Author
Owner

@sashahilton00 commented on GitHub (Jan 29, 2018):

Comment by jsopenrb
Tuesday Jun 13, 2017 at 11:10 GMT


@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.

<!-- gh-comment-id:361262660 --> @sashahilton00 commented on GitHub (Jan 29, 2018): <a href="https://github.com/jsopenrb"><img src="https://avatars0.githubusercontent.com/u/19466116?v=4" align="left" width="48" height="48" hspace="10"></img></a> **Comment by [jsopenrb](https://github.com/jsopenrb)** _Tuesday Jun 13, 2017 at 11:10 GMT_ ---- @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.
Author
Owner

@sashahilton00 commented on GitHub (Jan 29, 2018):

Comment by michaelherger
Thursday Jun 15, 2017 at 15:44 GMT


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?

<!-- gh-comment-id:361262693 --> @sashahilton00 commented on GitHub (Jan 29, 2018): <a href="https://github.com/michaelherger"><img src="https://avatars3.githubusercontent.com/u/2789989?v=4" align="left" width="48" height="48" hspace="10"></img></a> **Comment by [michaelherger](https://github.com/michaelherger)** _Thursday Jun 15, 2017 at 15:44 GMT_ ---- 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::spirc: kMessageTypePlay "iPhone 7" abc97b01bf1c3e20ea740135074490462057ea2e 22 0 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::spirc: kMessageTypePlay "iPhone 7" abc97b01bf1c3e20ea740135074490462057ea2e 24 0 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?
Author
Owner

@ComlOnline commented on GitHub (Jan 29, 2018):

@jsopenrb @michaelherger is this still an issue? Was any progress made?

<!-- gh-comment-id:361419630 --> @ComlOnline commented on GitHub (Jan 29, 2018): @jsopenrb @michaelherger is this still an issue? Was any progress made?
Author
Owner

@ComlOnline commented on GitHub (Feb 5, 2018):

As there are no other reports of this and there is no one with the bug to troubleshoot with, I'm closing this issue/ Feel free to open a new one if its still there.

<!-- gh-comment-id:363200273 --> @ComlOnline commented on GitHub (Feb 5, 2018): As there are no other reports of this and there is no one with the bug to troubleshoot with, I'm closing this issue/ Feel free to open a new one if its still there.
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
starred/librespot#43
No description provided.