Plays correct song, but displays previous track

Nerokyl · May 5, 2024, 6:18pm

Hi,
I have a problem with the GUI often displaying the previous track during playback. Usually already at the second song of the playback queue it still shows the first track infos (cover, title, etc.) even though the second track is playing. The next tracks are the same, it always shows the infos of the previous song. I can correct it by restarting the song using the previous button or selecting it from the queue. But the next song will have the problem again. The seekbar seems to be generally correct, but is not correctly synced. I noticed that the song ends before the seekbar has ended, meaning that the seek bar of the next song also starts late. I tested with albums and singles of Tidal and my local collection on my NAS.

I made a log:

Summary

Starting Live Log…
info: Executing endpoint metavolumio
info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio
Soliciting pool server 129.70.132.36
info: CALLMETHOD: system_controller system enableLiveLog false
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
info: Live Log process terminated: null
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
Soliciting pool server 80.153.195.191
info: [ASDebug] Togle GPIO: OFF
Soliciting pool server 79.133.44.139
info: CoreCommandRouter::volumioPlay
info: CoreStateMachine::play index 18
info: CoreStateMachine::setConsumeUpdateService undefined
info: CoreStateMachine::stop
info: CoreStateMachine::setConsumeUpdateService undefined
info: CoreStateMachine::updateTrackBlock
info: CorePlayQueue::getTrackBlock
info: CoreStateMachine::stPlaybackTimer
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 18
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreStateMachine::serviceStop
info: CorePlayQueue::getTrack 18
info: CoreCommandRouter::serviceStop
info: [1714932425886] ControllerTidal::stop
info: CoreStateMachine::setConsumeUpdateService mpd
info: ControllerMpd::stop

info: [ASDebug] CurState: stop PrevState: pause
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info:
---------------------------- MPD announces state update: player
info: sendMpdCommand stop took 35 milliseconds
info: ControllerMpd::getState

info: CoreStateMachine::play index undefined
info: CoreStateMachine::setConsumeUpdateService undefined
info: CorePlayQueue::getTrack 18
info: CoreStateMachine::startPlaybackTimer
info: CorePlayQueue::getTrack 18
info: [1714932425924] ControllerTidal::clearAddPlayTrack
info: Getting stream with soundQuality HI_RES

info: sendMpdCommand status took 3 milliseconds
info: sendMpdCommand stop took 1 milliseconds

info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info: sendMpdCommand playlistinfo took 6 milliseconds
info: sendMpdCommand clear took 6 milliseconds

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CorePlayQueue::getTrack 18
info: CoreCommandRouter::volumioPushState
info: CorePlayQueue::getTrack 18
info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current tidal Received mpd
info: ------------------------------ 30ms
error: updateQueue error: null
info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info: ------------------------------ 23ms
info: sendMpdCommand add “http://127.0.0.1:3245?data=tidal://song/166335358&soundQuality=HI_RES” took 18 milliseconds
info: CoreStateMachine::setConsumeUpdateService mpd

STREAMING PROXY: Handling url /?data=tidal://song/166335358&soundQuality=HI_RES
info: [ASDebug] CurState: stop PrevState: pause
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: ------------------------------ 23ms
info: sendMpdCommand play took 21 milliseconds
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: Executing endpoint getStreamUrltidal
info: CoreCommandRouter::executeOnPlugin: tidal , getStreamUrlAPI
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: getStreamUrl took 298 milliseconds
STREAMING PROXY: Got real url: http://sp-pr-fa.audio.tidal.com/mediatracks/CAEaKRInYmMxMDYyMDNmY2JlM2QyOWFlMzVlODNjNTM0NWJlMmNfNjIubXA0/0.flac?token=1714935844~ODliYTE4YjNjYjU3NTRhOTY1NzQ1OTViY2NhZTQ0ZjMwZjIxYjk5OA==
STREAMING PROXY: Response: 200, length: 35663645
info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info: FusionDsp - ---- read samplerate, raw:
error: FusionDsp - invalid sample rate
info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32
info: FusionDsp - ---- read samplerate from file: 44100
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info:
---------------------------- MPD announces state update: player
info: sendMpdCommand status took 31 milliseconds
info: ControllerMpd::getState

