In synchronized playback, Title displayed no longer switches to next track

[stsichler]

Hi,
while I'm still debugging sync/seeking issues, I just noticed that the title that is displayed does not switch to the next track when a track is played to the end and the player should move on to the next item.
The audio played back is the next title, but the track displayed does not switch to the next item.
I was playing back synchronized with my Radio. Note that also the track display of the Radio did not switch to the next track.

I think that this might be related to your change 8e348d1, but I still have to verify that.

EDIT: I'd guess that there is missing some "I'm finished with that track" message from squeezeclient.

[maniac103]

The track title is parsed from the stream contents, so the DSCO change is unrelated. How long did you wait for the title to update? I've seen delays up to 1 minute, but didn't debug that further yet.

Edit: I assume by 'displayed' you're referring to the local player notification?

[stsichler]

Hm, I surely didn't wait any longer than 10-15 seconds and then assumed that it won't change anymore.

I assume by 'displayed' you're referring to the local player notification?

Both the album art displayed and the track title displayed did not update after the track change, on both the Squeezeclient and the SB Radio(!).

[maniac103]

Both the album art displayed and the track title displayed did not update after the track change, on both the Squeezeclient and the SB Radio(!).

So you mean the now playing screen? That's indeed unexpected, I'll check this.

[maniac103]

I can't reproduce that, neither in unsynced mode, nor if SqueezeClient is the sync master, nor if it's the sync slave.
Can you reproduce that reliably? If so,

• Does it also happen in unsynced mode? If so, we should use that for debugging to reduce complexity. If not, does it happen when using SC as master, as slave or both?
• Please provide a server log of such a case with network.protocol.slimproto, player.source, player.streaming, player.playlist, player.sync set to debug

[stsichler]

