search

michaelherger / librespot

Open Source Spotify client library
MIT License
16 stars 7 forks source link

LMS + Spotty plays a few seconds of a song, then skip to the next one #5

Open EmmanuelP opened 1 year ago

EmmanuelP commented 1 year ago

Using spotty from logitech media server, randomly, the system starts to behave incorrectly, playing only the first seconds of a song then skip to the next one. It happens with most of the songs, but sometimes a song is played to the end. Then it goes nuts again, or works fine for a while, it depends.

Looking at the processes, there is a lot of zombie spotty processes. I don't know if it is related though...

819      1120558  0.0  0.0      0     0 ?        Z    07:42   0:00 [spotty-x86_64] <defunct>
819      1120563  0.0  0.0      0     0 ?        Z    07:42   0:00 [spotty-x86_64] <defunct>
...
And hundreds more lines like these

I did not find anything relevant in the LMS logs.

Logitech media server 8.2.0 1627922070 running in a podman container on a fedora 35 OS Plugin version Spotty v4.8.3 helper spotty v1.3.0 - using librespot 0.4.1 c5b689f (Built on 2022-06-04, Build ID: NGB9GMS0, Profile: release)

michaelherger commented 1 year ago

Hmm... interesting. Because earlier this week my LMS system (a Raspberry Pi) "died" as it run out of storage (it's running off of a 16GB SD card). The syslog was full with hundreds of thousands of lines coming from Spotty. Something I had never seen before and still don't understand where it came from. Could you please check your syslog, too? See whether there would be a ton of spotty related logging going on?

Are you saying that you saw all those zombie processes? Could they have been one process per track skipped?

EmmanuelP commented 1 year ago

Hmm... interesting. Because earlier this week my LMS system (a Raspberry Pi) "died" as it run out of storage (it's running off of a 16GB SD card). The syslog was full with hundreds of thousands of lines coming from Spotty. Something I had never seen before and still don't understand where it came from. Could you please check your syslog, too? See whether there would be a ton of spotty related logging going on?

I have not seen anything related to spotty in the container logs.

Are you saying that you saw all those zombie processes? Could they have been one process per track skipped?

It seems so.

EmmanuelP commented 1 year ago

It seems so.

I have just checked again, and finally it seems the number of defunct is not related to the number of skipped songs. I'm playing some music for 1 hour or so, without any skipping issue, and I already have a bunch of defunct spotty processes.

stiefenm commented 4 months ago

I'm also using spotty from LMS and experiencing the same issue for years - but ONLY WITH SPOTIFY CONNECT. Sometimes it's gone for weeks, sometimes it gets really bad. Songs are playing for about 5 seconds, then are skipped to the next one and so on. Interesting thing to note: Songs that ones have been skipped, keep broken, even if I clear the android application's cache and the cache directories of spotty-hf - /var/lib/squeezeboxserver/cache/spotty/ in my installation.

According to the logs I suspect the helper app generating a "next song" event for any reason: [24-03-27 12:37:52.9651] Plugins::Spotty::Connect::ANON (414) Current Connect state: [24-03-27 12:37:52.9659] Plugins::Spotty::Connect::ANON (437) Got a new track to be played: spotify:track:1WGFr0kwmeUZ1vDwPXry1r [24-03-27 12:37:53.4327] Plugins::Spotty::Connect::ANON (414) Current Connect state: [24-03-27 12:37:59.7438] Plugins::Spotty::Connect::ANON (414) Current Connect state: [24-03-27 12:37:59.7443] Plugins::Spotty::Connect::ANON (427) Got a change event, but actually this is a play next track event [24-03-27 12:37:59.7448] Plugins::Spotty::Connect::ANON (437) Got a new track to be played: spotify:track:7ituvlPAZokpX2CSaCtR3B

Full log attached

I'd like to debug the helper app's behaviour more - but I don't know how. Any suggestions?

Logitech Media Server Version: 8.5.0 - 1710422688 @ Thu 14 Mar 2024 03:09:10 PM CET Spotty Plugin: v4.10.0 Helper: spotty v1.3.0 - using librespot 0.4.1 UNKNOWN (Built on 2022-06-04, Build ID: 0HDT7ABt, Profile: release)

spotty.txt

michaelherger commented 4 months ago

Would you have multiple players/apps trying to stream at the same moment?

stiefenm commented 4 months ago

I can pretty much rule that out. Only the app on my mobile phone.

stiefenm commented 3 months ago

@michaelherger I would be grateful for any ideas on how to debug this issue. Here are my findings so far:

michaelherger commented 3 months ago

Connect with Spotty is known to be unstable (unfortunately). But I have no clue why this would apply even more to specific tracks, because the actual playback would be the same, whether you play through Connect or Spotty directly. You aren't using squeezelite based players with a particularly big buffer, are you?

stiefenm commented 3 months ago

Regarding the buffers: I'm running squeezelite with default settings, only name, mac and output device specified - so this should not be the case.

Regarding further analyses: As far as I can see, the spotty-hf helper application is getting a change/next track event on all the affected tracks. My idea is, to debug the helper application, to find out what is the root cause of this event.

But I'm unsure how to accomplish that. I'm not aware of verbose debug option and how to set them, since the helper is started by the plugin at runtime.

michaelherger commented 3 months ago

I've mentioned before that Connect mode was fragile. Getting premature change track events just sounds like some of that. But then this wouldn't be limited to newly released music.

stiefenm commented 3 months ago

I finally found time to debug Connect.pm. The unexpected change (next track) event definitely comes from the helper daemon 3s after song start. I managed to compile a debug release of the spotty helper (librespot) in v1.3.1. Unfortunately I cannot get this release being run as Daemon - maybe caused by it's size, maybe some other reason: Plugins::Spotty::Connect::DaemonManager::checkAPIConnectPlayers (210) Connect daemon is running, but not connected - shutting down to force restart:

But I can run it from shell using the cached credentials from the cache directory and play songs to LMS. And I can observe the following Warning: [2024-04-22T14:03:23Z WARN librespot_playback::player] Skipping to next track, unable to get next packet for track <SpotifyId { id: 91059572173932678270438855222659849237, audio_type: Track }>: LewtonDecoder("Ogg decode problem")

It is interesting that this is always the case 3s after the end of preloading the next track: [2024-04-22T14:03:20Z DEBUG librespot_audio::fetch] File 8ef6b330617b5208532e40a9766405c80711664f complete, saving to cache

Before you ask me about network problems, bear in mind that it's always the same list of somehow "poisoned" songs and that the problem is not reproducible with "good" tracks but with "poisoned" ones. And last but not least: All songs can be played via Spotty (LMS my apps) without any problems.

michaelherger commented 3 months ago

There's been some feedback recently about new songs which come with video(?). I don't know exactly what this is about. But the reporter mentioned that some new tracks would play as videos, and trying to stream them to Spotty would fail playback. Is this something you could confirm?

stiefenm commented 3 months ago

Promising idea, but this does not seem to be the root cause.

There are songs with video and without affected. Same goes for songs with canvas (the 30sec clips that are part of spotify for years) and without. Even songs with video play fine, as long as I keep the video view switched off in the spotify app.

stiefenm commented 3 months ago

Seems that I found a workaround / solution:

I've build a current dev release (spotty 1.3.99) AND activated IPv6 on my PI. Both measures led to a stable playback of all the songs, that didn't work before.

I can only guess about the root cause, but it seems like some of the regional spotify access points and also the fallback access point can not be handled stable anymore with IPv4 only.

My impression is that 1.3.99 is handling the selection of access points different then 1.3.0 and it is using IPv6 for at least the https connections to spotify.

I'll give you a status update if the situation keeps stable.

michaelherger commented 3 months ago

What branch are you building from?

stiefenm commented 3 months ago

spotty-dev git clone -b spotty-dev --single-branch https://github.com/michaelherger/librespot.git

mr-manuel commented 2 months ago

I can report a similiar issue. Some new songs are skipped without reason, when selected in the Spotify app and played over Spotify Connect. Selecting the song directly in the Spotty app in LMS it works fine. Unfortunately I have no IPv6 connection to test it.