info: sendMpdCommand status took 2 milliseconds
info: sendMpdCommand playlistinfo took 2 milliseconds

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 18

info: CoreStateMachine::syncState stateService play
info: CoreStateMachine::syncState currentStatus stop
info: ------------------------------ 36ms
info: sendMpdCommand playlistinfo took 1 milliseconds

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 18

info: CoreStateMachine::syncState stateService play
info: CoreStateMachine::syncState currentStatus play
info: Received an update from plugin. extracting info from payload
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: ------------------------------ 30ms
info: [ASDebug] CurState: play PrevState: pause
info: [ASDebug] Togle GPIO: ON
info: [ASDebug] CurState: play PrevState: play
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: touch_display: Setting screensaver timeout to 0 seconds.
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: CoreCommandRouter::volumioGetState
STREAMING PROXY: Client dropped request, destroying
info: Executing endpoint metavolumio
info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio
info: Executing endpoint metavolumio
info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio
info: Executing endpoint metavolumio
info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio
Soliciting pool server 185.13.148.71
Soliciting pool server 148.251.5.46
Soliciting pool server 45.9.61.155
Soliciting pool server 78.47.168.188
Soliciting pool server 144.76.0.164
Soliciting pool server 2001:8d8:1800:704:123:123:123:123
Soliciting pool server 116.203.219.116
Soliciting pool server 78.46.60.40

info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
info: CoreCommandRouter::volumioGetVisibleSources
info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom
info: Received Get System Info
info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
info: Discovery: Getting this device information
info: CoreCommandRouter::volumioGetState
info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
info: CoreCommandRouter::volumioGetState
info: Listing playlists
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache
info: CoreCommandRouter::getUIConfigOnPlugin
info: CoreCommandRouter::getUIConfigOnPlugin
info: CoreCommandRouter::getUIConfigOnPlugin
info: CoreCommandRouter::getUIConfigOnPlugin
info: Executing endpoint metavolumio
info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio
info: Executing endpoint metavolumio
info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio
info: Executing endpoint metavolumio
info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio
Soliciting pool server 194.164.164.175
Soliciting pool server 2a01:4f9:c010:157::1
Soliciting pool server 144.76.138.23
Soliciting pool server 213.239.234.28
info: CorePlayQueue::getTrack 18
info: CorePlayQueue::getTrack 19
info: Prefetching next song
info: [1714932634259] ControllerTidal::prefetch
info: Getting stream with soundQuality HI_RES

info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
STREAMING PROXY: Handling url /?data=tidal://song/166335359&soundQuality=HI_RES
info: sendMpdCommand add “http://127.0.0.1:3245?data=tidal://song/166335359&soundQuality=HI_RES” took 2 milliseconds
info: CoreStateMachine::setConsumeUpdateService mpd

info: ------------------------------ 3ms
info: sendMpdCommand consume 1 took 1 milliseconds
info: Executing endpoint getStreamUrltidal
info: CoreCommandRouter::executeOnPlugin: tidal , getStreamUrlAPI
info: getStreamUrl took 350 milliseconds
STREAMING PROXY: Got real url: http://sp-pr-fa.audio.tidal.com/mediatracks/CAEaKRInN2NlNjE4MTNmMzkyM2E5MjljMDBkYmY5NDQ5MDRmZWJfNjIubXA0/0.flac?token=1714936234~MmNiMzI3ZjdjZDgwNDI3M2UyNmU1MjNjMTA5YzFhZTkwYTNjZGQzZg==
STREAMING PROXY: Response: 200, length: 37381017
info:
---------------------------- MPD announces system playlist update
info: Ignoring MPD Status Update
info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info:
---------------------------- MPD announces state update: player
info:
---------------------------- MPD announces state update: player
info: ControllerMpd::getState

