Home of the Squeezebox™ & Transporter® network music players.
Page 1 of 2 12 LastLast
Results 1 to 10 of 14
  1. #1
    Senior Member
    Join Date
    Dec 2010
    Posts
    138

    Spotty - 'stalled' stream

    Running Spotty 4.2.0 on LMS Version: 8.0.0 - 1593258969 I've noticed occasionally the stream appears to 'stall' at the end of a song.

    I tend to play via the Spotify Genre's/Mood links.

    The stream will play multiple songs successfully, but then I just notice the music/stream has stalled at the end of a song (still with multiple songs appearing in the current playlist)

    The player web interface and Boom screen still show the song as playing but it's at 100% complete (eg. remaining duration is 0) and the indicator is still showing playing.

    If I click next-track (either on web or physical Boom remote) the stream continues.

    I see nothing in the error level log, but I'll set Spotty level to debug and see if I see anything.

    But, I'm not sure if it's a network issue on my side, and Spotify stream issue, or a Plug-in issue.

    I was just asking if anyone else has experienced similar stalls at the end of songs?

    Cheers.

  2. #2
    Senior Member
    Join Date
    Dec 2010
    Posts
    138
    Just happened again. Logging didn't show any errors

    Code:
    [20-07-13 18:08:17.9257] Plugins::Spotty::ProtocolHandler::getMetadataFor (181) Returning metadata cached in song object for spotify://track:03ZQhvP0UXQvUhGxlGqOSq
    [20-07-13 18:08:17.9267] Plugins::Spotty::ProtocolHandler::getMetadataFor (182) {
      album => "Do You Love Me Lately?",
      artist => "Emily Keener",
      bitrate => "320k VBR",
      cover => "https://i.scdn.co/image/ab67616d0000b2737d68b1fd4c25c7288ff965f9",
      duration => "236.408",
      icon => "/html/images/cover.png",
      originalType => "Ogg Vorbis (Spotify)",
      originaltype => "Ogg Vorbis (Spotify)",
      title => "Do You Love Me Lately?",
      type => "Ogg Vorbis (Spotify)",
      url => "spotify://track:03ZQhvP0UXQvUhGxlGqOSq",
    }
    [20-07-13 18:08:17.9281] Plugins::Spotty::ProtocolHandler::getMetadataFor (181) Returning metadata cached in song object for spotify://track:03ZQhvP0UXQvUhGxlGqOSq
    [20-07-13 18:08:17.9291] Plugins::Spotty::ProtocolHandler::getMetadataFor (182) {
      album => "Do You Love Me Lately?",
      artist => "Emily Keener",
      bitrate => "320k VBR",
      cover => "https://i.scdn.co/image/ab67616d0000b2737d68b1fd4c25c7288ff965f9",
      duration => "236.408",
      icon => "/html/images/cover.png",
      originalType => "Ogg Vorbis (Spotify)",
      originaltype => "Ogg Vorbis (Spotify)",
      title => "Do You Love Me Lately?",
      type => "Ogg Vorbis (Spotify)",
      url => "spotify://track:03ZQhvP0UXQvUhGxlGqOSq",
    }
    The Material and Standard Web interface showing it still 'playing' but stalled at the end of track 45 out of 64. (This was on a Duet Receiver, so no Boom interface this time)

    Name:  material.jpg
Views: 306
Size:  116.3 KB

    Name:  desktop.jpg
