-- Logs begin at Tue 2025-07-08 12:55:01 JST, end at Tue 2025-07-08 14:45:41 JST. -- Jul 08 14:44:00 volumio volumio[1484]: info: CoreStateMachine::startPlaybackTimer Jul 08 14:44:00 volumio volumio[1484]: info: CorePlayQueue::getTrack 1 Jul 08 14:44:00 volumio volumio[1484]: SPOTIFY: PUSH STATE SPOTIFY Jul 08 14:44:00 volumio volumio[1484]: SPOTIFY: {"status":"play","service":"spop","title":"everything i wanted","artist":"Billie Eilish","album":"everything i wanted","albumart":"https://i.scdn.co/image/ab67616d00001e02f2248cf6dad1d6c062587249","uri":"spotify:track:3ZCTVFBt2Brf31RLEnCkWJ","trackType":"spotify","seek":0,"duration":245,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 08 14:44:00 volumio volumio[1484]: info: CoreCommandRouter::servicePushState Jul 08 14:44:00 volumio volumio[1484]: info: CorePlayQueue::getTrack 1 Jul 08 14:44:00 volumio volumio[1484]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"everything i wanted","artist":"Billie Eilish","album":"everything i wanted","albumart":"https://i.scdn.co/image/ab67616d00001e02f2248cf6dad1d6c062587249","uri":"spotify:track:3ZCTVFBt2Brf31RLEnCkWJ","trackType":"spotify","seek":0,"duration":245,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 08 14:44:00 volumio volumio[1484]: verbose: CURRENT POSITION 1 Jul 08 14:44:00 volumio volumio[1484]: info: CoreStateMachine::syncState stateService play Jul 08 14:44:00 volumio volumio[1484]: info: CoreStateMachine::syncState currentStatus play Jul 08 14:44:00 volumio volumio[1484]: info: Received an update from plugin. extracting info from payload Jul 08 14:44:00 volumio volumio[1484]: info: CoreStateMachine::pushState Jul 08 14:44:00 volumio volumio[1484]: info: CorePlayQueue::getTrack 1 Jul 08 14:44:00 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 08 14:44:00 volumio volumio[1484]: info: CoreCommandRouter::volumioPushState Jul 08 14:44:00 volumio volumio[1484]: info: MRS: Pushing multiroomSync output update for this device Jul 08 14:44:00 volumio volumio[1484]: info: MRS: Pushing multiroomSync output Jul 08 14:44:00 volumio volumio[1484]: info: CoreCommandRouter::volumioGetState Jul 08 14:44:00 volumio volumio[1484]: info: CorePlayQueue::getTrack 1 Jul 08 14:44:00 volumio volumio[1484]: info: CoreStateMachine::pushState Jul 08 14:44:00 volumio volumio[1484]: info: CorePlayQueue::getTrack 1 Jul 08 14:44:00 volumio volumio[1484]: info: CoreCommandRouter::volumioPushState Jul 08 14:44:00 volumio volumio[1484]: info: MRS: Pushing multiroomSync output update for this device Jul 08 14:44:00 volumio volumio[1484]: info: MRS: Pushing multiroomSync output Jul 08 14:44:00 volumio volumio[1484]: info: CoreCommandRouter::volumioGetState Jul 08 14:44:00 volumio volumio[1484]: info: CorePlayQueue::getTrack 1 Jul 08 14:44:00 volumio volumio[1484]: info: [ASDebug] CurState: play PrevState: play Jul 08 14:44:00 volumio volumio[1484]: info: [ASDebug] CurState: play PrevState: play Jul 08 14:44:00 volumio volumio[1484]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 08 14:44:00 volumio volumio[1484]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 08 14:44:00 volumio volumio[1484]: info: CoreStateMachine::pushState Jul 08 14:44:00 volumio volumio[1484]: info: CorePlayQueue::getTrack 1 Jul 08 14:44:00 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 08 14:44:00 volumio volumio[1484]: info: CoreCommandRouter::volumioPushState Jul 08 14:44:00 volumio volumio[1484]: info: MRS: Pushing multiroomSync output update for this device Jul 08 14:44:00 volumio volumio[1484]: info: MRS: Pushing multiroomSync output Jul 08 14:44:00 volumio volumio[1484]: info: CoreCommandRouter::volumioGetState Jul 08 14:44:00 volumio volumio[1484]: info: CorePlayQueue::getTrack 1 Jul 08 14:44:00 volumio volumio[1484]: info: [ASDebug] CurState: play PrevState: play Jul 08 14:44:00 volumio volumio[1484]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 08 14:44:12 volumio go-librespot[1697]: time="2025-07-08T14:44:12+09:00" level=trace msg="sent dealer ping" Jul 08 14:44:12 volumio go-librespot[1697]: time="2025-07-08T14:44:12+09:00" level=trace msg="received dealer pong" Jul 08 14:44:14 volumio go-librespot[1697]: time="2025-07-08T14:44:14+09:00" level=debug msg="fetched chunk 4/16, size: 524288" uri="spotify:track:3ZCTVFBt2Brf31RLEnCkWJ" Jul 08 14:44:26 volumio volumio[1484]: info: Preload queue cleared Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::ClearQueue Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::stop Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::stPlaybackTimer Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::updateTrackBlock Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::getTrackBlock Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::pushState Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::getTrack 1 Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::volumioPushState Jul 08 14:44:26 volumio volumio[1484]: info: MRS: Pushing multiroomSync output update for this device Jul 08 14:44:26 volumio volumio[1484]: info: MRS: Pushing multiroomSync output Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::volumioGetState Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::getTrack 1 Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::serviceStop Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::getTrack 1 Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::serviceStop Jul 08 14:44:26 volumio volumio[1484]: info: Spotify Stop Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: SPOTIFY STOP Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: {"status":"play","position":1,"title":"everything i wanted","artist":"Billie Eilish","album":"everything i wanted","albumart":"https://i.scdn.co/image/ab67616d0000b273f2248cf6dad1d6c062587249","uri":"spotify:track:3ZCTVFBt2Brf31RLEnCkWJ","trackType":"spotify","codec":"ogg","seek":250,"duration":245,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jul 08 14:44:26 volumio volumio[1484]: info: Sending Spotify command to local API: /player/pause Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::clearPlayQueue Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::saveQueue Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::volumioPushQueue Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::addQueueItems Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::addQueueItems Jul 08 14:44:26 volumio volumio[1484]: info: Preload queue cleared Jul 08 14:44:26 volumio volumio[1484]: info: Adding Item to queue: spotify:track:4k7x3QKrc3h3U0Viqk0uop Jul 08 14:44:26 volumio volumio[1484]: info: Exploding uri spotify:track:4k7x3QKrc3h3U0Viqk0uop in service spop Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:4k7x3QKrc3h3U0Viqk0uop Jul 08 14:44:26 volumio volumio[1484]: info: [ASDebug] CurState: stop PrevState: play Jul 08 14:44:26 volumio volumio[1484]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="pause track at 25879ms" Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4k7x3QKrc3h3U0Viqk0uop","service":"spop","name":"Rosyln","artist":"Bon Iver","album":"The Twilight Saga: New Moon (Original Motion Picture Soundtrack)","type":"song","duration":289,"albumart":"https://i.scdn.co/image/ab67616d0000b2738cdc3315bbb5331eddf6a21d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::volumioPushQueue Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::saveQueue Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::updateTrackBlock Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::getTrackBlock Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::volumioPlay Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::play index 0 Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::addQueueItems Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::addQueueItems Jul 08 14:44:26 volumio volumio[1484]: info: Preload queue cleared Jul 08 14:44:26 volumio volumio[1484]: info: Adding Item to queue: spotify:track:2qTy3hGSbxoSenKmlKGHFw Jul 08 14:44:26 volumio volumio[1484]: info: Exploding uri spotify:track:2qTy3hGSbxoSenKmlKGHFw in service spop Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:2qTy3hGSbxoSenKmlKGHFw Jul 08 14:44:26 volumio volumio[1484]: info: Adding Item to queue: spotify:track:6Xk5AaN4n4SnW71473GI7A Jul 08 14:44:26 volumio volumio[1484]: info: Exploding uri spotify:track:6Xk5AaN4n4SnW71473GI7A in service spop Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:6Xk5AaN4n4SnW71473GI7A Jul 08 14:44:26 volumio volumio[1484]: info: Adding Item to queue: spotify:track:2ozyU0ouEszNl675sgJjjM Jul 08 14:44:26 volumio volumio[1484]: info: Exploding uri spotify:track:2ozyU0ouEszNl675sgJjjM in service spop Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:2ozyU0ouEszNl675sgJjjM Jul 08 14:44:26 volumio volumio[1484]: info: Adding Item to queue: spotify:track:1kgLXgHrXecZyRCDROfAPb Jul 08 14:44:26 volumio volumio[1484]: info: Exploding uri spotify:track:1kgLXgHrXecZyRCDROfAPb in service spop Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:1kgLXgHrXecZyRCDROfAPb Jul 08 14:44:26 volumio volumio[1484]: info: Adding Item to queue: spotify:track:7F1xUyDoz9vSbwSaCryT5x Jul 08 14:44:26 volumio volumio[1484]: info: Exploding uri spotify:track:7F1xUyDoz9vSbwSaCryT5x in service spop Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:7F1xUyDoz9vSbwSaCryT5x Jul 08 14:44:26 volumio volumio[1484]: info: Adding Item to queue: spotify:track:5IXTT9RvcVupmzLTFqIInj Jul 08 14:44:26 volumio volumio[1484]: info: Exploding uri spotify:track:5IXTT9RvcVupmzLTFqIInj in service spop Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:5IXTT9RvcVupmzLTFqIInj Jul 08 14:44:26 volumio volumio[1484]: info: Adding Item to queue: spotify:track:2rKP4A3wm8b5zLFyqSXCMY Jul 08 14:44:26 volumio volumio[1484]: info: Exploding uri spotify:track:2rKP4A3wm8b5zLFyqSXCMY in service spop Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:2rKP4A3wm8b5zLFyqSXCMY Jul 08 14:44:26 volumio volumio[1484]: info: Adding Item to queue: spotify:track:6TryolYM0MBzNTxGrlfcqt Jul 08 14:44:26 volumio volumio[1484]: info: Exploding uri spotify:track:6TryolYM0MBzNTxGrlfcqt in service spop Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:6TryolYM0MBzNTxGrlfcqt Jul 08 14:44:26 volumio volumio[1484]: info: Adding Item to queue: spotify:track:54IL47Tmp2MAVABIdf6eMF Jul 08 14:44:26 volumio volumio[1484]: info: Exploding uri spotify:track:54IL47Tmp2MAVABIdf6eMF in service spop Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:54IL47Tmp2MAVABIdf6eMF Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::stop Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::play index undefined Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::getTrack 0 Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::startPlaybackTimer Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::getTrack 0 Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::volumioGetVisibleSources Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jul 08 14:44:26 volumio volumio[1484]: info: METAVOLUMIO: Retrieving similar tracks from metavolumio Jul 08 14:44:26 volumio volumio[1484]: info: [1751953466385] ControllerSpotify::clearAddPlayTrack Jul 08 14:44:26 volumio volumio[1484]: info: Sending Spotify command with payload to local API: /player/play Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=trace msg="emitting websocket event: paused" Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3ZCTVFBt2Brf31RLEnCkWJ","play_origin":"go-librespot"}} Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: PUSH STATE SPOTIFY Jul 08 14:44:26 volumio volumio[1484]: 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} Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::servicePushState Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::getTrack 0 Jul 08 14:44:26 volumio volumio[1484]: 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} Jul 08 14:44:26 volumio volumio[1484]: verbose: CURRENT POSITION 0 Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::syncState stateService pause Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::syncState currentStatus stop Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::pushState Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::getTrack 0 Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::volumioPushState Jul 08 14:44:26 volumio volumio[1484]: info: MRS: Pushing multiroomSync output update for this device Jul 08 14:44:26 volumio volumio[1484]: info: MRS: Pushing multiroomSync output Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::volumioGetState Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::getTrack 0 Jul 08 14:44:26 volumio volumio[1484]: info: [ASDebug] CurState: stop PrevState: play Jul 08 14:44:26 volumio volumio[1484]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2qTy3hGSbxoSenKmlKGHFw","service":"spop","name":"Los Ageless","artist":"St. Vincent","album":"MASSEDUCTION","type":"song","duration":281,"albumart":"https://i.scdn.co/image/ab67616d0000b273c5819ccc3fbcd68e3fe0ebd2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2ozyU0ouEszNl675sgJjjM","service":"spop","name":"Tiempos Violentos (feat. Mon Laferte)","artist":"St. Vincent","album":"Tiempos Violentos (feat. Mon Laferte)","type":"song","duration":237,"albumart":"https://i.scdn.co/image/ab67616d0000b27352f86fdfff983f6f1011d3fb","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6Xk5AaN4n4SnW71473GI7A","service":"spop","name":"Fast Slow Disco","artist":"St. Vincent","album":"Fast Slow Disco","type":"song","duration":197,"albumart":"https://i.scdn.co/image/ab67616d0000b273bf59cf03df3b4e1c2d7ada7f","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1kgLXgHrXecZyRCDROfAPb","service":"spop","name":"Broken Man","artist":"St. Vincent","album":"All Born Screaming","type":"song","duration":201,"albumart":"https://i.scdn.co/image/ab67616d0000b273902e9fffc3787dd4fe7678e7","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7F1xUyDoz9vSbwSaCryT5x","service":"spop","name":"Big Time Nothing","artist":"St. Vincent","album":"All Born Screaming","type":"song","duration":178,"albumart":"https://i.scdn.co/image/ab67616d0000b273902e9fffc3787dd4fe7678e7","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="resolved context of track" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6TryolYM0MBzNTxGrlfcqt","service":"spop","name":"Flea","artist":"St. Vincent","album":"All Born Screaming","type":"song","duration":226,"albumart":"https://i.scdn.co/image/ab67616d0000b273902e9fffc3787dd4fe7678e7","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:54IL47Tmp2MAVABIdf6eMF","service":"spop","name":"Hang On Me","artist":"St. Vincent","album":"MASSEDUCTION","type":"song","duration":168,"albumart":"https://i.scdn.co/image/ab67616d0000b273c5819ccc3fbcd68e3fe0ebd2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5IXTT9RvcVupmzLTFqIInj","service":"spop","name":"New York","artist":"St. Vincent","album":"MASSEDUCTION","type":"song","duration":154,"albumart":"https://i.scdn.co/image/ab67616d0000b273c5819ccc3fbcd68e3fe0ebd2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2rKP4A3wm8b5zLFyqSXCMY","service":"spop","name":"The Antidote","artist":"St. Vincent","album":"The Twilight Saga: Breaking Dawn - Part 2 (Original Motion Picture Soundtrack)","type":"song","duration":219,"albumart":"https://i.scdn.co/image/ab67616d0000b27333d6ad1275ae8ebe156686f5","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::volumioPushQueue Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::saveQueue Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::updateTrackBlock Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::getTrackBlock Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=trace msg="emitting websocket event: will_play" Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4k7x3QKrc3h3U0Viqk0uop","play_origin":"go-librespot"}} Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="selected format OGG_VORBIS_320 (07abe7773911489276421d44e2b7c6e59e904a91)" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="requested aes key for file 07abe7773911489276421d44e2b7c6e59e904a91, gid: 4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="fetched first chunk of 20, total size is 10282204 bytes" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09: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" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=info msg="loaded track \"Rosyln\" (paused: false, position: 0ms, duration: 289560ms, prefetched: false)" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=trace msg="scheduling prefetch in 259s" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=trace msg="emitting websocket event: metadata" Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4k7x3QKrc3h3U0Viqk0uop","name":"Rosyln","artist_names":["Bon Iver","St. Vincent"],"album_name":"The Twilight Saga: New Moon (Original Motion Picture Soundtrack)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e028cdc3315bbb5331eddf6a21d","position":0,"duration":289560,"release_date":"year:2009 month:10 day:16","track_number":8,"disc_number":1}} Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 14:44:26 volumio go-librespot[1697]: time="2025-07-08T14:44:26+09:00" level=trace msg="emitting websocket event: playing" Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4k7x3QKrc3h3U0Viqk0uop","play_origin":"go-librespot"}} Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: PUSH STATE SPOTIFY Jul 08 14:44:26 volumio volumio[1484]: SPOTIFY: {"status":"play","service":"spop","title":"Rosyln","artist":"Bon Iver, St. Vincent","album":"The Twilight Saga: New Moon (Original Motion Picture Soundtrack)","albumart":"https://i.scdn.co/image/ab67616d00001e028cdc3315bbb5331eddf6a21d","uri":"spotify:track:4k7x3QKrc3h3U0Viqk0uop","trackType":"spotify","seek":0,"duration":289,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 08 14:44:26 volumio volumio[1484]: info: CoreCommandRouter::servicePushState Jul 08 14:44:26 volumio volumio[1484]: info: CorePlayQueue::getTrack 0 Jul 08 14:44:26 volumio volumio[1484]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Rosyln","artist":"Bon Iver, St. Vincent","album":"The Twilight Saga: New Moon (Original Motion Picture Soundtrack)","albumart":"https://i.scdn.co/image/ab67616d00001e028cdc3315bbb5331eddf6a21d","uri":"spotify:track:4k7x3QKrc3h3U0Viqk0uop","trackType":"spotify","seek":0,"duration":289,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 08 14:44:26 volumio volumio[1484]: verbose: CURRENT POSITION 0 Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::syncState stateService play Jul 08 14:44:26 volumio volumio[1484]: info: CoreStateMachine::syncState currentStatus stop Jul 08 14:44:27 volumio volumio[1484]: info: [ASDebug] Togle GPIO: OFF Jul 08 14:44:27 volumio volumio[1484]: SPOTIFY: PUSH STATE SPOTIFY Jul 08 14:44:27 volumio volumio[1484]: SPOTIFY: {"status":"play","service":"spop","title":"Rosyln","artist":"Bon Iver, St. Vincent","album":"The Twilight Saga: New Moon (Original Motion Picture Soundtrack)","albumart":"https://i.scdn.co/image/ab67616d00001e028cdc3315bbb5331eddf6a21d","uri":"spotify:track:4k7x3QKrc3h3U0Viqk0uop","trackType":"spotify","seek":0,"duration":289,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 08 14:44:27 volumio volumio[1484]: info: CoreCommandRouter::servicePushState Jul 08 14:44:27 volumio volumio[1484]: info: CorePlayQueue::getTrack 0 Jul 08 14:44:27 volumio volumio[1484]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Rosyln","artist":"Bon Iver, St. Vincent","album":"The Twilight Saga: New Moon (Original Motion Picture Soundtrack)","albumart":"https://i.scdn.co/image/ab67616d00001e028cdc3315bbb5331eddf6a21d","uri":"spotify:track:4k7x3QKrc3h3U0Viqk0uop","trackType":"spotify","seek":0,"duration":289,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 08 14:44:27 volumio volumio[1484]: verbose: CURRENT POSITION 0 Jul 08 14:44:27 volumio volumio[1484]: info: CoreStateMachine::syncState stateService play Jul 08 14:44:27 volumio volumio[1484]: info: CoreStateMachine::syncState currentStatus play Jul 08 14:44:27 volumio volumio[1484]: info: Received an update from plugin. extracting info from payload Jul 08 14:44:27 volumio volumio[1484]: info: CoreStateMachine::pushState Jul 08 14:44:27 volumio volumio[1484]: info: CorePlayQueue::getTrack 0 Jul 08 14:44:27 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 08 14:44:27 volumio volumio[1484]: info: CoreCommandRouter::volumioPushState Jul 08 14:44:27 volumio volumio[1484]: info: MRS: Pushing multiroomSync output update for this device Jul 08 14:44:27 volumio volumio[1484]: info: MRS: Pushing multiroomSync output Jul 08 14:44:27 volumio volumio[1484]: info: CoreCommandRouter::volumioGetState Jul 08 14:44:27 volumio volumio[1484]: info: CorePlayQueue::getTrack 0 Jul 08 14:44:27 volumio volumio[1484]: info: CoreStateMachine::pushState Jul 08 14:44:27 volumio volumio[1484]: info: CorePlayQueue::getTrack 0 Jul 08 14:44:27 volumio volumio[1484]: info: CoreCommandRouter::volumioPushState Jul 08 14:44:27 volumio volumio[1484]: info: MRS: Pushing multiroomSync output update for this device Jul 08 14:44:27 volumio volumio[1484]: info: MRS: Pushing multiroomSync output Jul 08 14:44:27 volumio volumio[1484]: info: CoreCommandRouter::volumioGetState Jul 08 14:44:27 volumio volumio[1484]: info: CorePlayQueue::getTrack 0 Jul 08 14:44:27 volumio volumio[1484]: info: [ASDebug] CurState: play PrevState: stop Jul 08 14:44:27 volumio volumio[1484]: info: [ASDebug] Togle GPIO: ON Jul 08 14:44:27 volumio volumio[1484]: info: [ASDebug] CurState: play PrevState: play Jul 08 14:44:27 volumio volumio[1484]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 08 14:44:27 volumio volumio[1484]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 08 14:44:31 volumio volumio[1484]: error: Failed request for metavolumio API Jul 08 14:44:31 volumio volumio[1484]: error: METAVOLUMIO: No similar tracks returned Jul 08 14:44:31 volumio volumio[1484]: error: METAVOLUMIO: No Matched Tracks found, Starting fallback strategies Jul 08 14:44:31 volumio volumio[1484]: info: CoreCommandRouter::volumioGetQueue Jul 08 14:44:31 volumio volumio[1484]: info: CoreStateMachine::getQueue Jul 08 14:44:31 volumio volumio[1484]: info: CorePlayQueue::getQueue Jul 08 14:44:31 volumio volumio[1484]: info: METAVOLUMIO: Executing Random Queue Item Fallback Strategy with index: 5 Jul 08 14:44:31 volumio volumio[1484]: info: CoreCommandRouter::volumioGetVisibleSources Jul 08 14:44:31 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 14:44:31 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jul 08 14:44:31 volumio volumio[1484]: info: METAVOLUMIO: Retrieving similar tracks from metavolumio Jul 08 14:44:39 volumio go-librespot[1697]: time="2025-07-08T14:44:39+09:00" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:44:41 volumio volumio[1484]: info: All cached search sources collected Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: calmradio , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: soundcloud , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 14:44:41 volumio volumio[1484]: info: [1751953481385] ControllerCalmRadio::searchCategories Jul 08 14:44:41 volumio volumio[1484]: info: [1751953481386] ControllerCalmRadio::searchChannels Jul 08 14:44:41 volumio volumio[1484]: info: All cached search sources collected Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: calmradio , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: soundcloud , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 14:44:41 volumio volumio[1484]: info: [1751953481516] ControllerCalmRadio::searchCategories Jul 08 14:44:41 volumio volumio[1484]: info: [1751953481517] ControllerCalmRadio::searchChannels Jul 08 14:44:41 volumio volumio[1484]: info: All cached search sources collected Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: calmradio , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: soundcloud , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 14:44:41 volumio volumio[1484]: info: [1751953481712] ControllerCalmRadio::searchCategories Jul 08 14:44:41 volumio volumio[1484]: info: [1751953481713] ControllerCalmRadio::searchChannels Jul 08 14:44:41 volumio volumio[1484]: info: All cached search sources collected Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: calmradio , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: soundcloud , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 14:44:41 volumio volumio[1484]: info: [1751953481813] ControllerCalmRadio::searchCategories Jul 08 14:44:41 volumio volumio[1484]: info: [1751953481814] ControllerCalmRadio::searchChannels Jul 08 14:44:41 volumio volumio[1484]: info: All cached search sources collected Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: calmradio , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: soundcloud , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 14:44:41 volumio volumio[1484]: info: [1751953481918] ControllerCalmRadio::searchCategories Jul 08 14:44:41 volumio volumio[1484]: info: [1751953481919] ControllerCalmRadio::searchChannels Jul 08 14:44:41 volumio volumio[1484]: info: All cached search sources collected Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: calmradio , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: soundcloud , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jul 08 14:44:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 14:44:42 volumio volumio[1484]: info: [1751953482030] ControllerCalmRadio::searchCategories Jul 08 14:44:42 volumio volumio[1484]: info: [1751953482031] ControllerCalmRadio::searchChannels Jul 08 14:44:42 volumio volumio[1484]: info: All cached search sources collected Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::volumioGetQueue Jul 08 14:44:42 volumio volumio[1484]: info: CoreStateMachine::getQueue Jul 08 14:44:42 volumio volumio[1484]: info: CorePlayQueue::getQueue Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::volumioAddQueueItems Jul 08 14:44:42 volumio volumio[1484]: info: CoreStateMachine::addQueueItems Jul 08 14:44:42 volumio volumio[1484]: info: CorePlayQueue::addQueueItems Jul 08 14:44:42 volumio volumio[1484]: info: Preload queue cleared Jul 08 14:44:42 volumio volumio[1484]: info: Adding Item to queue: spotify:track:3jt1ZVIuluGkV0sWWLSUzw Jul 08 14:44:42 volumio volumio[1484]: info: Exploding uri spotify:track:3jt1ZVIuluGkV0sWWLSUzw in service spop Jul 08 14:44:42 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:3jt1ZVIuluGkV0sWWLSUzw Jul 08 14:44:42 volumio volumio[1484]: info: All cached search sources collected Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: calmradio , search Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: soundcloud , search Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 14:44:42 volumio volumio[1484]: info: [1751953482141] ControllerCalmRadio::searchCategories Jul 08 14:44:42 volumio volumio[1484]: info: [1751953482142] ControllerCalmRadio::searchChannels Jul 08 14:44:42 volumio volumio[1484]: info: All cached search sources collected Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: calmradio , search Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: soundcloud , search Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 14:44:42 volumio volumio[1484]: info: [1751953482259] ControllerCalmRadio::searchCategories Jul 08 14:44:42 volumio volumio[1484]: info: [1751953482260] ControllerCalmRadio::searchChannels Jul 08 14:44:42 volumio go-librespot[1697]: time="2025-07-08T14:44:42+09:00" level=trace msg="sent dealer ping" Jul 08 14:44:42 volumio go-librespot[1697]: time="2025-07-08T14:44:42+09:00" level=trace msg="received dealer pong" Jul 08 14:44:42 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3jt1ZVIuluGkV0sWWLSUzw","service":"spop","name":"Appointments","artist":"Julien Baker","album":"Turn Out the Lights","type":"song","duration":273,"albumart":"https://i.scdn.co/image/ab67616d0000b27355e6251f6f6ffa24f092daac","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:42 volumio volumio[1484]: info: CoreCommandRouter::volumioPushQueue Jul 08 14:44:42 volumio volumio[1484]: info: CorePlayQueue::saveQueue Jul 08 14:44:42 volumio volumio[1484]: info: CoreStateMachine::updateTrackBlock Jul 08 14:44:42 volumio volumio[1484]: info: CorePlayQueue::getTrackBlock Jul 08 14:44:42 volumio volumio[1484]: info: All search sources collected, pushing search results Jul 08 14:44:43 volumio volumio[1484]: info: All search sources collected, pushing search results Jul 08 14:44:43 volumio volumio[1484]: info: CoreCommandRouter::volumioGetQueue Jul 08 14:44:43 volumio volumio[1484]: info: CoreStateMachine::getQueue Jul 08 14:44:43 volumio volumio[1484]: info: CorePlayQueue::getQueue Jul 08 14:44:43 volumio volumio[1484]: info: All search sources collected, pushing search results Jul 08 14:44:43 volumio volumio[1484]: info: All search sources collected, pushing search results Jul 08 14:44:43 volumio volumio[1484]: info: All search sources collected, pushing search results Jul 08 14:44:43 volumio volumio[1484]: info: CoreCommandRouter::volumioGetQueue Jul 08 14:44:43 volumio volumio[1484]: info: CoreStateMachine::getQueue Jul 08 14:44:43 volumio volumio[1484]: info: CorePlayQueue::getQueue Jul 08 14:44:43 volumio volumio[1484]: info: CoreCommandRouter::volumioAddQueueItems Jul 08 14:44:43 volumio volumio[1484]: info: CoreStateMachine::addQueueItems Jul 08 14:44:43 volumio volumio[1484]: info: CorePlayQueue::addQueueItems Jul 08 14:44:43 volumio volumio[1484]: info: Preload queue cleared Jul 08 14:44:43 volumio volumio[1484]: info: Adding Item to queue: spotify:track:5Nhsc59aScz67qNXA0y9Mn Jul 08 14:44:43 volumio volumio[1484]: info: Exploding uri spotify:track:5Nhsc59aScz67qNXA0y9Mn in service spop Jul 08 14:44:43 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:5Nhsc59aScz67qNXA0y9Mn Jul 08 14:44:43 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5Nhsc59aScz67qNXA0y9Mn","service":"spop","name":"Digital Witness","artist":"St. Vincent","album":"St. Vincent","type":"song","duration":202,"albumart":"https://i.scdn.co/image/ab67616d0000b27303bead735d5b6501512117a2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:43 volumio volumio[1484]: info: CoreCommandRouter::volumioPushQueue Jul 08 14:44:43 volumio volumio[1484]: info: CorePlayQueue::saveQueue Jul 08 14:44:43 volumio volumio[1484]: info: CoreStateMachine::updateTrackBlock Jul 08 14:44:43 volumio volumio[1484]: info: CorePlayQueue::getTrackBlock Jul 08 14:44:45 volumio volumio[1484]: info: All search sources collected, pushing search results Jul 08 14:44:45 volumio volumio[1484]: info: CoreCommandRouter::volumioGetQueue Jul 08 14:44:45 volumio volumio[1484]: info: CoreStateMachine::getQueue Jul 08 14:44:45 volumio volumio[1484]: info: CorePlayQueue::getQueue Jul 08 14:44:45 volumio volumio[1484]: info: CoreCommandRouter::volumioAddQueueItems Jul 08 14:44:45 volumio volumio[1484]: info: CoreStateMachine::addQueueItems Jul 08 14:44:45 volumio volumio[1484]: info: CorePlayQueue::addQueueItems Jul 08 14:44:45 volumio volumio[1484]: info: Preload queue cleared Jul 08 14:44:45 volumio volumio[1484]: info: Adding Item to queue: spotify:track:3fIotQ6HWB2zLhpnOs6Tl6 Jul 08 14:44:45 volumio volumio[1484]: info: Exploding uri spotify:track:3fIotQ6HWB2zLhpnOs6Tl6 in service spop Jul 08 14:44:45 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:3fIotQ6HWB2zLhpnOs6Tl6 Jul 08 14:44:45 volumio volumio[1484]: info: All search sources collected, pushing search results Jul 08 14:44:45 volumio volumio[1484]: info: CoreCommandRouter::volumioGetQueue Jul 08 14:44:45 volumio volumio[1484]: info: CoreStateMachine::getQueue Jul 08 14:44:45 volumio volumio[1484]: info: CorePlayQueue::getQueue Jul 08 14:44:45 volumio volumio[1484]: info: CoreCommandRouter::volumioAddQueueItems Jul 08 14:44:45 volumio volumio[1484]: info: CoreStateMachine::addQueueItems Jul 08 14:44:45 volumio volumio[1484]: info: CorePlayQueue::addQueueItems Jul 08 14:44:45 volumio volumio[1484]: info: Preload queue cleared Jul 08 14:44:45 volumio volumio[1484]: info: Adding Item to queue: spotify:track:6FPw780c3azvSQXDuV5Z52 Jul 08 14:44:45 volumio volumio[1484]: info: Exploding uri spotify:track:6FPw780c3azvSQXDuV5Z52 in service spop Jul 08 14:44:45 volumio volumio[1484]: SPOTIFY: EXPLODING URI:spotify:track:6FPw780c3azvSQXDuV5Z52 Jul 08 14:44:45 volumio volumio[1484]: info: All search sources collected, pushing search results Jul 08 14:44:45 volumio volumio[1484]: info: CoreCommandRouter::volumioGetQueue Jul 08 14:44:45 volumio volumio[1484]: info: CoreStateMachine::getQueue Jul 08 14:44:45 volumio volumio[1484]: info: CorePlayQueue::getQueue Jul 08 14:44:45 volumio volumio[1484]: info: METAVOLUMIO: Infinity Playback added 4 Tracks to queue Jul 08 14:44:45 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3fIotQ6HWB2zLhpnOs6Tl6","service":"spop","name":"Rattlesnake","artist":"St. Vincent","album":"St. Vincent (Deluxe Edition)","type":"song","duration":214,"albumart":"https://i.scdn.co/image/ab67616d0000b2735d0cd496494ab309d93c24c2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:45 volumio volumio[1484]: info: CoreCommandRouter::volumioPushQueue Jul 08 14:44:45 volumio volumio[1484]: info: CorePlayQueue::saveQueue Jul 08 14:44:45 volumio volumio[1484]: info: CoreStateMachine::updateTrackBlock Jul 08 14:44:45 volumio volumio[1484]: info: CorePlayQueue::getTrackBlock Jul 08 14:44:45 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6FPw780c3azvSQXDuV5Z52","service":"spop","name":"Cruel","artist":"St. Vincent","album":"Strange Mercy","type":"song","duration":214,"albumart":"https://i.scdn.co/image/ab67616d0000b273194059a08c20b4f39bbb31c7","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:44:45 volumio volumio[1484]: info: CoreCommandRouter::volumioPushQueue Jul 08 14:44:45 volumio volumio[1484]: info: CorePlayQueue::saveQueue Jul 08 14:44:45 volumio volumio[1484]: info: CoreStateMachine::updateTrackBlock Jul 08 14:44:45 volumio volumio[1484]: info: CorePlayQueue::getTrackBlock Jul 08 14:44:53 volumio go-librespot[1697]: time="2025-07-08T14:44:53+09:00" level=debug msg="fetched chunk 5/19, size: 524288" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:45:08 volumio go-librespot[1697]: time="2025-07-08T14:45:08+09:00" level=debug msg="fetched chunk 6/19, size: 524288" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:45:12 volumio go-librespot[1697]: time="2025-07-08T14:45:12+09:00" level=trace msg="sent dealer ping" Jul 08 14:45:12 volumio go-librespot[1697]: time="2025-07-08T14:45:12+09:00" level=trace msg="received dealer pong" Jul 08 14:45:22 volumio go-librespot[1697]: time="2025-07-08T14:45:22+09:00" level=debug msg="fetched chunk 7/19, size: 524288" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:45:34 volumio volumio[1484]: info: Listing playlists Jul 08 14:45:37 volumio go-librespot[1697]: time="2025-07-08T14:45:37+09:00" level=debug msg="fetched chunk 8/19, size: 524288" uri="spotify:track:4k7x3QKrc3h3U0Viqk0uop" Jul 08 14:45:40 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: spop , getTrack Jul 08 14:45:41 volumio volumio[1484]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4k7x3QKrc3h3U0Viqk0uop","service":"spop","name":"Rosyln","artist":"Bon Iver","album":"The Twilight Saga: New Moon (Original Motion Picture Soundtrack)","type":"song","duration":289,"albumart":"https://i.scdn.co/image/ab67616d0000b2738cdc3315bbb5331eddf6a21d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 14:45:41 volumio volumio[1484]: info: Saving Cloud item St. Vincent Jul 08 14:45:41 volumio volumio[1484]: info: CoreCommandRouter::executeOnPlugin: my_volumio , saveCloudItem Jul 08 14:45:41 volumio volumio[1484]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 14:45:41 volumio volumio[1484]: Error: Reference.child failed: First argument was an invalid path = "/user_data/T7EJcqiCJ1SmfLoituTSovzGJCI3/myPlaylists/St. Vincent". Paths must be non-empty strings and can't contain ".", "#", "$", "[", or "]" Jul 08 14:45:41 volumio volumio[1484]: at validatePathString (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:1667:15) Jul 08 14:45:41 volumio volumio[1484]: at validateRootPathString (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:1679:5) Jul 08 14:45:41 volumio volumio[1484]: at Reference.child (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:13737:17) Jul 08 14:45:41 volumio volumio[1484]: at Database.ref (/volumio/node_modules/@firebase/database/dist/index.node.cjs.js:15115:48) Jul 08 14:45:41 volumio volumio[1484]: at myVolumio.syncJSONToCloud (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:28817) Jul 08 14:45:41 volumio volumio[1484]: at myVolumio.saveCloudMyPlaylist (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:23840) Jul 08 14:45:41 volumio volumio[1484]: at myVolumio.saveCloudItem (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:18337) Jul 08 14:45:41 volumio volumio[1484]: at CoreCommandRouter.executeOnPlugin (/volumio/app/index.js:1096:32) Jul 08 14:45:41 volumio volumio[1484]: at PlaylistManager.saveJSONFile (/volumio/app/playlistManager.js:613:31) Jul 08 14:45:41 volumio volumio[1484]: at /volumio/app/playlistManager.js:560:20 Jul 08 14:45:41 volumio volumio[1484]: at /volumio/node_modules/jsonfile/index.js:46:5 Jul 08 14:45:41 volumio volumio[1484]: at /volumio/node_modules/graceful-fs/graceful-fs.js:123:16 Jul 08 14:45:41 volumio volumio[1484]: at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:63:3) Jul 08 14:45:41 volumio volumio[1484]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 14:45:41 volumio sudo[17348]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-08 14:44 Jul 08 14:45:41 volumio sudo[17348]: 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="811ff8312d42f9da0260be1d353081a805678820" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 02 Jul 2025 04:07:25 PM CEST" VOLUMIO_VERSION="3.819" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3b9115b1943141a9d7186aa434f8f3c2"