info: ------------------------------ 14ms
info: ControllerMpd::getState

info: sendMpdCommand status took 10 milliseconds

info: sendMpdCommand status took 11 milliseconds
info: sendMpdCommand status took 11 milliseconds
info: sendMpdCommand playlistinfo took 3 milliseconds

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 18

info: CoreStateMachine::syncState stateService play
info: CoreStateMachine::syncState currentStatus play
info: Received an update from plugin. extracting info from payload
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: ------------------------------ 93ms
info: sendMpdCommand playlistinfo took 70 milliseconds
info: sendMpdCommand playlistinfo took 67 milliseconds

info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 18

info: CoreStateMachine::syncState stateService play
info: CoreStateMachine::syncState currentStatus play
info: Received an update from plugin. extracting info from payload
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: ControllerMpd::pushState
info: CoreCommandRouter::servicePushState
info: CorePlayQueue::getTrack 18

info: CoreStateMachine::syncState stateService play
info: CoreStateMachine::syncState currentStatus play
info: Received an update from plugin. extracting info from payload
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::volumioPushState
info: ------------------------------ 198ms
info: ------------------------------ 199ms
info: [ASDebug] CurState: play PrevState: play
info: [ASDebug] CurState: play PrevState: play
info: [ASDebug] CurState: play PrevState: play
info: [ASDebug] CurState: play PrevState: play
info: [ASDebug] CurState: play PrevState: play
info: [ASDebug] CurState: play PrevState: play
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
STREAMING PROXY: Client dropped request, destroying
info: CoreStateMachine::startPlaybackTimer
info: CorePlayQueue::getTrack 19
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: [ASDebug] CurState: play PrevState: play
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - volume level for loudness 27 gain applied 12.88
info: FusionDsp - If filter freq >samplerate/2 then disable it
info: FusionDsp - Loudness is ON true
info: FusionDsp - Nulleq applied
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
info: FusionDsp - {“Reload”:{“result”:“Ok”}}
Soliciting pool server 157.90.24.29
process exited with code null

I started by manually selecting track 18 from the queue (display is correct for the duration of this song) and let it run. Track 19 started playing after track 18, but it still showed up as Track 18.

Let me know if more information is required.
Thank you in advance!
Sven

judydudi · May 5, 2024, 6:58pm

same issue here (on volumio 3.661)
See pic. here: Playing second Song, but still displaying first song.

rost21A · May 5, 2024, 7:21pm

Same for me
I use Qobuz, here in continuous replay

Here is the protocol
http://logs.volumio.org/volumio/mmOhxQD.html

TubularBells · May 6, 2024, 3:03pm

Chiming in to say this happens to me too when playing from both Tidal and local files.

It doesn’t happen all of the time, only after a while of playing music which I haven’t timed. The behavior is the same from browser connections (volumio.local), mobile app, and a connected display via hdmi or DSI+gpio.

l’ll try to reproduce the error on different devices, extract logs, and update.

rost21A · May 10, 2024, 8:14pm

The problem with the incorrectly displayed track does not seem to occur in dthe latest test-version 3.669 here or to a lesser extent.
I look forward to the next official version being released.

Dirkh · May 11, 2024, 10:09am

here the same

Lajos · May 12, 2024, 2:02am

Detto

Nerokyl · May 12, 2024, 11:04pm

I updated to 3.669, but the problem is still there. The music from my NAS runs correctly, but sometimes with a ~2 seconds offset (previos Song still playing for 2 seconds when next track is already displayed). Playing from Tidal it still shows the previous track from the second song onwards.

rost21A · May 13, 2024, 8:41pm

You’re right, the problem still exists.
(Qobuz, 3.674)

judydudi · May 14, 2024, 9:24am

I am missing a statement from the valued volumio support.
Would have liked to know if the problem is recognized and on the ToDo list.
Thanks, jens

judydudi · May 15, 2024, 7:33pm

I remember that this topic has been addressed before.