-- Logs begin at Fri 2025-06-06 18:43:13 EEST, end at Tue 2025-06-10 09:13:34 EEST. -- Jun 10 09:12:05 volumio go-librespot[1865]: time="2025-06-10T09:12:05+03:00" level=trace msg="sent dealer ping" Jun 10 09:12:05 volumio go-librespot[1865]: time="2025-06-10T09:12:05+03:00" level=trace msg="received dealer pong" Jun 10 09:12:11 volumio volumio[1057]: info: [jellyfin-poller-worker] _doPoll(): All servers polled. Will poll again in 30000ms. Jun 10 09:12:27 volumio sudo[20546]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 10 09:12:27 volumio sudo[20544]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 10 09:12:27 volumio sudo[20544]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 10 09:12:27 volumio sudo[20546]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 10 09:12:27 volumio sudo[20544]: pam_unix(sudo:session): session closed for user root Jun 10 09:12:27 volumio sudo[20546]: pam_unix(sudo:session): session closed for user root Jun 10 09:12:27 volumio volumio[1057]: verbose: New Socket.io Connection to 10.0.80.14 from 10.0.80.21 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Jun 10 09:12:27 volumio sudo[20550]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 10 09:12:27 volumio sudo[20550]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 10 09:12:27 volumio sudo[20550]: pam_unix(sudo:session): session closed for user root Jun 10 09:12:27 volumio sudo[20553]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 10 09:12:27 volumio sudo[20553]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 10 09:12:27 volumio sudo[20553]: pam_unix(sudo:session): session closed for user root Jun 10 09:12:27 volumio volumio[1057]: verbose: New Socket.io Connection to 10.0.80.14 from 10.0.80.21 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::volumioGetVisibleSources Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::volumioGetQueue Jun 10 09:12:28 volumio volumio[1057]: info: CoreStateMachine::getQueue Jun 10 09:12:28 volumio volumio[1057]: info: CorePlayQueue::getQueue Jun 10 09:12:28 volumio volumio[1057]: info: Listing playlists Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 10 09:12:28 volumio volumio[1057]: info: Received Get System Info Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 10 09:12:28 volumio volumio[1057]: info: Discovery: Getting this device information Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 10 09:12:28 volumio volumio[1057]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 10 09:12:29 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jun 10 09:12:29 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 10 09:12:29 volumio volumio[1057]: info: Received Get System Info Jun 10 09:12:29 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 10 09:12:29 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 10 09:12:29 volumio volumio[1057]: info: Discovery: Getting this device information Jun 10 09:12:29 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Jun 10 09:12:29 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 10 09:12:31 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 10 09:12:31 volumio volumio[1057]: info: Received Get System Info Jun 10 09:12:31 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 10 09:12:31 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 10 09:12:31 volumio volumio[1057]: info: Discovery: Getting this device information Jun 10 09:12:31 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Jun 10 09:12:31 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 10 09:12:35 volumio go-librespot[1865]: time="2025-06-10T09:12:35+03:00" level=trace msg="sent dealer ping" Jun 10 09:12:35 volumio go-librespot[1865]: time="2025-06-10T09:12:35+03:00" level=trace msg="received dealer pong" Jun 10 09:12:37 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 10 09:12:40 volumio volumio[1057]: info: Preload queue cleared Jun 10 09:12:40 volumio volumio[1057]: info: CoreCommandRouter::volumioReplaceandPlayItems Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::ClearQueue Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::stop Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::stPlaybackTimer Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::updateTrackBlock Jun 10 09:12:40 volumio volumio[1057]: info: CorePlayQueue::getTrackBlock Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::pushState Jun 10 09:12:40 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Jun 10 09:12:40 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 09:12:40 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::serviceStop Jun 10 09:12:40 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Jun 10 09:12:40 volumio volumio[1057]: info: CoreCommandRouter::serviceStop Jun 10 09:12:40 volumio volumio[1057]: info: [1749535960077] ControllerWebradio::stop Jun 10 09:12:40 volumio volumio[1057]: verbose: ControllerMpd::sendMpdCommand stop Jun 10 09:12:40 volumio volumio[1057]: info: CorePlayQueue::clearPlayQueue Jun 10 09:12:40 volumio volumio[1057]: info: CorePlayQueue::saveQueue Jun 10 09:12:40 volumio volumio[1057]: info: CoreCommandRouter::volumioPushQueue Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::addQueueItems Jun 10 09:12:40 volumio volumio[1057]: info: CorePlayQueue::addQueueItems Jun 10 09:12:40 volumio volumio[1057]: info: Preload queue cleared Jun 10 09:12:40 volumio volumio[1057]: info: Adding Item to queue: spotify:track:4bVH9n88EDVLVJEcpzVy2z Jun 10 09:12:40 volumio volumio[1057]: info: Exploding uri spotify:track:4bVH9n88EDVLVJEcpzVy2z in service spop Jun 10 09:12:40 volumio volumio[1057]: SPOTIFY: EXPLODING URI:spotify:track:4bVH9n88EDVLVJEcpzVy2z Jun 10 09:12:40 volumio volumio[1057]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jun 10 09:12:40 volumio volumio[1057]: SPOTIFY: RECEIVED VOLUMIO VOLUME 19 Jun 10 09:12:40 volumio volumio[1057]: info: New access token = BQBjieViH40r_vPCqoU4mALBc5kTLVstBzVK2_g1NDXOyOk84pNyhmWupYjmmFydmp8pO0lIowiV679KQ2fcKyJbE5hOOvKuu9oM6ACiQg0e_7PGqLZLJ5JlLia7hfO_54UbJ81WfQrnblovO46RBzQjRvccWdwi7KTrYxDhfYW-Tritw_hPvtVF-iLpeayS-tC_cygIAV4V9BZU6xYzW4cakOKpMQ1BEyVghVg9f3he8_nWnOJDW0Y51verFTt0OGyEPY2pkY8bUGnVUW7z6reo Jun 10 09:12:40 volumio volumio[1057]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4bVH9n88EDVLVJEcpzVy2z","service":"spop","name":"Ο Αλήτης","artist":"MelodyLab","album":"Ο Αλήτης","type":"song","duration":163,"albumart":"https://i.scdn.co/image/ab67616d0000b27358329aefc45202703008e0fc","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 10 09:12:40 volumio volumio[1057]: info: CoreCommandRouter::volumioPushQueue Jun 10 09:12:40 volumio volumio[1057]: info: CorePlayQueue::saveQueue Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::updateTrackBlock Jun 10 09:12:40 volumio volumio[1057]: info: CorePlayQueue::getTrackBlock Jun 10 09:12:40 volumio volumio[1057]: info: CoreCommandRouter::volumioPlay Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::play index 0 Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::addQueueItems Jun 10 09:12:40 volumio volumio[1057]: info: CorePlayQueue::addQueueItems Jun 10 09:12:40 volumio volumio[1057]: info: Preload queue cleared Jun 10 09:12:40 volumio volumio[1057]: info: Adding Item to queue: spotify:track:2I9wJ5aB10lVw6b5fae2Ib Jun 10 09:12:40 volumio volumio[1057]: info: Exploding uri spotify:track:2I9wJ5aB10lVw6b5fae2Ib in service spop Jun 10 09:12:40 volumio volumio[1057]: SPOTIFY: EXPLODING URI:spotify:track:2I9wJ5aB10lVw6b5fae2Ib Jun 10 09:12:40 volumio volumio[1057]: info: Adding Item to queue: spotify:track:5GIrqMQl3Eq0GP6oyHPcW6 Jun 10 09:12:40 volumio volumio[1057]: info: Exploding uri spotify:track:5GIrqMQl3Eq0GP6oyHPcW6 in service spop Jun 10 09:12:40 volumio volumio[1057]: SPOTIFY: EXPLODING URI:spotify:track:5GIrqMQl3Eq0GP6oyHPcW6 Jun 10 09:12:40 volumio volumio[1057]: info: Adding Item to queue: spotify:track:6dSxlCy7yWA6WrhkwebA3N Jun 10 09:12:40 volumio volumio[1057]: info: Exploding uri spotify:track:6dSxlCy7yWA6WrhkwebA3N in service spop Jun 10 09:12:40 volumio volumio[1057]: SPOTIFY: EXPLODING URI:spotify:track:6dSxlCy7yWA6WrhkwebA3N Jun 10 09:12:40 volumio volumio[1057]: info: Adding Item to queue: spotify:track:7erLLE04cL867iWS4Sx9Y5 Jun 10 09:12:40 volumio volumio[1057]: info: Exploding uri spotify:track:7erLLE04cL867iWS4Sx9Y5 in service spop Jun 10 09:12:40 volumio volumio[1057]: SPOTIFY: EXPLODING URI:spotify:track:7erLLE04cL867iWS4Sx9Y5 Jun 10 09:12:40 volumio volumio[1057]: info: Adding Item to queue: spotify:track:6bed5ET4I168rfi7zfUaAE Jun 10 09:12:40 volumio volumio[1057]: info: Exploding uri spotify:track:6bed5ET4I168rfi7zfUaAE in service spop Jun 10 09:12:40 volumio volumio[1057]: SPOTIFY: EXPLODING URI:spotify:track:6bed5ET4I168rfi7zfUaAE Jun 10 09:12:40 volumio volumio[1057]: info: Adding Item to queue: spotify:track:3I9StIyIvgcxK9BYgvVXZH Jun 10 09:12:40 volumio volumio[1057]: info: Exploding uri spotify:track:3I9StIyIvgcxK9BYgvVXZH in service spop Jun 10 09:12:40 volumio volumio[1057]: SPOTIFY: EXPLODING URI:spotify:track:3I9StIyIvgcxK9BYgvVXZH Jun 10 09:12:40 volumio volumio[1057]: info: Adding Item to queue: spotify:track:2xp1hPnYNbrSUQxV2ocNya Jun 10 09:12:40 volumio volumio[1057]: info: Exploding uri spotify:track:2xp1hPnYNbrSUQxV2ocNya in service spop Jun 10 09:12:40 volumio volumio[1057]: SPOTIFY: EXPLODING URI:spotify:track:2xp1hPnYNbrSUQxV2ocNya Jun 10 09:12:40 volumio volumio[1057]: info: Adding Item to queue: spotify:track:26lcIvCD6tB1BmbYAIsyjt Jun 10 09:12:40 volumio volumio[1057]: info: Exploding uri spotify:track:26lcIvCD6tB1BmbYAIsyjt in service spop Jun 10 09:12:40 volumio volumio[1057]: SPOTIFY: EXPLODING URI:spotify:track:26lcIvCD6tB1BmbYAIsyjt Jun 10 09:12:40 volumio volumio[1057]: info: Adding Item to queue: spotify:track:12mVAzkdPtXSDA0etgPC2V Jun 10 09:12:40 volumio volumio[1057]: info: Exploding uri spotify:track:12mVAzkdPtXSDA0etgPC2V in service spop Jun 10 09:12:40 volumio volumio[1057]: SPOTIFY: EXPLODING URI:spotify:track:12mVAzkdPtXSDA0etgPC2V Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::stop Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::play index undefined Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 10 09:12:40 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Jun 10 09:12:40 volumio volumio[1057]: info: CoreStateMachine::startPlaybackTimer Jun 10 09:12:40 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Jun 10 09:12:40 volumio volumio[1057]: info: [1749535960820] ControllerSpotify::clearAddPlayTrack Jun 10 09:12:40 volumio volumio[1057]: info: Sending Spotify command with payload to local API: /player/play Jun 10 09:12:40 volumio go-librespot[1865]: time="2025-06-10T09:12:40+03:00" level=debug msg="renewing login5 access token" Jun 10 09:12:41 volumio volumio[1057]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2I9wJ5aB10lVw6b5fae2Ib","service":"spop","name":"Έρωτας Upbeat","artist":"MelodyLab","album":"This is MelodyLab !","type":"song","duration":154,"albumart":"https://i.scdn.co/image/ab67616d0000b273bdd83f8733f4613b5d2c111c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 10 09:12:41 volumio volumio[1057]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6bed5ET4I168rfi7zfUaAE","service":"spop","name":"Γρηγόρης και Έλενα","artist":"MelodyLab","album":"This is MelodyLab !","type":"song","duration":182,"albumart":"https://i.scdn.co/image/ab67616d0000b273bdd83f8733f4613b5d2c111c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 10 09:12:41 volumio volumio[1057]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3I9StIyIvgcxK9BYgvVXZH","service":"spop","name":"Του Κυριάκου το εργαστήριο","artist":"MelodyLab","album":"This is MelodyLab !","type":"song","duration":79,"albumart":"https://i.scdn.co/image/ab67616d0000b273bdd83f8733f4613b5d2c111c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 10 09:12:41 volumio volumio[1057]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:26lcIvCD6tB1BmbYAIsyjt","service":"spop","name":"Οι μέρες κυλούν","artist":"MelodyLab","album":"This is MelodyLab !","type":"song","duration":212,"albumart":"https://i.scdn.co/image/ab67616d0000b273bdd83f8733f4613b5d2c111c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 10 09:12:41 volumio go-librespot[1865]: time="2025-06-10T09:12:41+03:00" level=info msg="authenticated Login5 as 11181942269" Jun 10 09:12:41 volumio volumio[1057]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2xp1hPnYNbrSUQxV2ocNya","service":"spop","name":"Jurito","artist":"MelodyLab","album":"This is MelodyLab !","type":"song","duration":239,"albumart":"https://i.scdn.co/image/ab67616d0000b273bdd83f8733f4613b5d2c111c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 10 09:12:41 volumio volumio[1057]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:12mVAzkdPtXSDA0etgPC2V","service":"spop","name":"Ο Δημητράκης είναι 5","artist":"MelodyLab","album":"This is MelodyLab !","type":"song","duration":240,"albumart":"https://i.scdn.co/image/ab67616d0000b273bdd83f8733f4613b5d2c111c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 10 09:12:41 volumio volumio[1057]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6dSxlCy7yWA6WrhkwebA3N","service":"spop","name":"Κώστας Φραγκιαδούλης ο Υδραυλικός","artist":"MelodyLab","album":"This is MelodyLab !","type":"song","duration":197,"albumart":"https://i.scdn.co/image/ab67616d0000b273bdd83f8733f4613b5d2c111c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 10 09:12:41 volumio volumio[1057]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5GIrqMQl3Eq0GP6oyHPcW6","service":"spop","name":"Η ΜΑΝΑ","artist":"MelodyLab","album":"Η ΜΑΝΑ","type":"song","duration":193,"albumart":"https://i.scdn.co/image/ab67616d0000b27370c777c4907143ca908f7940","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 10 09:12:41 volumio volumio[1057]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7erLLE04cL867iWS4Sx9Y5","service":"spop","name":"Έλα κοντά μου","artist":"MelodyLab","album":"This is MelodyLab !","type":"song","duration":162,"albumart":"https://i.scdn.co/image/ab67616d0000b273bdd83f8733f4613b5d2c111c","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jun 10 09:12:41 volumio volumio[1057]: info: CoreCommandRouter::volumioPushQueue Jun 10 09:12:41 volumio volumio[1057]: info: CorePlayQueue::saveQueue Jun 10 09:12:41 volumio volumio[1057]: info: CoreStateMachine::updateTrackBlock Jun 10 09:12:41 volumio volumio[1057]: info: CorePlayQueue::getTrackBlock Jun 10 09:12:41 volumio volumio[1057]: info: Jun 10 09:12:41 volumio volumio[1057]: ---------------------------- MPD announces state update: player Jun 10 09:12:41 volumio volumio[1057]: info: sendMpdCommand stop took 1076 milliseconds Jun 10 09:12:41 volumio volumio[1057]: info: ControllerMpd::getState Jun 10 09:12:41 volumio volumio[1057]: verbose: ControllerMpd::sendMpdCommand status Jun 10 09:12:41 volumio volumio[1057]: info: Jun 10 09:12:41 volumio volumio[1057]: ---------------------------- MPD announces state update: player Jun 10 09:12:41 volumio volumio[1057]: info: ControllerMpd::getState Jun 10 09:12:41 volumio volumio[1057]: verbose: ControllerMpd::sendMpdCommand status Jun 10 09:12:41 volumio volumio[1057]: info: FusionDsp - eq1: Jun 10 09:12:41 volumio volumio[1057]: type: Biquad Jun 10 09:12:41 volumio volumio[1057]: parameters: Jun 10 09:12:41 volumio volumio[1057]: type: Lowshelf Jun 10 09:12:41 volumio volumio[1057]: freq: 185 Jun 10 09:12:41 volumio volumio[1057]: q: 0.82 Jun 10 09:12:41 volumio volumio[1057]: gain: 0 Jun 10 09:12:41 volumio volumio[1057]: eq2: Jun 10 09:12:41 volumio volumio[1057]: type: Biquad Jun 10 09:12:41 volumio volumio[1057]: parameters: Jun 10 09:12:41 volumio volumio[1057]: type: Peaking Jun 10 09:12:41 volumio volumio[1057]: freq: 1300 Jun 10 09:12:41 volumio volumio[1057]: q: 0.4 Jun 10 09:12:41 volumio volumio[1057]: gain: 0 Jun 10 09:12:41 volumio volumio[1057]: eq3: Jun 10 09:12:41 volumio volumio[1057]: type: Biquad Jun 10 09:12:41 volumio volumio[1057]: parameters: Jun 10 09:12:41 volumio volumio[1057]: type: Highshelf Jun 10 09:12:41 volumio volumio[1057]: freq: 5500 Jun 10 09:12:41 volumio volumio[1057]: q: 0.82 Jun 10 09:12:41 volumio volumio[1057]: gain: 0 Jun 10 09:12:41 volumio volumio[1057]: info: sendMpdCommand status took 16 milliseconds Jun 10 09:12:41 volumio volumio[1057]: info: sendMpdCommand status took 15 milliseconds Jun 10 09:12:41 volumio volumio[1057]: verbose: ControllerMpd::parseState Jun 10 09:12:41 volumio volumio[1057]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 09:12:41 volumio volumio[1057]: verbose: ControllerMpd::parseState Jun 10 09:12:41 volumio volumio[1057]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 09:12:41 volumio volumio[1057]: info: sendMpdCommand playlistinfo took 2 milliseconds Jun 10 09:12:41 volumio volumio[1057]: info: sendMpdCommand playlistinfo took 2 milliseconds Jun 10 09:12:41 volumio volumio[1057]: verbose: ControllerMpd::parseTrackInfo Jun 10 09:12:41 volumio volumio[1057]: verbose: ControllerMpd::parseTrackInfo Jun 10 09:12:41 volumio volumio[1057]: info: ControllerMpd::pushState Jun 10 09:12:41 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Jun 10 09:12:41 volumio go-librespot[1865]: time="2025-06-10T09:12:41+03:00" level=debug msg="resolved context of track" uri="spotify:track:4bVH9n88EDVLVJEcpzVy2z" Jun 10 09:12:41 volumio go-librespot[1865]: time="2025-06-10T09:12:41+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4bVH9n88EDVLVJEcpzVy2z" Jun 10 09:12:41 volumio go-librespot[1865]: time="2025-06-10T09:12:41+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4bVH9n88EDVLVJEcpzVy2z" Jun 10 09:12:41 volumio volumio[1057]: info: CoreStateMachine::pushState Jun 10 09:12:41 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Jun 10 09:12:41 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 09:12:41 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Jun 10 09:12:41 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Jun 10 09:12:41 volumio volumio[1057]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Jun 10 09:12:41 volumio volumio[1057]: info: ControllerMpd::pushState Jun 10 09:12:41 volumio volumio[1057]: info: CoreCommandRouter::servicePushState Jun 10 09:12:41 volumio volumio[1057]: info: CoreStateMachine::pushState Jun 10 09:12:41 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Jun 10 09:12:41 volumio volumio[1057]: info: CoreCommandRouter::volumioPushState Jun 10 09:12:41 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Jun 10 09:12:41 volumio volumio[1057]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Jun 10 09:12:41 volumio volumio[1057]: info: ------------------------------ 40ms Jun 10 09:12:41 volumio volumio[1057]: info: ------------------------------ 38ms Jun 10 09:12:41 volumio volumio[1057]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jun 10 09:12:41 volumio volumio[1057]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jun 10 09:12:41 volumio volumio[1057]: SPOTIFY: RECEIVED VOLUMIO VOLUME 19 Jun 10 09:12:41 volumio volumio[1057]: SPOTIFY: RECEIVED VOLUMIO VOLUME 19 Jun 10 09:12:41 volumio volumio[1057]: error: FusionDsp - WebSocket error: [object Object] Jun 10 09:12:41 volumio go-librespot[1865]: time="2025-06-10T09:12:41+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 10 09:12:41 volumio go-librespot[1865]: time="2025-06-10T09:12:41+03:00" level=trace msg="emitting websocket event: will_play" Jun 10 09:12:41 volumio volumio[1057]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4bVH9n88EDVLVJEcpzVy2z","play_origin":"go-librespot"}} Jun 10 09:12:41 volumio go-librespot[1865]: time="2025-06-10T09:12:41+03:00" level=debug msg="selected format OGG_VORBIS_320 (48dd7b32c2aa80d390e1cead777d37029d563ab6)" uri="spotify:track:4bVH9n88EDVLVJEcpzVy2z" Jun 10 09:12:41 volumio go-librespot[1865]: time="2025-06-10T09:12:41+03:00" level=debug msg="requested aes key for file 48dd7b32c2aa80d390e1cead777d37029d563ab6, gid: 4bVH9n88EDVLVJEcpzVy2z" Jun 10 09:12:41 volumio volumio[1057]: info: [jellyfin-poller-worker] _doPoll(): All servers polled. Will poll again in 30000ms. Jun 10 09:12:41 volumio go-librespot[1865]: time="2025-06-10T09:12:41+03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4bVH9n88EDVLVJEcpzVy2z: failed retrieving audio key: failed retrieving aes key with code 1" Jun 10 09:12:41 volumio volumio[1057]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Jun 10 09:12:42 volumio volumio[1057]: info: FusionDsp - eq1: Jun 10 09:12:42 volumio volumio[1057]: type: Biquad Jun 10 09:12:42 volumio volumio[1057]: parameters: Jun 10 09:12:42 volumio volumio[1057]: type: Lowshelf Jun 10 09:12:42 volumio volumio[1057]: freq: 185 Jun 10 09:12:42 volumio volumio[1057]: q: 0.82 Jun 10 09:12:42 volumio volumio[1057]: gain: 0 Jun 10 09:12:42 volumio volumio[1057]: eq2: Jun 10 09:12:42 volumio volumio[1057]: type: Biquad Jun 10 09:12:42 volumio volumio[1057]: parameters: Jun 10 09:12:42 volumio volumio[1057]: type: Peaking Jun 10 09:12:42 volumio volumio[1057]: freq: 1300 Jun 10 09:12:42 volumio volumio[1057]: q: 0.4 Jun 10 09:12:42 volumio volumio[1057]: gain: 0 Jun 10 09:12:42 volumio volumio[1057]: eq3: Jun 10 09:12:42 volumio volumio[1057]: type: Biquad Jun 10 09:12:42 volumio volumio[1057]: parameters: Jun 10 09:12:42 volumio volumio[1057]: type: Highshelf Jun 10 09:12:42 volumio volumio[1057]: freq: 5500 Jun 10 09:12:42 volumio volumio[1057]: q: 0.82 Jun 10 09:12:42 volumio volumio[1057]: gain: 0 Jun 10 09:12:42 volumio volumio[1057]: info: FusionDsp - eq1: Jun 10 09:12:42 volumio volumio[1057]: type: Biquad Jun 10 09:12:42 volumio volumio[1057]: parameters: Jun 10 09:12:42 volumio volumio[1057]: type: Lowshelf Jun 10 09:12:42 volumio volumio[1057]: freq: 185 Jun 10 09:12:42 volumio volumio[1057]: q: 0.82 Jun 10 09:12:42 volumio volumio[1057]: gain: 0 Jun 10 09:12:42 volumio volumio[1057]: eq2: Jun 10 09:12:42 volumio volumio[1057]: type: Biquad Jun 10 09:12:42 volumio volumio[1057]: parameters: Jun 10 09:12:42 volumio volumio[1057]: type: Peaking Jun 10 09:12:42 volumio volumio[1057]: freq: 1300 Jun 10 09:12:42 volumio volumio[1057]: q: 0.4 Jun 10 09:12:42 volumio volumio[1057]: gain: 0 Jun 10 09:12:42 volumio volumio[1057]: eq3: Jun 10 09:12:42 volumio volumio[1057]: type: Biquad Jun 10 09:12:42 volumio volumio[1057]: parameters: Jun 10 09:12:42 volumio volumio[1057]: type: Highshelf Jun 10 09:12:42 volumio volumio[1057]: freq: 5500 Jun 10 09:12:42 volumio volumio[1057]: q: 0.82 Jun 10 09:12:42 volumio volumio[1057]: gain: 0 Jun 10 09:12:42 volumio volumio[1057]: error: FusionDsp - WebSocket error: [object Object] Jun 10 09:12:44 volumio volumio[1057]: info: CoreCommandRouter::volumioPlay Jun 10 09:12:44 volumio volumio[1057]: info: CoreStateMachine::play index undefined Jun 10 09:12:44 volumio volumio[1057]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 10 09:12:44 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Jun 10 09:12:44 volumio volumio[1057]: info: CoreStateMachine::startPlaybackTimer Jun 10 09:12:44 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Jun 10 09:12:44 volumio volumio[1057]: info: [1749535964033] ControllerSpotify::clearAddPlayTrack Jun 10 09:12:44 volumio volumio[1057]: info: Sending Spotify command with payload to local API: /player/play Jun 10 09:12:44 volumio go-librespot[1865]: time="2025-06-10T09:12:44+03:00" level=debug msg="resolved context of track" uri="spotify:track:4bVH9n88EDVLVJEcpzVy2z" Jun 10 09:12:44 volumio go-librespot[1865]: time="2025-06-10T09:12:44+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4bVH9n88EDVLVJEcpzVy2z" Jun 10 09:12:44 volumio go-librespot[1865]: time="2025-06-10T09:12:44+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4bVH9n88EDVLVJEcpzVy2z" Jun 10 09:12:44 volumio go-librespot[1865]: time="2025-06-10T09:12:44+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 10 09:12:44 volumio go-librespot[1865]: time="2025-06-10T09:12:44+03:00" level=trace msg="emitting websocket event: will_play" Jun 10 09:12:44 volumio volumio[1057]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4bVH9n88EDVLVJEcpzVy2z","play_origin":"go-librespot"}} Jun 10 09:12:44 volumio go-librespot[1865]: time="2025-06-10T09:12:44+03:00" level=debug msg="selected format OGG_VORBIS_320 (48dd7b32c2aa80d390e1cead777d37029d563ab6)" uri="spotify:track:4bVH9n88EDVLVJEcpzVy2z" Jun 10 09:12:44 volumio go-librespot[1865]: time="2025-06-10T09:12:44+03:00" level=debug msg="requested aes key for file 48dd7b32c2aa80d390e1cead777d37029d563ab6, gid: 4bVH9n88EDVLVJEcpzVy2z" Jun 10 09:12:44 volumio go-librespot[1865]: time="2025-06-10T09:12:44+03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:4bVH9n88EDVLVJEcpzVy2z: failed retrieving audio key: failed retrieving aes key with code 1" Jun 10 09:12:44 volumio volumio[1057]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Jun 10 09:12:46 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 10 09:12:46 volumio volumio[1057]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jun 10 09:12:46 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jun 10 09:12:46 volumio volumio[1057]: info: Received Get System Version Jun 10 09:12:46 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 10 09:12:46 volumio volumio[1057]: info: Received Get System Info Jun 10 09:12:46 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 10 09:12:46 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 10 09:12:46 volumio volumio[1057]: info: Discovery: Getting this device information Jun 10 09:12:46 volumio volumio[1057]: info: CoreCommandRouter::volumioGetState Jun 10 09:12:46 volumio volumio[1057]: info: CorePlayQueue::getTrack 0 Jun 10 09:12:46 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 10 09:13:02 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 10 09:13:02 volumio volumio[1057]: info: Preload queue cleared Jun 10 09:13:05 volumio go-librespot[1865]: time="2025-06-10T09:13:05+03:00" level=trace msg="sent dealer ping" Jun 10 09:13:05 volumio go-librespot[1865]: time="2025-06-10T09:13:05+03:00" level=trace msg="received dealer pong" Jun 10 09:13:07 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 10 09:13:07 volumio volumio[1057]: info: Preload queue cleared Jun 10 09:13:11 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 10 09:13:11 volumio volumio[1057]: info: Preload queue cleared Jun 10 09:13:11 volumio volumio[1057]: info: [jellyfin-poller-worker] _doPoll(): All servers polled. Will poll again in 30000ms. Jun 10 09:13:21 volumio go-librespot[1865]: time="2025-06-10T09:13:21+03:00" level=trace msg="received accesspoint ping" Jun 10 09:13:22 volumio go-librespot[1865]: time="2025-06-10T09:13:22+03:00" level=trace msg="received accesspoint pong ack" Jun 10 09:13:32 volumio volumio[1057]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jun 10 09:13:33 volumio volumio[1057]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 10 09:13:33 volumio volumio[1057]: TypeError: Cannot read property 'length' of undefined Jun 10 09:13:33 volumio volumio[1057]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Jun 10 09:13:33 volumio volumio[1057]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Jun 10 09:13:33 volumio volumio[1057]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Jun 10 09:13:33 volumio volumio[1057]: at Parser.emit (events.js:315:20) Jun 10 09:13:33 volumio volumio[1057]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Jun 10 09:13:33 volumio volumio[1057]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Jun 10 09:13:33 volumio volumio[1057]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Jun 10 09:13:33 volumio volumio[1057]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Jun 10 09:13:33 volumio volumio[1057]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Jun 10 09:13:33 volumio volumio[1057]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Jun 10 09:13:33 volumio volumio[1057]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Jun 10 09:13:33 volumio volumio[1057]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Jun 10 09:13:33 volumio volumio[1057]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Jun 10 09:13:33 volumio volumio[1057]: at IncomingMessage.emit (events.js:327:22) Jun 10 09:13:33 volumio volumio[1057]: at endReadableNT (internal/streams/readable.js:1327:12) Jun 10 09:13:33 volumio volumio[1057]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jun 10 09:13:33 volumio volumio[1057]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 10 09:13:34 volumio sudo[20730]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-10 09:12 Jun 10 09:13:34 volumio sudo[20730]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"