I now have a server-log.txt from such event.
Synced playback was about to move from 3rd track (Nobody's Home) to 4th track (Everlasting Pictures) of playlist, but "Playing Screen" remained at Nobody's Home.
(note: I did not set network.protocol.slimproto to debug, because of the large amount of output)

[stsichler]

Note: I most often see this when starting a track playback synchronized to a Radio, then seek to some point before the track end and then let the playback continue past the track end to the next track.

[maniac103]

The log does look OK:

• the Radio has already finished loading the stream (and thus sent DSCO), which caused the play state to become STREAMOUT
• the Radio now finishes decoding (and sends STMd), which causes the transition to IDLE
• then the new track is loaded, but can't be played yet, because SqueezeClient hasn't yet sent STMd (as we can't distinguish decoding from playback, as it's abstracted away from us) -> thus play state becomes TRACKWAIT
• SqueezeClient sends STMd -> server loads new track and starts playing it -> play state becomes STREAMING

Question is now why no player status update is sent. I guess I'll have to dig into how this actually works. The gist of it is

• the client (Jive on the Radio, or SqueezeClient) subscribes to updates for a specific CLI command (here: the status command)
• the server memorizes that subscription (see Slim::Control::Request::subscribe) and enqueues a callback (which causes a cometd event) once the result of the command changes

The latter is even documented as such in the docs of the command: When enabled, the status request is automatically re-generated on player change (and sent asynchronously to the CLI client). ... I just haven't found the implementation of that mechanism yet.

[maniac103]

OK, it's this call, which then causes the status query to be reexecuted, because Slim::Control::Queries::statusQuery_filter lets playlist newsong pass.

If you enable control.commands debug logging in addition to the other log levels mentioned above, the server log should look somewhat like this:

[25-11-27 14:04:20.2839] Slim::Player::StreamingController::_Playing (367) Song 12 has now started playing
[25-11-27 14:04:20.2839] Slim::Buttons::Playlist::jump (375) Jumping to song index: 12
[25-11-27 14:04:20.2840] Slim::Control::Request::notifyFromArray (842) (playlist newsong So hard (2023 Remaster) 12)
[25-11-27 14:04:20.2841] Slim::Player::StreamingController::_Playing (396) Song queue is now 12
[25-11-27 14:04:20.2841] Slim::Control::Request::notify (2009) Notifying playlist newsong
[25-11-27 14:04:20.2842] Slim::Control::Request::notify (2047) Notifying Slim::Plugin::RandomPlay::Plugin::commandCallback of playlist newsong =~ [['playlist']['newsong','delete','clear','loadtracks','playtracks','load','play','loadalbum','playalbum']]
[25-11-27 14:04:20.2842] Slim::Control::Request::notify (2047) Notifying Slim::Player::Playlist::modifyPlaylistCallback of playlist newsong =~ [['playlist']]
[25-11-27 14:04:20.2843] Slim::Player::Playlist::modifyPlaylistCallback (1116) Checking if persistPlaylists is set..
[25-11-27 14:04:20.2843] Slim::Player::Playlist::modifyPlaylistCallback (1140) saveCurrentSong not set. Returning.
[25-11-27 14:04:20.2844] Slim::Control::Request::notify (2047) Notifying Slim::Buttons::Playlist::knobPlaylistCallback of playlist newsong =~ [['playlist']]
[25-11-27 14:04:20.2844] Slim::Control::Request::notify (2047) Notifying Slim::Plugin::DontStopTheMusic::Plugin::onPlaylistChange of playlist newsong =~ [['playlist']['cant_open','newsong','delete','resume']]
[25-11-27 14:04:20.5891] Slim::Control::Request::__autoexecute (2470) __autoexecute()
[25-11-27 14:04:20.5891] Slim::Control::Request::dump (2335) Request: Query [e7:61:8d:29:17:c1->status] from /bc849e76/slim/playerstatus/e7618d2917c1|12||bc849e76|Squeezer-squeezer/1.0  (Dispatchable)
[25-11-27 14:04:20.5891] Slim::Control::Request::dump (2339)    Param: [useContextMenu] = [1]
[25-11-27 14:04:20.5892] Slim::Control::Request::dump (2339)    Param: [_quantity] = [1]
[25-11-27 14:04:20.5892] Slim::Control::Request::dump (2339)    Param: [menu] = [menu]
[25-11-27 14:04:20.5892] Slim::Control::Request::dump (2339)    Param: [subscribe] = [0]
[25-11-27 14:04:20.5893] Slim::Control::Request::dump (2339)    Param: [_index] = [-]
[25-11-27 14:04:20.5897] Slim::Control::Request::registerAutoExecute (2121) registerAutoExecute()
[25-11-27 14:04:20.5897] Slim::Control::Request::registerAutoExecute (2149) Old friend: bc849e76 - status - e7:61:8d:29:17:c1
[25-11-27 14:04:20.5898] Slim::Control::Request::registerAutoExecute (2169) .. set ourself up
[25-11-27 14:04:20.5898] Slim::Control::Request::dump (2335) Request: Query [e7:61:8d:29:17:c1->status] from /bc849e76/slim/playerstatus/e7618d2917c1|12||bc849e76|Squeezer-squeezer/1.0  (Done)
[25-11-27 14:04:20.5898] Slim::Control::Request::dump (2339)    Param: [useContextMenu] = [1]
[25-11-27 14:04:20.5899] Slim::Control::Request::dump (2339)    Param: [_quantity] = [1]
[25-11-27 14:04:20.5899] Slim::Control::Request::dump (2339)    Param: [menu] = [menu]
[25-11-27 14:04:20.5899] Slim::Control::Request::dump (2339)    Param: [subscribe] = [0]
[25-11-27 14:04:20.5900] Slim::Control::Request::dump (2339)    Param: [_index] = [-]
[25-11-27 14:04:20.5901] Slim::Control::Request::dump (2371)    Result: [preset_data] = [[{}, {}, {}, {}, {}, {}, {}, {}, {}, {}]]
[25-11-27 14:04:20.5901] Slim::Control::Request::dump (2371)    Result: [player_ip] = [192.168.2.26:39344]
[25-11-27 14:04:20.5901] Slim::Control::Request::dump (2371)    Result: [mode] = [play]
[25-11-27 14:04:20.5901] Slim::Control::Request::dump (2348)    Result: [item_loop] is loop with 1 elements:
[25-11-27 14:04:20.5902] Slim::Control::Request::dump (2358)    Result:   0. [album] = [SMASH – The Singles 1985 – 2020 (2023 Remaster)]
[25-11-27 14:04:20.5902] Slim::Control::Request::dump (2358)    Result:   0. [track] = [So hard (2023 Remaster)]
[25-11-27 14:04:20.5903] Slim::Control::Request::dump (2358)    Result:   0. [artist] = [Pet Shop Boys]
[25-11-27 14:04:20.5903] Slim::Control::Request::dump (2358)    Result:   0. [trackType] = [local]
[25-11-27 14:04:20.5904] Slim::Control::Request::dump (2358)    Result:   0. [params] = [{ playlist_index => 12, track_id => 55 }]
[25-11-27 14:04:20.5904] Slim::Control::Request::dump (2358)    Result:   0. [icon-id] = [25a32404]
[25-11-27 14:04:20.5904] Slim::Control::Request::dump (2358)    Result:   0. [text] = [So hard (2023 Remaster)
Pet Shop Boys - SMASH – The Singles 1985 – 2020 (2023 Remaster)]
[25-11-27 14:04:20.5905] Slim::Control::Request::dump (2358)    Result:   0. [style] = [itemplay]
[25-11-27 14:04:20.5905] Slim::Control::Request::dump (2371)    Result: [playlist_cur_index] = [12]
[25-11-27 14:04:20.5905] Slim::Control::Request::dump (2371)    Result: [can_seek] = [1]
[25-11-27 14:04:20.5906] Slim::Control::Request::dump (2371)    Result: [base] = [{
  actions => {
        more => {
              cmd => ["contextmenu"],
              itemsParams => "params",
              params => { context => "playlist", menu => "track" },
              player => 0,
              window => { isContextMenu => 1 },
            },
      },
}]
[25-11-27 14:04:20.5907] Slim::Control::Request::dump (2371)    Result: [rate] = [1]
[25-11-27 14:04:20.5907] Slim::Control::Request::dump (2371)    Result: [alarm_timeout_seconds] = [3600]
[25-11-27 14:04:20.5907] Slim::Control::Request::dump (2371)    Result: [alarm_version] = [2]
[25-11-27 14:04:20.5907] Slim::Control::Request::dump (2348)    Result: [preset_loop] is loop with 10 elements:
[25-11-27 14:04:20.5908] Slim::Control::Request::dump (2365)    Result:   0
[25-11-27 14:04:20.5908] Slim::Control::Request::dump (2365)    Result:   0
[25-11-27 14:04:20.5908] Slim::Control::Request::dump (2365)    Result:   0
[25-11-27 14:04:20.5909] Slim::Control::Request::dump (2365)    Result:   0
[25-11-27 14:04:20.5909] Slim::Control::Request::dump (2365)    Result:   0
[25-11-27 14:04:20.5909] Slim::Control::Request::dump (2365)    Result:   0
[25-11-27 14:04:20.5910] Slim::Control::Request::dump (2365)    Result:   0
[25-11-27 14:04:20.5910] Slim::Control::Request::dump (2365)    Result:   0
[25-11-27 14:04:20.5910] Slim::Control::Request::dump (2365)    Result:   0
[25-11-27 14:04:20.5911] Slim::Control::Request::dump (2365)    Result:   0
[25-11-27 14:04:20.5911] Slim::Control::Request::dump (2371)    Result: [player_connected] = [1]
[25-11-27 14:04:20.5911] Slim::Control::Request::dump (2371)    Result: [randomplay] = [0]
[25-11-27 14:04:20.5911] Slim::Control::Request::dump (2371)    Result: [time] = [0]
[25-11-27 14:04:20.5912] Slim::Control::Request::dump (2371)    Result: [seq_no] = [0]
[25-11-27 14:04:20.5912] Slim::Control::Request::dump (2371)    Result: [count] = [57]
[25-11-27 14:04:20.5912] Slim::Control::Request::dump (2371)    Result: [duration] = [240.32]
[25-11-27 14:04:20.5913] Slim::Control::Request::dump (2371)    Result: [playlist mode] = [off]
[25-11-27 14:04:20.5913] Slim::Control::Request::dump (2371)    Result: [playlist repeat] = [0]
[25-11-27 14:04:20.5913] Slim::Control::Request::dump (2371)    Result: [player_name] = [SqueezeClient - sdk_gphone64_x86_64]
[25-11-27 14:04:20.5913] Slim::Control::Request::dump (2371)    Result: [signalstrength] = [0]
[25-11-27 14:04:20.5914] Slim::Control::Request::dump (2371)    Result: [playlist_timestamp] = [1764248466.65536]
[25-11-27 14:04:20.5914] Slim::Control::Request::dump (2371)    Result: [offset] = [-]
[25-11-27 14:04:20.5914] Slim::Control::Request::dump (2371)    Result: [mixer volume] = [60]
[25-11-27 14:04:20.5914] Slim::Control::Request::dump (2371)    Result: [digital_volume_control] = [1]
[25-11-27 14:04:20.5915] Slim::Control::Request::dump (2371)    Result: [power] = [1]
[25-11-27 14:04:20.5915] Slim::Control::Request::dump (2371)    Result: [alarm_state] = [none]
[25-11-27 14:04:20.5915] Slim::Control::Request::dump (2371)    Result: [use_volume_control] = [1]
[25-11-27 14:04:20.5916] Slim::Control::Request::dump (2371)    Result: [playlist_tracks] = [55]
[25-11-27 14:04:20.5916] Slim::Control::Request::dump (2371)    Result: [playlist shuffle] = [0]
[25-11-27 14:04:20.5916] Slim::Control::Request::dump (2371)    Result: [alarm_snooze_seconds] = [540]
[25-11-27 14:04:20.5917] Slim::Control::Request::dump (2371)    Result: [alarm_next] = [0]
[25-11-27 14:04:20.5917] Slim::Control::Request::executeDone (1917) 0

... and that output should include the title of the song that's about to be played.

Comparing your log to what I have here, it seems like your log is missing the Slim::Player::StreamingController::playerTrackStarted line for the Radio (playback master), AKA STMs. That one is what causes the PLAYING-STREAMING -> PLAYING transition, which is what actually causes the playlist to advance.

I don't see how SqueezeClient can possibly cause that. though...