-- Logs begin at Thu 2025-05-01 04:29:16 EEST, end at Mon 2025-05-12 12:00:29 EEST. -- May 12 11:59:01 rivoplus go-librespot[4133]: time="2025-05-12T11:59:01+03:00" level=debug msg="fetched chunk 4/18, size: 524288" uri="spotify:track:65krtHkaYLPr0mEbjL61UP" May 12 11:59:04 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 12 11:59:04 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 12 11:59:04 rivoplus volumio[3412]: info: Discovery: Getting this device information May 12 11:59:04 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 11:59:04 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 11:59:04 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 12 11:59:10 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 12 11:59:10 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 12 11:59:10 rivoplus volumio[3412]: info: Discovery: Getting this device information May 12 11:59:10 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 11:59:10 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 11:59:10 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 12 11:59:14 rivoplus go-librespot[4133]: time="2025-05-12T11:59:14+03:00" level=debug msg="fetched chunk 5/18, size: 524288" uri="spotify:track:65krtHkaYLPr0mEbjL61UP" May 12 11:59:27 rivoplus go-librespot[4133]: time="2025-05-12T11:59:27+03:00" level=trace msg="sent dealer ping" May 12 11:59:27 rivoplus go-librespot[4133]: time="2025-05-12T11:59:27+03:00" level=trace msg="received dealer pong" May 12 11:59:29 rivoplus go-librespot[4133]: time="2025-05-12T11:59:29+03:00" level=debug msg="fetched chunk 6/18, size: 524288" uri="spotify:track:65krtHkaYLPr0mEbjL61UP" May 12 11:59:29 rivoplus go-librespot[4133]: ALSA lib /home/pi/volumio-alsa-plugin/src/pcm_volumioswitch.c:912:(_snd_pcm_volumioswitch_advance) PCM volumioMultiRoomServer cannot write to target PCM volumioOutput as it has failed its update check. May 12 11:59:29 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 12 11:59:29 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 12 11:59:29 rivoplus volumio[3412]: info: Discovery: Getting this device information May 12 11:59:29 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 11:59:29 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 11:59:29 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 12 11:59:29 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 12 11:59:29 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 12 11:59:29 rivoplus volumio[3412]: info: Discovery: Getting this device information May 12 11:59:29 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 11:59:29 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 11:59:29 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 12 11:59:33 rivoplus volumio[3412]: info: VolumeController::SetAlsaVolume100 May 12 11:59:33 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 11:59:33 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 11:59:33 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 11:59:33 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 11:59:33 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 11:59:33 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 11:59:33 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 11:59:33 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 11:59:33 rivoplus volumio[3412]: info: Signalling Playback active due to playback status change May 12 11:59:33 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 11:59:34 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 12 11:59:34 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 12 11:59:34 rivoplus volumio[3412]: info: Discovery: Getting this device information May 12 11:59:34 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 11:59:34 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 11:59:34 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 12 11:59:42 rivoplus volumio[3412]: info: Preload queue cleared May 12 11:59:42 rivoplus volumio[3412]: info: CoreCommandRouter::volumioReplaceandPlayItems May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::ClearQueue May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::stop May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::stPlaybackTimer May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::updateTrackBlock May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::getTrackBlock May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 11:59:42 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 11:59:42 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 11:59:42 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 11:59:42 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 11:59:42 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::serviceStop May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 11:59:42 rivoplus volumio[3412]: info: CoreCommandRouter::serviceStop May 12 11:59:42 rivoplus volumio[3412]: info: Spotify Stop May 12 11:59:42 rivoplus volumio[3412]: SPOTIFY: SPOTIFY STOP May 12 11:59:42 rivoplus volumio[3412]: SPOTIFY: {"status":"play","position":0,"title":"Soft Landing","artist":"Hadouk Trio","album":"Air Hadouk","albumart":"https://i.scdn.co/image/ab67616d0000b273f855db53f672daeade4cf824","uri":"spotify:track:67kBtb8RbncKeIri9TlBu8","trackType":"spotify","codec":"ogg","seek":45810,"duration":251,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":true,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 12 11:59:42 rivoplus volumio[3412]: info: Sending Spotify command to local API: /player/pause May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::clearPlayQueue May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::saveQueue May 12 11:59:42 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushQueue May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::addQueueItems May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::addQueueItems May 12 11:59:42 rivoplus volumio[3412]: info: Preload queue cleared May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:67kBtb8RbncKeIri9TlBu8 May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:67kBtb8RbncKeIri9TlBu8 May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:77HsDRybYI2rp92WVyC28R May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:77HsDRybYI2rp92WVyC28R May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:0cFflkVplDVP698RNshp8y May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:0cFflkVplDVP698RNshp8y May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:65krtHkaYLPr0mEbjL61UP May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:65krtHkaYLPr0mEbjL61UP May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:4iod8kqnoetXbVpErvl90H May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:4iod8kqnoetXbVpErvl90H May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:5lq0SOte6JafOmfVJrA5aa May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:5lq0SOte6JafOmfVJrA5aa May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:08TmRNaaezzsowLSXk9zYO May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:08TmRNaaezzsowLSXk9zYO May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:1xuGC3ptS4g1UD7qVLdeTf May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:1xuGC3ptS4g1UD7qVLdeTf May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:3wpMNfxEkbtZPtdygu09a7 May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:3wpMNfxEkbtZPtdygu09a7 May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:6dDxmIiZ0RPUbRiFLSKgGl May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:6dDxmIiZ0RPUbRiFLSKgGl May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:7dGGAyrVPy22BRT1zcLGsQ May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:7dGGAyrVPy22BRT1zcLGsQ May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:147G6D3C7ofHAAdwXc8XHf May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:147G6D3C7ofHAAdwXc8XHf May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:3yciVUssJVGRgUxfqu5976 May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:3yciVUssJVGRgUxfqu5976 May 12 11:59:42 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushQueue May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::saveQueue May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::updateTrackBlock May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::getTrackBlock May 12 11:59:42 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPlay May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::play index 12 May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::addQueueItems May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::addQueueItems May 12 11:59:42 rivoplus volumio[3412]: info: Preload queue cleared May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:05k4W9gurMAW4P1Ik2tbIn May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:05k4W9gurMAW4P1Ik2tbIn May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:4cfak8MOpdiiwKyb9o4FY2 May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:4cfak8MOpdiiwKyb9o4FY2 May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:29OeqYwBynHvsobePI4Ajs May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:29OeqYwBynHvsobePI4Ajs May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:3MOVEm1lP5zLLegG5yf8D7 May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:3MOVEm1lP5zLLegG5yf8D7 May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:0aRO0zEpE5RZIJrm0TXB4p May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:0aRO0zEpE5RZIJrm0TXB4p May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:58XCU778MEK1qh3G7B6UrO May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:58XCU778MEK1qh3G7B6UrO May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:7maV8hPRUExy1amUQ0moU7 May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:7maV8hPRUExy1amUQ0moU7 May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:4iukJONBjeoe4Cr563NB9t May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:4iukJONBjeoe4Cr563NB9t May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:11jWIXRqi36lzgsIMQROrJ May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:11jWIXRqi36lzgsIMQROrJ May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:1lEcwPE8bKoPcGbK1CZOpQ May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:1lEcwPE8bKoPcGbK1CZOpQ May 12 11:59:42 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:1GwzJMfSqoNDptZA5GHKqp May 12 11:59:42 rivoplus volumio[3412]: info: Using cached record of: spotify:track:1GwzJMfSqoNDptZA5GHKqp May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::stop May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 11:59:42 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushQueue May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::saveQueue May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::play index undefined May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::updateTrackBlock May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::getTrackBlock May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:42 rivoplus volumio[3412]: info: CoreStateMachine::startPlaybackTimer May 12 11:59:42 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:42 rivoplus volumio[3412]: info: [1747040382729] ControllerSpotify::clearAddPlayTrack May 12 11:59:42 rivoplus volumio[3412]: info: Sending Spotify command with payload to local API: /player/play May 12 11:59:42 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 11:59:42 rivoplus go-librespot[4133]: time="2025-05-12T11:59:42+03:00" level=debug msg="pause track at 55387ms" May 12 11:59:42 rivoplus volumio[3412]: info: MCU Signalled Playback Inactive May 12 11:59:42 rivoplus go-librespot[4133]: time="2025-05-12T11:59:42+03:00" level=debug msg="fetched chunk 7/18, size: 524288" uri="spotify:track:65krtHkaYLPr0mEbjL61UP" May 12 11:59:42 rivoplus go-librespot[4133]: time="2025-05-12T11:59:42+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=trace msg="emitting websocket event: paused" May 12 11:59:43 rivoplus volumio[3412]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:65krtHkaYLPr0mEbjL61UP","play_origin":"go-librespot"}} May 12 11:59:43 rivoplus volumio[3412]: SPOTIFY: PUSH STATE SPOTIFY May 12 11:59:43 rivoplus volumio[3412]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 11:59:43 rivoplus volumio[3412]: info: CoreCommandRouter::servicePushState May 12 11:59:43 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:43 rivoplus volumio[3412]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 11:59:43 rivoplus volumio[3412]: verbose: CURRENT POSITION 12 May 12 11:59:43 rivoplus volumio[3412]: info: CoreStateMachine::syncState stateService pause May 12 11:59:43 rivoplus volumio[3412]: info: CoreStateMachine::syncState currentStatus stop May 12 11:59:43 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 11:59:43 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:43 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 11:59:43 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 11:59:43 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 11:59:43 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:43 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 11:59:43 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 11:59:43 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=debug msg="resolved context of track" uri="spotify:track:3yciVUssJVGRgUxfqu5976" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3yciVUssJVGRgUxfqu5976" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3yciVUssJVGRgUxfqu5976" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=trace msg="emitting websocket event: will_play" May 12 11:59:43 rivoplus volumio[3412]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3yciVUssJVGRgUxfqu5976","play_origin":"go-librespot"}} May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=debug msg="selected format OGG_VORBIS_320 (17e008185614caa34f3d1b3da92743a5e9260d8a)" uri="spotify:track:3yciVUssJVGRgUxfqu5976" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=debug msg="requested aes key for file 17e008185614caa34f3d1b3da92743a5e9260d8a, gid: 3yciVUssJVGRgUxfqu5976" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=debug msg="fetched first chunk of 27, total size is 13787168 bytes" uri="spotify:track:3yciVUssJVGRgUxfqu5976" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=info msg="loaded track \"Creep\" (paused: false, position: 0ms, duration: 348840ms, prefetched: false)" uri="spotify:track:3yciVUssJVGRgUxfqu5976" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=trace msg="scheduling prefetch in 319s" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=trace msg="emitting websocket event: metadata" May 12 11:59:43 rivoplus volumio[3412]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3yciVUssJVGRgUxfqu5976","name":"Creep","artist_names":["Vanessa Fernandez"],"album_name":"I Want You","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02f7e33d707f4dd275bd2a4472","position":0,"duration":348840,"release_date":"year:2019 month:4 day:20","track_number":9,"disc_number":1}} May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=debug msg="fetched chunk 1/26, size: 524288" uri="spotify:track:3yciVUssJVGRgUxfqu5976" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=debug msg="fetched chunk 3/26, size: 524288" uri="spotify:track:3yciVUssJVGRgUxfqu5976" May 12 11:59:43 rivoplus go-librespot[4133]: time="2025-05-12T11:59:43+03:00" level=debug msg="fetched chunk 2/26, size: 524288" uri="spotify:track:3yciVUssJVGRgUxfqu5976" May 12 11:59:44 rivoplus go-librespot[4133]: time="2025-05-12T11:59:44+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 11:59:44 rivoplus go-librespot[4133]: time="2025-05-12T11:59:44+03:00" level=trace msg="emitting websocket event: playing" May 12 11:59:44 rivoplus volumio[3412]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3yciVUssJVGRgUxfqu5976","play_origin":"go-librespot"}} May 12 11:59:44 rivoplus volumio[3412]: SPOTIFY: PUSH STATE SPOTIFY May 12 11:59:44 rivoplus volumio[3412]: SPOTIFY: {"status":"play","service":"spop","title":"Creep","artist":"Vanessa Fernandez","album":"I Want You","albumart":"https://i.scdn.co/image/ab67616d00001e02f7e33d707f4dd275bd2a4472","uri":"spotify:track:3yciVUssJVGRgUxfqu5976","trackType":"spotify","seek":0,"duration":348,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 11:59:44 rivoplus volumio[3412]: info: CoreCommandRouter::servicePushState May 12 11:59:44 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:44 rivoplus volumio[3412]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Creep","artist":"Vanessa Fernandez","album":"I Want You","albumart":"https://i.scdn.co/image/ab67616d00001e02f7e33d707f4dd275bd2a4472","uri":"spotify:track:3yciVUssJVGRgUxfqu5976","trackType":"spotify","seek":0,"duration":348,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 11:59:44 rivoplus volumio[3412]: verbose: CURRENT POSITION 12 May 12 11:59:44 rivoplus volumio[3412]: info: CoreStateMachine::syncState stateService play May 12 11:59:44 rivoplus volumio[3412]: info: CoreStateMachine::syncState currentStatus stop May 12 11:59:44 rivoplus volumio[3412]: SPOTIFY: PUSH STATE SPOTIFY May 12 11:59:44 rivoplus volumio[3412]: SPOTIFY: {"status":"play","service":"spop","title":"Creep","artist":"Vanessa Fernandez","album":"I Want You","albumart":"https://i.scdn.co/image/ab67616d00001e02f7e33d707f4dd275bd2a4472","uri":"spotify:track:3yciVUssJVGRgUxfqu5976","trackType":"spotify","seek":0,"duration":348,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 11:59:44 rivoplus volumio[3412]: info: CoreCommandRouter::servicePushState May 12 11:59:44 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:44 rivoplus volumio[3412]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Creep","artist":"Vanessa Fernandez","album":"I Want You","albumart":"https://i.scdn.co/image/ab67616d00001e02f7e33d707f4dd275bd2a4472","uri":"spotify:track:3yciVUssJVGRgUxfqu5976","trackType":"spotify","seek":0,"duration":348,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 11:59:44 rivoplus volumio[3412]: verbose: CURRENT POSITION 12 May 12 11:59:44 rivoplus volumio[3412]: info: CoreStateMachine::syncState stateService play May 12 11:59:44 rivoplus volumio[3412]: info: CoreStateMachine::syncState currentStatus play May 12 11:59:44 rivoplus volumio[3412]: info: Received an update from plugin. extracting info from payload May 12 11:59:44 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 11:59:44 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:44 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 11:59:44 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 11:59:44 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 11:59:44 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:44 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 11:59:44 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 11:59:44 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 11:59:44 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:44 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 11:59:44 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 11:59:44 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:44 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 11:59:44 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 11:59:44 rivoplus volumio[3412]: info: Signalling Playback active due to playback status change May 12 11:59:44 rivoplus volumio[3412]: info: Signalling Playback active due to playback status change May 12 11:59:44 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 11:59:44 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 11:59:44 rivoplus volumio[3412]: info: MCU Signalled Playback Active May 12 11:59:45 rivoplus volumio[3412]: info: Executing endpoint metavolumio May 12 11:59:45 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 12 11:59:45 rivoplus volumio[3412]: info: Executing endpoint metavolumio May 12 11:59:45 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 12 11:59:45 rivoplus volumio[3412]: info: Executing endpoint metavolumio May 12 11:59:45 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 12 11:59:49 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 12 11:59:49 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 12 11:59:49 rivoplus volumio[3412]: info: Discovery: Getting this device information May 12 11:59:49 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 11:59:49 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:49 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 12 11:59:49 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 12 11:59:49 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 12 11:59:49 rivoplus volumio[3412]: info: Discovery: Getting this device information May 12 11:59:49 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 11:59:49 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 11:59:49 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 12 11:59:57 rivoplus go-librespot[4133]: time="2025-05-12T11:59:57+03:00" level=trace msg="sent dealer ping" May 12 11:59:57 rivoplus go-librespot[4133]: time="2025-05-12T11:59:57+03:00" level=debug msg="fetched chunk 4/26, size: 524288" uri="spotify:track:3yciVUssJVGRgUxfqu5976" May 12 11:59:57 rivoplus go-librespot[4133]: time="2025-05-12T11:59:57+03:00" level=trace msg="received dealer pong" May 12 12:00:00 rivoplus go-librespot[4133]: time="2025-05-12T12:00:00+03:00" level=trace msg="received accesspoint ping" May 12 12:00:00 rivoplus go-librespot[4133]: time="2025-05-12T12:00:00+03:00" level=trace msg="received accesspoint pong ack" May 12 12:00:04 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 12 12:00:04 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 12 12:00:04 rivoplus volumio[3412]: info: Discovery: Getting this device information May 12 12:00:04 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:04 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 12:00:04 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 12 12:00:09 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 12 12:00:09 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 12 12:00:09 rivoplus volumio[3412]: info: Discovery: Getting this device information May 12 12:00:09 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:09 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 12:00:09 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 12 12:00:10 rivoplus volumio[3412]: info: Preload queue cleared May 12 12:00:10 rivoplus volumio[3412]: info: CoreCommandRouter::volumioReplaceandPlayItems May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::ClearQueue May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::stop May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::stPlaybackTimer May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::updateTrackBlock May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::getTrackBlock May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 12:00:10 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 12:00:10 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 12:00:10 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 12:00:10 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 12:00:10 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::serviceStop May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 12 May 12 12:00:10 rivoplus volumio[3412]: info: CoreCommandRouter::serviceStop May 12 12:00:10 rivoplus volumio[3412]: info: Spotify Stop May 12 12:00:10 rivoplus volumio[3412]: SPOTIFY: SPOTIFY STOP May 12 12:00:10 rivoplus volumio[3412]: SPOTIFY: {"status":"play","position":12,"title":"Creep","artist":"Vanessa Fernandez","album":"I Want You","albumart":"https://i.scdn.co/image/ab67616d0000b273f7e33d707f4dd275bd2a4472","uri":"spotify:track:3yciVUssJVGRgUxfqu5976","trackType":"spotify","codec":"ogg","seek":0,"duration":348,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":true,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 12 12:00:10 rivoplus volumio[3412]: info: Sending Spotify command to local API: /player/pause May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::clearPlayQueue May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::saveQueue May 12 12:00:10 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushQueue May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::addQueueItems May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::addQueueItems May 12 12:00:10 rivoplus volumio[3412]: info: Preload queue cleared May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:67kBtb8RbncKeIri9TlBu8 May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:67kBtb8RbncKeIri9TlBu8 May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:77HsDRybYI2rp92WVyC28R May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:77HsDRybYI2rp92WVyC28R May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:0cFflkVplDVP698RNshp8y May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:0cFflkVplDVP698RNshp8y May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:65krtHkaYLPr0mEbjL61UP May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:65krtHkaYLPr0mEbjL61UP May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:4iod8kqnoetXbVpErvl90H May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:4iod8kqnoetXbVpErvl90H May 12 12:00:10 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushQueue May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::saveQueue May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::updateTrackBlock May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::getTrackBlock May 12 12:00:10 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPlay May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::play index 4 May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::addQueueItems May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::addQueueItems May 12 12:00:10 rivoplus volumio[3412]: info: Preload queue cleared May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:5lq0SOte6JafOmfVJrA5aa May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:5lq0SOte6JafOmfVJrA5aa May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:08TmRNaaezzsowLSXk9zYO May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:08TmRNaaezzsowLSXk9zYO May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:1xuGC3ptS4g1UD7qVLdeTf May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:1xuGC3ptS4g1UD7qVLdeTf May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:3wpMNfxEkbtZPtdygu09a7 May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:3wpMNfxEkbtZPtdygu09a7 May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:6dDxmIiZ0RPUbRiFLSKgGl May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:6dDxmIiZ0RPUbRiFLSKgGl May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:7dGGAyrVPy22BRT1zcLGsQ May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:7dGGAyrVPy22BRT1zcLGsQ May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:147G6D3C7ofHAAdwXc8XHf May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:147G6D3C7ofHAAdwXc8XHf May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:3yciVUssJVGRgUxfqu5976 May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:3yciVUssJVGRgUxfqu5976 May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:05k4W9gurMAW4P1Ik2tbIn May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:05k4W9gurMAW4P1Ik2tbIn May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:4cfak8MOpdiiwKyb9o4FY2 May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:4cfak8MOpdiiwKyb9o4FY2 May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:29OeqYwBynHvsobePI4Ajs May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:29OeqYwBynHvsobePI4Ajs May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:3MOVEm1lP5zLLegG5yf8D7 May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:3MOVEm1lP5zLLegG5yf8D7 May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:0aRO0zEpE5RZIJrm0TXB4p May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:0aRO0zEpE5RZIJrm0TXB4p May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:58XCU778MEK1qh3G7B6UrO May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:58XCU778MEK1qh3G7B6UrO May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:7maV8hPRUExy1amUQ0moU7 May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:7maV8hPRUExy1amUQ0moU7 May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:4iukJONBjeoe4Cr563NB9t May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:4iukJONBjeoe4Cr563NB9t May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:11jWIXRqi36lzgsIMQROrJ May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:11jWIXRqi36lzgsIMQROrJ May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:1lEcwPE8bKoPcGbK1CZOpQ May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:1lEcwPE8bKoPcGbK1CZOpQ May 12 12:00:10 rivoplus volumio[3412]: info: Adding Item to queue: spotify:track:1GwzJMfSqoNDptZA5GHKqp May 12 12:00:10 rivoplus volumio[3412]: info: Using cached record of: spotify:track:1GwzJMfSqoNDptZA5GHKqp May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::stop May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 12:00:10 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushQueue May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::saveQueue May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::play index undefined May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::updateTrackBlock May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::getTrackBlock May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:10 rivoplus volumio[3412]: info: CoreStateMachine::startPlaybackTimer May 12 12:00:10 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:10 rivoplus volumio[3412]: info: [1747040410950] ControllerSpotify::clearAddPlayTrack May 12 12:00:10 rivoplus volumio[3412]: info: Sending Spotify command with payload to local API: /player/play May 12 12:00:10 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 12:00:10 rivoplus go-librespot[4133]: time="2025-05-12T12:00:10+03:00" level=debug msg="pause track at 27095ms" May 12 12:00:11 rivoplus volumio[3412]: info: MCU Signalled Playback Inactive May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=trace msg="emitting websocket event: paused" May 12 12:00:11 rivoplus volumio[3412]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3yciVUssJVGRgUxfqu5976","play_origin":"go-librespot"}} May 12 12:00:11 rivoplus volumio[3412]: SPOTIFY: PUSH STATE SPOTIFY May 12 12:00:11 rivoplus volumio[3412]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:11 rivoplus volumio[3412]: info: CoreCommandRouter::servicePushState May 12 12:00:11 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:11 rivoplus volumio[3412]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":1000,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:11 rivoplus volumio[3412]: verbose: CURRENT POSITION 4 May 12 12:00:11 rivoplus volumio[3412]: info: CoreStateMachine::syncState stateService pause May 12 12:00:11 rivoplus volumio[3412]: info: CoreStateMachine::syncState currentStatus stop May 12 12:00:11 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 12:00:11 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:11 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 12:00:11 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 12:00:11 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:11 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:11 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 12:00:11 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 12:00:11 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=debug msg="resolved context of track" uri="spotify:track:4iod8kqnoetXbVpErvl90H" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4iod8kqnoetXbVpErvl90H" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4iod8kqnoetXbVpErvl90H" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=trace msg="emitting websocket event: will_play" May 12 12:00:11 rivoplus volumio[3412]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4iod8kqnoetXbVpErvl90H","play_origin":"go-librespot"}} May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=debug msg="selected format OGG_VORBIS_320 (3e93b16bdf171e8613288f10a048f15132b03de9)" uri="spotify:track:4iod8kqnoetXbVpErvl90H" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=debug msg="requested aes key for file 3e93b16bdf171e8613288f10a048f15132b03de9, gid: 4iod8kqnoetXbVpErvl90H" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=debug msg="fetched first chunk of 15, total size is 7537524 bytes" uri="spotify:track:4iod8kqnoetXbVpErvl90H" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=info msg="loaded track \"Sorry Seems To Be The Hardest Word\" (paused: false, position: 0ms, duration: 223866ms, prefetched: false)" uri="spotify:track:4iod8kqnoetXbVpErvl90H" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:4iod8kqnoetXbVpErvl90H" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=trace msg="scheduling prefetch in 194s" May 12 12:00:11 rivoplus go-librespot[4133]: time="2025-05-12T12:00:11+03:00" level=trace msg="emitting websocket event: metadata" May 12 12:00:12 rivoplus volumio[3412]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4iod8kqnoetXbVpErvl90H","name":"Sorry Seems To Be The Hardest Word","artist_names":["Lydia Gray"],"album_name":"In My Eyes","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","position":0,"duration":223866,"release_date":"year:2007 month:9 day:6","track_number":9,"disc_number":1}} May 12 12:00:12 rivoplus go-librespot[4133]: time="2025-05-12T12:00:12+03:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:4iod8kqnoetXbVpErvl90H" May 12 12:00:12 rivoplus go-librespot[4133]: time="2025-05-12T12:00:12+03:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:4iod8kqnoetXbVpErvl90H" May 12 12:00:12 rivoplus go-librespot[4133]: time="2025-05-12T12:00:12+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:12 rivoplus go-librespot[4133]: time="2025-05-12T12:00:12+03:00" level=trace msg="emitting websocket event: playing" May 12 12:00:12 rivoplus volumio[3412]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4iod8kqnoetXbVpErvl90H","play_origin":"go-librespot"}} May 12 12:00:12 rivoplus volumio[3412]: SPOTIFY: PUSH STATE SPOTIFY May 12 12:00:12 rivoplus volumio[3412]: SPOTIFY: {"status":"play","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":0,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:12 rivoplus volumio[3412]: info: CoreCommandRouter::servicePushState May 12 12:00:12 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:12 rivoplus volumio[3412]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":0,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:12 rivoplus volumio[3412]: verbose: CURRENT POSITION 4 May 12 12:00:12 rivoplus volumio[3412]: info: CoreStateMachine::syncState stateService play May 12 12:00:12 rivoplus volumio[3412]: info: CoreStateMachine::syncState currentStatus stop May 12 12:00:12 rivoplus volumio[3412]: SPOTIFY: PUSH STATE SPOTIFY May 12 12:00:12 rivoplus volumio[3412]: SPOTIFY: {"status":"play","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":0,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:12 rivoplus volumio[3412]: info: CoreCommandRouter::servicePushState May 12 12:00:12 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:12 rivoplus volumio[3412]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":0,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:12 rivoplus volumio[3412]: verbose: CURRENT POSITION 4 May 12 12:00:12 rivoplus volumio[3412]: info: CoreStateMachine::syncState stateService play May 12 12:00:12 rivoplus volumio[3412]: info: CoreStateMachine::syncState currentStatus play May 12 12:00:12 rivoplus volumio[3412]: info: Received an update from plugin. extracting info from payload May 12 12:00:12 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 12:00:12 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:12 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 12:00:12 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 12:00:12 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:12 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:12 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 12:00:12 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 12:00:12 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 12:00:12 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:12 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 12:00:12 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:12 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:12 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 12:00:12 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 12:00:12 rivoplus volumio[3412]: info: Signalling Playback active due to playback status change May 12 12:00:12 rivoplus volumio[3412]: info: Signalling Playback active due to playback status change May 12 12:00:12 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 12:00:12 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 12:00:12 rivoplus volumio[3412]: info: MCU Signalled Playback Active May 12 12:00:13 rivoplus volumio[3412]: info: Executing endpoint metavolumio May 12 12:00:13 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 12 12:00:13 rivoplus volumio[3412]: info: Executing endpoint metavolumio May 12 12:00:13 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 12 12:00:13 rivoplus volumio[3412]: info: Executing endpoint metavolumio May 12 12:00:13 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 12 12:00:14 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPause May 12 12:00:14 rivoplus volumio[3412]: info: CoreStateMachine::pause May 12 12:00:14 rivoplus volumio[3412]: info: CoreStateMachine::stPlaybackTimer May 12 12:00:14 rivoplus volumio[3412]: info: CoreStateMachine::servicePause May 12 12:00:14 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:14 rivoplus volumio[3412]: info: CoreCommandRouter::servicePause May 12 12:00:14 rivoplus volumio[3412]: info: Spotify Received pause May 12 12:00:14 rivoplus volumio[3412]: SPOTIFY: SPOTIFY PAUSE May 12 12:00:14 rivoplus volumio[3412]: SPOTIFY: {"status":"play","position":4,"title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d0000b2730dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","codec":"ogg","seek":0,"duration":223,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":true,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 12 12:00:14 rivoplus volumio[3412]: info: Sending Spotify command to local API: /player/pause May 12 12:00:14 rivoplus go-librespot[4133]: time="2025-05-12T12:00:14+03:00" level=debug msg="pause track at 2988ms" May 12 12:00:15 rivoplus go-librespot[4133]: time="2025-05-12T12:00:15+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:15 rivoplus go-librespot[4133]: time="2025-05-12T12:00:15+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:15 rivoplus go-librespot[4133]: time="2025-05-12T12:00:15+03:00" level=trace msg="emitting websocket event: paused" May 12 12:00:15 rivoplus volumio[3412]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4iod8kqnoetXbVpErvl90H","play_origin":"go-librespot"}} May 12 12:00:15 rivoplus volumio[3412]: SPOTIFY: PUSH STATE SPOTIFY May 12 12:00:15 rivoplus volumio[3412]: SPOTIFY: {"status":"pause","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":3000,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:15 rivoplus volumio[3412]: info: CoreCommandRouter::servicePushState May 12 12:00:15 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:15 rivoplus volumio[3412]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":3000,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:15 rivoplus volumio[3412]: verbose: CURRENT POSITION 4 May 12 12:00:15 rivoplus volumio[3412]: info: CoreStateMachine::syncState stateService pause May 12 12:00:15 rivoplus volumio[3412]: info: CoreStateMachine::syncState currentStatus pause May 12 12:00:15 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 12:00:15 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:15 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 12:00:15 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 12:00:15 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:15 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 4 May 12 12:00:15 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 12:00:15 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 12:00:15 rivoplus volumio[3412]: info: CoreStateMachine::stPlaybackTimer May 12 12:00:15 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 12:00:15 rivoplus volumio[3412]: info: MCU Signalled Playback Inactive May 12 12:00:18 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPrevious May 12 12:00:18 rivoplus volumio[3412]: info: CoreStateMachine::previous May 12 12:00:18 rivoplus volumio[3412]: info: CoreStateMachine::updateTrackBlock May 12 12:00:18 rivoplus volumio[3412]: info: CorePlayQueue::getTrackBlock May 12 12:00:18 rivoplus volumio[3412]: info: CoreStateMachine::serviceClearAddPlay May 12 12:00:18 rivoplus volumio[3412]: info: CoreCommandRouter::serviceClearAddPlayTracks May 12 12:00:18 rivoplus volumio[3412]: error: WARNING: No clearAddPlayTracks method for service spop May 12 12:00:20 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPrevious May 12 12:00:20 rivoplus volumio[3412]: info: CoreStateMachine::previous May 12 12:00:20 rivoplus volumio[3412]: info: CoreStateMachine::updateTrackBlock May 12 12:00:20 rivoplus volumio[3412]: info: CorePlayQueue::getTrackBlock May 12 12:00:20 rivoplus volumio[3412]: info: CoreStateMachine::serviceClearAddPlay May 12 12:00:20 rivoplus volumio[3412]: info: CoreCommandRouter::serviceClearAddPlayTracks May 12 12:00:20 rivoplus volumio[3412]: error: WARNING: No clearAddPlayTracks method for service spop May 12 12:00:20 rivoplus volumio[3412]: error: Failed request for metavolumio API May 12 12:00:21 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPlay May 12 12:00:21 rivoplus volumio[3412]: info: CoreStateMachine::play index undefined May 12 12:00:21 rivoplus volumio[3412]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 12:00:21 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 24 May 12 12:00:24 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPlay May 12 12:00:24 rivoplus volumio[3412]: info: CoreStateMachine::play index undefined May 12 12:00:24 rivoplus volumio[3412]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 12:00:24 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:24 rivoplus volumio[3412]: info: CoreStateMachine::startPlaybackTimer May 12 12:00:24 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:24 rivoplus volumio[3412]: info: Spotify Resume May 12 12:00:24 rivoplus volumio[3412]: info: Sending Spotify command to local API: /player/resume May 12 12:00:24 rivoplus go-librespot[4133]: time="2025-05-12T12:00:24+03:00" level=trace msg="seek to 2988ms (diff: 164ms, samples: 131770, bytes: 95400)" uri="spotify:track:4iod8kqnoetXbVpErvl90H" May 12 12:00:24 rivoplus go-librespot[4133]: time="2025-05-12T12:00:24+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 12 12:00:24 rivoplus go-librespot[4133]: time="2025-05-12T12:00:24+03:00" level=debug msg="resume track at 2824ms" May 12 12:00:24 rivoplus go-librespot[4133]: time="2025-05-12T12:00:24+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:24 rivoplus go-librespot[4133]: time="2025-05-12T12:00:24+03:00" level=trace msg="scheduling prefetch in 191s" May 12 12:00:24 rivoplus go-librespot[4133]: time="2025-05-12T12:00:24+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:24 rivoplus go-librespot[4133]: time="2025-05-12T12:00:24+03:00" level=trace msg="emitting websocket event: playing" May 12 12:00:24 rivoplus volumio[3412]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4iod8kqnoetXbVpErvl90H","play_origin":"go-librespot"}} May 12 12:00:24 rivoplus volumio[3412]: SPOTIFY: PUSH STATE SPOTIFY May 12 12:00:24 rivoplus volumio[3412]: SPOTIFY: {"status":"play","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":3000,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:24 rivoplus volumio[3412]: info: CoreCommandRouter::servicePushState May 12 12:00:24 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:24 rivoplus volumio[3412]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":3000,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:24 rivoplus volumio[3412]: verbose: CURRENT POSITION 0 May 12 12:00:24 rivoplus volumio[3412]: info: CoreStateMachine::syncState stateService play May 12 12:00:24 rivoplus volumio[3412]: info: CoreStateMachine::syncState currentStatus pause May 12 12:00:24 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 12:00:24 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:24 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 12:00:24 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 12:00:24 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:24 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:24 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 12:00:24 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 12:00:24 rivoplus volumio[3412]: info: Signalling Playback active due to playback status change May 12 12:00:24 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 12:00:24 rivoplus volumio[3412]: info: MCU Signalled Playback Active May 12 12:00:24 rivoplus volumio[3412]: SPOTIFY: PUSH STATE SPOTIFY May 12 12:00:24 rivoplus volumio[3412]: SPOTIFY: {"status":"play","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":3000,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:24 rivoplus volumio[3412]: info: CoreCommandRouter::servicePushState May 12 12:00:24 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:24 rivoplus volumio[3412]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":3000,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:24 rivoplus volumio[3412]: verbose: CURRENT POSITION 0 May 12 12:00:24 rivoplus volumio[3412]: info: CoreStateMachine::syncState stateService play May 12 12:00:24 rivoplus volumio[3412]: info: CoreStateMachine::syncState currentStatus play May 12 12:00:24 rivoplus volumio[3412]: info: Received an update from plugin. extracting info from payload May 12 12:00:24 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 12:00:24 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:24 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 12:00:24 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 12:00:24 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:24 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:24 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 12:00:24 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 12:00:24 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 12:00:24 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:24 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 12:00:24 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:24 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:24 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 12:00:24 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 12:00:24 rivoplus volumio[3412]: info: Signalling Playback active due to playback status change May 12 12:00:24 rivoplus volumio[3412]: info: Signalling Playback active due to playback status change May 12 12:00:24 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 12:00:24 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 12:00:26 rivoplus volumio[3412]: info: Executing endpoint metavolumio May 12 12:00:26 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 12 12:00:26 rivoplus volumio[3412]: info: Executing endpoint metavolumio May 12 12:00:26 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 12 12:00:26 rivoplus volumio[3412]: info: Executing endpoint metavolumio May 12 12:00:26 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio May 12 12:00:26 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPrevious May 12 12:00:26 rivoplus volumio[3412]: info: CoreStateMachine::previous May 12 12:00:26 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:26 rivoplus volumio[3412]: info: Spotify seek to: 0 May 12 12:00:26 rivoplus volumio[3412]: info: Sending Spotify command with payload to local API: /player/seek May 12 12:00:26 rivoplus go-librespot[4133]: time="2025-05-12T12:00:26+03:00" level=debug msg="seek track to 0ms" May 12 12:00:26 rivoplus go-librespot[4133]: time="2025-05-12T12:00:26+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:4iod8kqnoetXbVpErvl90H" May 12 12:00:26 rivoplus go-librespot[4133]: time="2025-05-12T12:00:26+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:26 rivoplus go-librespot[4133]: time="2025-05-12T12:00:26+03:00" level=trace msg="scheduling prefetch in 194s" May 12 12:00:26 rivoplus go-librespot[4133]: time="2025-05-12T12:00:26+03:00" level=trace msg="emitting websocket event: seek" May 12 12:00:26 rivoplus volumio[3412]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:4iod8kqnoetXbVpErvl90H","position":0,"duration":223866,"play_origin":"go-librespot"}} May 12 12:00:26 rivoplus volumio[3412]: SPOTIFY: PUSH STATE SPOTIFY May 12 12:00:26 rivoplus volumio[3412]: SPOTIFY: {"status":"play","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":0,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:26 rivoplus volumio[3412]: info: CoreCommandRouter::servicePushState May 12 12:00:26 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:26 rivoplus volumio[3412]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":0,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:26 rivoplus volumio[3412]: verbose: CURRENT POSITION 0 May 12 12:00:26 rivoplus volumio[3412]: info: CoreStateMachine::syncState stateService play May 12 12:00:26 rivoplus volumio[3412]: info: CoreStateMachine::syncState currentStatus play May 12 12:00:26 rivoplus volumio[3412]: info: Received an update from plugin. extracting info from payload May 12 12:00:26 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 12:00:26 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:26 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 12:00:26 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 12:00:26 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:26 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:26 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 12:00:26 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 12:00:26 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 12:00:26 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:26 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 12:00:26 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:26 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:26 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 12:00:26 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 12:00:26 rivoplus volumio[3412]: info: Signalling Playback active due to playback status change May 12 12:00:26 rivoplus volumio[3412]: info: Signalling Playback active due to playback status change May 12 12:00:26 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 12:00:26 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 12:00:27 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPrevious May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::previous May 12 12:00:27 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::stop May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::stPlaybackTimer May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::updateTrackBlock May 12 12:00:27 rivoplus volumio[3412]: info: CorePlayQueue::getTrackBlock May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 12:00:27 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:27 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 12:00:27 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 12:00:27 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:27 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:27 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 12:00:27 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::serviceStop May 12 12:00:27 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:27 rivoplus volumio[3412]: info: CoreCommandRouter::serviceStop May 12 12:00:27 rivoplus volumio[3412]: info: Spotify Stop May 12 12:00:27 rivoplus volumio[3412]: SPOTIFY: SPOTIFY STOP May 12 12:00:27 rivoplus volumio[3412]: SPOTIFY: {"status":"play","position":0,"title":"Soft Landing","artist":"Hadouk Trio","album":"Air Hadouk","albumart":"https://i.scdn.co/image/ab67616d0000b273f855db53f672daeade4cf824","uri":"spotify:track:67kBtb8RbncKeIri9TlBu8","trackType":"spotify","codec":"ogg","seek":0,"duration":223,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":true,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} May 12 12:00:27 rivoplus volumio[3412]: info: Sending Spotify command to local API: /player/pause May 12 12:00:27 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 12:00:27 rivoplus go-librespot[4133]: time="2025-05-12T12:00:27+03:00" level=debug msg="pause track at 612ms" May 12 12:00:27 rivoplus go-librespot[4133]: time="2025-05-12T12:00:27+03:00" level=trace msg="sent dealer ping" May 12 12:00:27 rivoplus volumio[3412]: info: MCU Signalled Playback Inactive May 12 12:00:27 rivoplus go-librespot[4133]: time="2025-05-12T12:00:27+03:00" level=trace msg="received dealer pong" May 12 12:00:27 rivoplus go-librespot[4133]: time="2025-05-12T12:00:27+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:27 rivoplus go-librespot[4133]: time="2025-05-12T12:00:27+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:27 rivoplus go-librespot[4133]: time="2025-05-12T12:00:27+03:00" level=trace msg="emitting websocket event: paused" May 12 12:00:27 rivoplus volumio[3412]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4iod8kqnoetXbVpErvl90H","play_origin":"go-librespot"}} May 12 12:00:27 rivoplus volumio[3412]: SPOTIFY: PUSH STATE SPOTIFY May 12 12:00:27 rivoplus volumio[3412]: SPOTIFY: {"status":"pause","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":1000,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:27 rivoplus volumio[3412]: info: CoreCommandRouter::servicePushState May 12 12:00:27 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:27 rivoplus volumio[3412]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Sorry Seems To Be The Hardest Word","artist":"Lydia Gray","album":"In My Eyes","albumart":"https://i.scdn.co/image/ab67616d00001e020dbc63f84640111c19cc9024","uri":"spotify:track:4iod8kqnoetXbVpErvl90H","trackType":"spotify","seek":1000,"duration":223,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:27 rivoplus volumio[3412]: verbose: CURRENT POSITION 0 May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::syncState stateService pause May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::syncState currentStatus stop May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::pushState May 12 12:00:27 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:27 rivoplus volumio[3412]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 12 12:00:27 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPushState May 12 12:00:27 rivoplus volumio[3412]: info: CoreCommandRouter::volumioGetState May 12 12:00:27 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 0 May 12 12:00:27 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output update for this device May 12 12:00:27 rivoplus volumio[3412]: info: MRS: Pushing multiroomSync output May 12 12:00:27 rivoplus volumio[3412]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::play index undefined May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::setConsumeUpdateService undefined May 12 12:00:27 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 16 May 12 12:00:27 rivoplus volumio[3412]: info: CoreStateMachine::startPlaybackTimer May 12 12:00:27 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 16 May 12 12:00:27 rivoplus volumio[3412]: info: [1747040427960] ControllerSpotify::clearAddPlayTrack May 12 12:00:27 rivoplus volumio[3412]: info: Sending Spotify command with payload to local API: /player/play May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=debug msg="resolved context of track" uri="spotify:track:3MOVEm1lP5zLLegG5yf8D7" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3MOVEm1lP5zLLegG5yf8D7" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3MOVEm1lP5zLLegG5yf8D7" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=trace msg="emitting websocket event: will_play" May 12 12:00:28 rivoplus volumio[3412]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3MOVEm1lP5zLLegG5yf8D7","play_origin":"go-librespot"}} May 12 12:00:28 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPrevious May 12 12:00:28 rivoplus volumio[3412]: info: CoreStateMachine::previous May 12 12:00:28 rivoplus volumio[3412]: info: CoreStateMachine::updateTrackBlock May 12 12:00:28 rivoplus volumio[3412]: info: CorePlayQueue::getTrackBlock May 12 12:00:28 rivoplus volumio[3412]: info: CoreStateMachine::serviceClearAddPlay May 12 12:00:28 rivoplus volumio[3412]: info: CoreCommandRouter::serviceClearAddPlayTracks May 12 12:00:28 rivoplus volumio[3412]: error: WARNING: No clearAddPlayTracks method for service spop May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=debug msg="selected format OGG_VORBIS_320 (0c843efe6d1a1f5137bce25f82de04d3405af58e)" uri="spotify:track:3MOVEm1lP5zLLegG5yf8D7" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=debug msg="requested aes key for file 0c843efe6d1a1f5137bce25f82de04d3405af58e, gid: 3MOVEm1lP5zLLegG5yf8D7" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=debug msg="fetched first chunk of 32, total size is 16471809 bytes" uri="spotify:track:3MOVEm1lP5zLLegG5yf8D7" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=info msg="loaded track \"Hotel California\" (paused: false, position: 0ms, duration: 381365ms, prefetched: false)" uri="spotify:track:3MOVEm1lP5zLLegG5yf8D7" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=debug msg="fetched chunk 1/31, size: 524288" uri="spotify:track:3MOVEm1lP5zLLegG5yf8D7" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=trace msg="scheduling prefetch in 351s" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=trace msg="emitting websocket event: metadata" May 12 12:00:28 rivoplus volumio[3412]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3MOVEm1lP5zLLegG5yf8D7","name":"Hotel California","artist_names":["Yao Si Ting"],"album_name":"Collection","album_cover_url":"https://i.scdn.co/image/ab67616d00001e024cd2db4e428f4ada72d05fb3","position":0,"duration":381365,"release_date":"year:2024 month:1 day:16","track_number":4,"disc_number":1}} May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=debug msg="fetched chunk 3/31, size: 524288" uri="spotify:track:3MOVEm1lP5zLLegG5yf8D7" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=debug msg="fetched chunk 2/31, size: 524288" uri="spotify:track:3MOVEm1lP5zLLegG5yf8D7" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 12 12:00:28 rivoplus go-librespot[4133]: time="2025-05-12T12:00:28+03:00" level=trace msg="emitting websocket event: playing" May 12 12:00:28 rivoplus volumio[3412]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3MOVEm1lP5zLLegG5yf8D7","play_origin":"go-librespot"}} May 12 12:00:28 rivoplus volumio[3412]: SPOTIFY: PUSH STATE SPOTIFY May 12 12:00:28 rivoplus volumio[3412]: SPOTIFY: {"status":"play","service":"spop","title":"Hotel California","artist":"Yao Si Ting","album":"Collection","albumart":"https://i.scdn.co/image/ab67616d00001e024cd2db4e428f4ada72d05fb3","uri":"spotify:track:3MOVEm1lP5zLLegG5yf8D7","trackType":"spotify","seek":0,"duration":381,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:28 rivoplus volumio[3412]: info: CoreCommandRouter::servicePushState May 12 12:00:28 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 24 May 12 12:00:28 rivoplus volumio[3412]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Hotel California","artist":"Yao Si Ting","album":"Collection","albumart":"https://i.scdn.co/image/ab67616d00001e024cd2db4e428f4ada72d05fb3","uri":"spotify:track:3MOVEm1lP5zLLegG5yf8D7","trackType":"spotify","seek":0,"duration":381,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 12 12:00:28 rivoplus volumio[3412]: verbose: CURRENT POSITION 24 May 12 12:00:28 rivoplus volumio[3412]: info: CoreStateMachine::syncState stateService play May 12 12:00:28 rivoplus volumio[3412]: info: CoreStateMachine::syncState currentStatus stop May 12 12:00:29 rivoplus volumio[3412]: info: CoreCommandRouter::volumioPrevious May 12 12:00:29 rivoplus volumio[3412]: info: CoreStateMachine::previous May 12 12:00:29 rivoplus volumio[3412]: info: CorePlayQueue::getTrack 24 May 12 12:00:29 rivoplus volumio[3412]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 12 12:00:29 rivoplus volumio[3412]: TypeError: Cannot read property 'service' of undefined May 12 12:00:29 rivoplus volumio[3412]: at CoreStateMachine.previous (/volumio/app/statemachine.js:1325:97) May 12 12:00:29 rivoplus volumio[3412]: at CoreCommandRouter.volumioPrevious (/volumio/app/index.js:97:28) May 12 12:00:29 rivoplus volumio[3412]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:270:33) May 12 12:00:29 rivoplus volumio[3412]: at Socket.emit (events.js:400:28) May 12 12:00:29 rivoplus volumio[3412]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 May 12 12:00:29 rivoplus volumio[3412]: at processTicksAndRejections (internal/process/task_queues.js:77:11) May 12 12:00:29 rivoplus volumio[3412]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 12 12:00:29 rivoplus sudo[10966]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-12 11:59 May 12 12:00:29 rivoplus sudo[10966]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 30 Apr 2025 11:06:47 AM CEST" VOLUMIO_VERSION="3.807" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="f92ac0ecb6de863dba28fedfed23f19e"