Views: 303
Size:  125.2 KB

    Pressing 'next track' continues play with next song (46 out of 64)

  3. #3
    Junior Member
    Join Date
    Nov 2010
    Posts
    10
    I also have experienced this. Yesterday after playing a playlist with 300+ songs it stops after song no 79 ("What A Man"). I thought it may be related with the cache purge.

    I found this just before the
    [20-10-18 22:56:38.0386] Plugins::Spotty::AccountHelper:urgeAudioCacheAfterXTracks (230) Played 14 song(s) since last audio cache purge.
    [20-10-18 22:56:38.0811] Plugins::Spotty::ProtocolHandler::getMetadataFor (201) Found cached metadata for spotify:track:6lFmtdoWhYyD5A8uPRUEZE
    [20-10-18 22:56:38.0828] Plugins::Spotty::ProtocolHandler::getMetadataFor (202) {
    album => "What A Man",
    artist => "The Grand East",
    cover => "https://i.scdn.co/image/ab67616d0000b27363a87ffd3fee9c6f42d08bad",
    duration => "258.805",
    title => "What A Man",
    }

    Just a long shot.

  4. #4
    Junior Member
    Join Date
    Feb 2012
    Posts
    10
    I have a similar issue - either that will happen, or the playback will just skip onto the next track in the middle of the track.

    Where did you find the setting to increase the logging level on Spotty? There's nothing in the server log I can see when this happens and I can't see a setting.

    (Running LMS 8.0 with Spotty 4.4.0)

  5. #5
    Junior Member
    Join Date
    Nov 2010
    Posts
    10
    I can reproduce the situation for that particular song. Even if I only select that song (in the Spotify playlist).
    Running on piCore - NL - utf8, LMS 8.0.0 - 1602486506, Spotty 4.4.0, Squeezebox receiver, Squeezebox Touch
    Last edited by jepege; 2020-10-20 at 01:43.

  6. #6
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    20,530

    Spotty - 'stalled' stream

    > I also have experienced this. Yesterday after playing a playlist with
    > 300+ songs it stops after song no 79 ("What A Man"). I thought it may be
    > related with the cache purge.


    Interesting hint! I thought I had delayed the cleanup enough to not
    block initial track buffering. But who knows?

    > Plugins::Spotty::AccountHelper:urgeAudioCacheAfterXTracks (230) Played
    > 14 song(s) since last audio cache purge.


    Ok, but that's just the counter. The actual cleanup would only be
    triggered after 15 tracks.

    But anyway, please keep watching out. Any help would be welcome!
    --

    Michael

  7. #7
    Junior Member
    Join Date
    Nov 2010
    Posts
    10
    If you need some debug information, let me know which logging should be set on debug level.

  8. #8
    Junior Member
    Join Date
    Nov 2010
    Posts
    10
    I've tested this a little further with some debug levels on.
    I've selected the song "What A Man" and moved to 10 seconds before the end.
    As before at the end of the song the music stopped. In the server.log I've found some interesting lines.

    The stream for the next song couldn't be opened and herafter a stack dump. I hope this will help to trace the error.

    [20-10-23 09:52:08.9627] Slim::Player::StreamingController::_playersMessage (796) Probleem: Kan bestand niet openen voor:: spotify:track:63rTTYYRQUMK2JZIJ6pwXz
    [20-10-23 09:52:08.9699] Slim::Player::StreamingController::_eventAction (272) 00:04:20:16:fb:64: StreamingFailed in PLAYING-STREAMING -> Slim::Player::StreamingController::_SyncStopNext
    [20-10-23 09:52:08.9703] Slim::Player::StreamingController::_eventAction (283) params: errorDisconnect => undef
    [20-10-23 09:52:08.9706] Slim::Player::StreamingController::_setStreamingSt ate (2386) new streaming state IDLE
    [20-10-23 09:52:08.9711] Slim::Player::StreamingController::_willRetry (1408) no retry data
    [20-10-23 09:52:08.9715] Slim::Player::StreamingController::nextsong (889) The next song is number 79, was 78
    [20-10-23 09:52:08.9733] Slim::Player::StreamingController::_setStreamingSt ate (2386) new streaming state TRACKWAIT
    [20-10-23 09:52:08.9739] Slim::Player::StreamingController::_nextTrackReady (744) 00:04:20:16:fb:64: nextTrack will be index 79
    [20-10-23 09:52:08.9741] Slim::Player::StreamingController::_eventAction (272) 00:04:20:16:fb:64: NextTrackReady in PLAYING-TRACKWAIT -> Slim::Player::StreamingController::_StreamIfReady
    [20-10-23 09:52:08.9744] Slim::Player::StreamingController::_eventAction (302) 00:04:20:16:fb:64: StreamingFailed - new state PLAYING-TRACKWAIT
    [20-10-23 09:52:09.0188] Slim::Player::StreamingController::_eventAction (272) 00:04:20:16:fb:64: StatusHeartbeat in PLAYING-TRACKWAIT -> Slim::Player::StreamingController::_CheckSync
    [20-10-23 09:52:09.0205] Slim::Player::StreamingController::_eventAction (272) 00:04:20:16:fb:64: StatusHeartbeat in PLAYING-TRACKWAIT -> Slim::Player::StreamingController::_CheckSync
    [20-10-23 09:52:09.3825] Slim::Player::StreamingController:layerEndOfStream (2286) 00:04:20:16:fb:64
    [20-10-23 09:52:09.3832] Slim::Player::StreamingController::_eventAction (272) 00:04:20:16:fb:64: EndOfStream in PLAYING-TRACKWAIT -> Slim::Player::StreamingController::_Invalid
    [20-10-23 09:52:09.3838] Slim::Player::StreamingController::_Invalid (326) 00:04:20:16:fb:64: event EndOfStream received while in invalid state PLAYING-TRACKWAIT
    [20-10-23 09:52:09.3844] Slim::Player::StreamingController::_Invalid (327) Error:
    [20-10-23 09:52:09.3854] Slim::Player::StreamingController::_Invalid (327) Backtrace:

    frame 0: Slim::Utils::Log::logBacktrace (/usr/local/slimserver/Slim/Player/StreamingController.pm line 327)
    frame 1: Slim::Player::StreamingController::_Invalid (/usr/local/slimserver/Slim/Player/StreamingController.pm line 287)
    frame 2: Slim::Player::StreamingController::_eventAction (/usr/local/slimserver/Slim/Player/StreamingController.pm line 2292)
    frame 3: Slim::Player::StreamingController:layerEndOfStream (/usr/local/slimserver/Slim/Player/Squeezebox2.pm line 144)
    frame 4: Slim::Player::Squeezebox2::statHandler (/usr/local/slimserver/Slim/Networking/Slimproto.pm line 652)
    frame 5: Slim::Networking::Slimproto::_disco_handler (/usr/local/slimserver/Slim/Networking/Slimproto.pm line 401)
    frame 6: Slim::Networking::Slimproto::client_readable (/usr/local/slimserver/Slim/Networking/IO/Select.pm line 122)
    frame 7: (eval) (/usr/local/slimserver/Slim/Networking/IO/Select.pm line 118)
    frame 8: Slim::Networking::IO::Select::__ANON__ (/usr/local/slimserver/Slim/Networking/IO/Select.pm line 167)
    frame 9: (eval) (/usr/local/slimserver/Slim/Networking/IO/Select.pm line 167)
    frame 10: Slim::Networking::IO::Select::loop (/usr/local/slimserver/slimserver.pl line 728)
    frame 11: main::idle (/usr/local/slimserver/slimserver.pl line 678)
    frame 12: main::main (/usr/local/slimserver/slimserver.pl line 1211)


    JP

  9. #9
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    20,530

    Spotty - 'stalled' stream

    > Slim::Player::StreamingController::_playersMessage (796) Probleem: Kan
    > bestand niet openen voor:: spotify:track:63rTTYYRQUMK2JZIJ6pwXz


    Interesting: this track would indeed not play ("Komodo" by "JF
    Sebastien"). But spotty would skip right over it here.

    I'll see why it's even showing up, as non playable items should not be
    shown in Spotty.

    --

    Michael

  10. #10
    Junior Member
    Join Date
    Nov 2010
    Posts
    10
    Quote Originally Posted by mherger View Post
    > Slim::Player::StreamingController::_playersMessage (796) Probleem: Kan
    > bestand niet openen voor:: spotify:track:63rTTYYRQUMK2JZIJ6pwXz


    Interesting: this track would indeed not play ("Komodo" by "JF
    Sebastien"). But spotty would skip right over it here.

    I'll see why it's even showing up, as non playable items should not be
    shown in Spotty.

    --

    Michael
    Spotty never checks if a song is playable. In this case the song is not playable due to market restrictions.
    I have made a fix in the code of API/Sync.pm to solve this issue:


    sub playlistTrackIDs {
    my ($self, $id, $getFullData) = @_;

    my $offset = 0;
    my $tracks;

    do {
    my $params = {
    market => 'from_token',
    offset => $offset,
    limit => SPOTIFY_PLAYLIST_TRACKS_LIMIT,
    };

    $params->{fields} = 'next,items(track(uri,restrictions))' if !$getFullData;

    my $response = $self->_call("playlists/$id/tracks", $params);

    $offset = 0;

    if ( $response && $response->{items} && ref $response->{items} ) {
    push @$tracks, map {
    $libraryCache->normalize($_->{track}) if $getFullData;
    $_->{track}->{uri};
    } grep {
    $_->{track} && ref $_->{track} && $_->{track}->{uri} && $_->{track}->{uri} =~ /^spotifyepisode|track):/ && !$_->{track}->{restrictions}
    } @{$response->{items}};
    ($offset) = $response->{'next'} =~ /offset=(\d+)/;
    }
    } while $offset && $offset < SPOTIFY_MAX_LIMIT;

    return $tracks;
    }

    JP

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •