Dec 23 08:30:23 volumio-erg go-librespot[1633]: time="2025-12-23T08:30:23+02:00" level=trace msg="sent dealer ping" Dec 23 08:30:23 volumio-erg go-librespot[1633]: time="2025-12-23T08:30:23+02:00" level=trace msg="received dealer pong" Dec 23 08:30:48 volumio-erg volumio[1185]: verbose: New Socket.io Connection to 192.168.1.3:3000 from 192.168.1.5 UA: Dart/3.9 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Dec 23 08:30:48 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 23 08:30:48 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 23 08:30:48 volumio-erg volumio[1185]: info: Discovery: Getting this device information Dec 23 08:30:48 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:30:48 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 10 Dec 23 08:30:48 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 23 08:30:51 volumio-erg volumio[1185]: verbose: New Socket.io Connection to 192.168.1.3 from 192.168.1.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_6_2 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Dec 23 08:30:51 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetVisibleSources Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:30:52 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 10 Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 23 08:30:52 volumio-erg volumio[1185]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Dec 23 08:30:52 volumio-erg volumio[1185]: info: Received Get System Info Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 23 08:30:52 volumio-erg volumio[1185]: info: Discovery: Getting this device information Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:30:52 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 10 Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:30:52 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 10 Dec 23 08:30:52 volumio-erg volumio[1185]: info: Listing playlists Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetQueue Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreStateMachine::getQueue Dec 23 08:30:52 volumio-erg volumio[1185]: info: CorePlayQueue::getQueue Dec 23 08:30:52 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 23 08:30:53 volumio-erg go-librespot[1633]: time="2025-12-23T08:30:53+02:00" level=trace msg="sent dealer ping" Dec 23 08:30:53 volumio-erg go-librespot[1633]: time="2025-12-23T08:30:53+02:00" level=trace msg="received dealer pong" Dec 23 08:30:54 volumio-erg volumio[1185]: verbose: New Socket.io Connection to 192.168.1.3:3000 from 192.168.1.5 UA: Dart/3.9 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Dec 23 08:30:54 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 23 08:30:54 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 23 08:30:54 volumio-erg volumio[1185]: info: Discovery: Getting this device information Dec 23 08:30:54 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:30:54 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 10 Dec 23 08:30:54 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 23 08:31:01 volumio-erg volumio[1185]: info: Preload queue cleared Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::ClearQueue Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::stop Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 08:31:01 volumio-erg volumio[1185]: info: CorePlayQueue::clearPlayQueue Dec 23 08:31:01 volumio-erg volumio[1185]: info: CorePlayQueue::saveQueue Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushQueue Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::addQueueItems Dec 23 08:31:01 volumio-erg volumio[1185]: info: CorePlayQueue::addQueueItems Dec 23 08:31:01 volumio-erg volumio[1185]: info: Preload queue cleared Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:0u39Dqlv5V0tQrxqvtmkGd Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:0u39Dqlv5V0tQrxqvtmkGd Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:2ZSjufkjv49aUAZDSgWCU0 Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:2ZSjufkjv49aUAZDSgWCU0 Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:1TqZWopW54JwNYMxr7LCmV Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:1TqZWopW54JwNYMxr7LCmV Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:0xHDLWUrBIsGdiCVzKlPjy Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:0xHDLWUrBIsGdiCVzKlPjy Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:7n87xkMECGC9CoiwCPXYxL Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:7n87xkMECGC9CoiwCPXYxL Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:5B7af2i43MdC8o9FB0svPg Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:5B7af2i43MdC8o9FB0svPg Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:5eNelMQPNMcWnt1jB2gOsV Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:5eNelMQPNMcWnt1jB2gOsV Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:5puI2gKho2X0dWt4gK9zRX Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:5puI2gKho2X0dWt4gK9zRX Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:3qkkQOfWNAsI8QUEKvdphU Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:3qkkQOfWNAsI8QUEKvdphU Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushQueue Dec 23 08:31:01 volumio-erg volumio[1185]: info: CorePlayQueue::saveQueue Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::updateTrackBlock Dec 23 08:31:01 volumio-erg volumio[1185]: info: CorePlayQueue::getTrackBlock Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:31:01 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 10 Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPlay Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::play index 8 Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::addQueueItems Dec 23 08:31:01 volumio-erg volumio[1185]: info: CorePlayQueue::addQueueItems Dec 23 08:31:01 volumio-erg volumio[1185]: info: Preload queue cleared Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:6WUADvdcd7rUFMO7hW2GiU Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:6WUADvdcd7rUFMO7hW2GiU Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:5fIu2Ct1WdzsTlpXpBigfa Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:5fIu2Ct1WdzsTlpXpBigfa Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:3WXCm4NT1A88Cm65cPfe3m Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:3WXCm4NT1A88Cm65cPfe3m Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:2OVvSGxy7x6IhS32DztxTS Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:2OVvSGxy7x6IhS32DztxTS Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:49zy3fg8d7XtDj0dXlkAGd Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:49zy3fg8d7XtDj0dXlkAGd Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:62kPQDtHkx1azc4p5OLzId Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:62kPQDtHkx1azc4p5OLzId Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:1JtqT4H2y12gMJM6aGfKM5 Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:1JtqT4H2y12gMJM6aGfKM5 Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:6S0B7ZoQSKg2s1f1gr79xL Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:6S0B7ZoQSKg2s1f1gr79xL Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:7zz9C4DEuzmd8fzR1fh2Rd Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:7zz9C4DEuzmd8fzR1fh2Rd Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:2xbMFStoCq36qkYWGffArk Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:2xbMFStoCq36qkYWGffArk Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:7usXt2N6GSSdjVdcAi7vLR Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:7usXt2N6GSSdjVdcAi7vLR Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:2BnxkhENEfw61GXvQ7yV2F Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:2BnxkhENEfw61GXvQ7yV2F Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:1tmDWamsA4XR94f2zmTqcP Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:1tmDWamsA4XR94f2zmTqcP Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:33Ez2t468TSlYmuZPTwxRH Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:33Ez2t468TSlYmuZPTwxRH Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:0fsH5NxMhtcfo41WSHRu84 Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:0fsH5NxMhtcfo41WSHRu84 Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:70EhTtU0tA3raVjUrmLIti Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:70EhTtU0tA3raVjUrmLIti Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:2Lf1vsqB5TEIYZYq6jWoAI Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:2Lf1vsqB5TEIYZYq6jWoAI Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:5diT8Vf28DdzQll9ZohbJy Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:5diT8Vf28DdzQll9ZohbJy Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:4O9jDgn1phhCKnbuhiuXcU Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:4O9jDgn1phhCKnbuhiuXcU Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:5EgBtcrVYrmFIasmTh83NT Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:5EgBtcrVYrmFIasmTh83NT Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:28FgJspZCDMVQul17fUL0Y Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:28FgJspZCDMVQul17fUL0Y Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:7BoZqmUqVYlLAIcuiCtFjA Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:7BoZqmUqVYlLAIcuiCtFjA Dec 23 08:31:01 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:463WnhwNkwPBeAgjsbsNz2 Dec 23 08:31:01 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:463WnhwNkwPBeAgjsbsNz2 Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::stop Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushQueue Dec 23 08:31:01 volumio-erg volumio[1185]: info: CorePlayQueue::saveQueue Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::play index undefined Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::updateTrackBlock Dec 23 08:31:01 volumio-erg volumio[1185]: info: CorePlayQueue::getTrackBlock Dec 23 08:31:01 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:01 volumio-erg volumio[1185]: info: CoreStateMachine::startPlaybackTimer Dec 23 08:31:01 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:01 volumio-erg volumio[1185]: info: [1766471461376] ControllerSpotify::clearAddPlayTrack Dec 23 08:31:01 volumio-erg volumio[1185]: info: Sending Spotify command with payload to local API: /player/play Dec 23 08:31:01 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:01+02:00" level=debug msg="resolved context of track" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:01 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:01+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:01 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:01+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:01 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:01+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 08:31:01 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:01+02:00" level=trace msg="emitting websocket event: will_play" Dec 23 08:31:01 volumio-erg volumio[1185]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","play_origin":"go-librespot"}} Dec 23 08:31:01 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:01+02:00" level=debug msg="selected format OGG_VORBIS_320 (f2e96fdd407d0228bf2de021a717aa359922baca)" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:01 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:01+02:00" level=debug msg="requested aes key for file f2e96fdd407d0228bf2de021a717aa359922baca, gid: 3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:01 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:01+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02:00" level=debug msg="fetched first chunk of 21, total size is 10934416 bytes" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02: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, PCM format = FLOAT_LE" Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02:00" level=info msg="loaded track \"The Loving Touch\" (paused: false, position: 0ms, duration: 348733ms, prefetched: false)" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02:00" level=trace msg="scheduling prefetch in 319s" Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02:00" level=trace msg="emitting websocket event: metadata" Dec 23 08:31:02 volumio-erg volumio[1185]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","name":"The Loving Touch","artist_names":["Yoshio Chin Suzuki","Tsuyoshi Yamamoto"],"album_name":"Loving Touch","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0276667016bfb418db75a52b5e","position":0,"duration":348733,"release_date":"year:2020 month:4 day:8","track_number":1,"disc_number":1}} Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02:00" level=trace msg="emitting websocket event: playing" Dec 23 08:31:02 volumio-erg volumio[1185]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","resume":false,"play_origin":"go-librespot"}} Dec 23 08:31:02 volumio-erg volumio[1185]: SPOTIFY: PUSH STATE SPOTIFY Dec 23 08:31:02 volumio-erg volumio[1185]: SPOTIFY: {"status":"play","service":"spop","title":"The Loving Touch","artist":"Yoshio Chin Suzuki, Tsuyoshi Yamamoto","album":"Loving Touch","albumart":"https://i.scdn.co/image/ab67616d00001e0276667016bfb418db75a52b5e","uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","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} Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::servicePushState Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"The Loving Touch","artist":"Yoshio Chin Suzuki, Tsuyoshi Yamamoto","album":"Loving Touch","albumart":"https://i.scdn.co/image/ab67616d00001e0276667016bfb418db75a52b5e","uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","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} Dec 23 08:31:02 volumio-erg volumio[1185]: verbose: CURRENT POSITION 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::syncState stateService play Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::syncState currentStatus stop Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:02 volumio-erg volumio[1185]: info: Preload queue cleared Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::ClearQueue Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::stop Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::stPlaybackTimer Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::updateTrackBlock Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrackBlock Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::pushState Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushState Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:02 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output update for this device Dec 23 08:31:02 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::serviceStop Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::serviceStop Dec 23 08:31:02 volumio-erg volumio[1185]: info: Spotify Stop Dec 23 08:31:02 volumio-erg volumio[1185]: SPOTIFY: SPOTIFY STOP Dec 23 08:31:02 volumio-erg volumio[1185]: SPOTIFY: {"status":"stop","position":10,"title":"Kisses on the Wind","artist":"Yoshio Chin Suzuki","album":"Loving Touch","albumart":"https://i.scdn.co/image/ab67616d0000b27376667016bfb418db75a52b5e","uri":"spotify:track:5fIu2Ct1WdzsTlpXpBigfa","trackType":"spotify","codec":"ogg","seek":250,"duration":375,"samplerate":"320 kbps","bitdepth":"16 bit","random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Dec 23 08:31:02 volumio-erg volumio[1185]: info: Sending Spotify command to local API: /player/pause Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::clearPlayQueue Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::saveQueue Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushQueue Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::addQueueItems Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::addQueueItems Dec 23 08:31:02 volumio-erg volumio[1185]: info: Preload queue cleared Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:0u39Dqlv5V0tQrxqvtmkGd Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:0u39Dqlv5V0tQrxqvtmkGd Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:2ZSjufkjv49aUAZDSgWCU0 Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:2ZSjufkjv49aUAZDSgWCU0 Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:1TqZWopW54JwNYMxr7LCmV Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:1TqZWopW54JwNYMxr7LCmV Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:0xHDLWUrBIsGdiCVzKlPjy Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:0xHDLWUrBIsGdiCVzKlPjy Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:7n87xkMECGC9CoiwCPXYxL Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:7n87xkMECGC9CoiwCPXYxL Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:5B7af2i43MdC8o9FB0svPg Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:5B7af2i43MdC8o9FB0svPg Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:5eNelMQPNMcWnt1jB2gOsV Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:5eNelMQPNMcWnt1jB2gOsV Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:5puI2gKho2X0dWt4gK9zRX Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:5puI2gKho2X0dWt4gK9zRX Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:3qkkQOfWNAsI8QUEKvdphU Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:3qkkQOfWNAsI8QUEKvdphU Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushQueue Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::saveQueue Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::updateTrackBlock Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrackBlock Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPlay Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::play index 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::addQueueItems Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::addQueueItems Dec 23 08:31:02 volumio-erg volumio[1185]: info: Preload queue cleared Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:6WUADvdcd7rUFMO7hW2GiU Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:6WUADvdcd7rUFMO7hW2GiU Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:5fIu2Ct1WdzsTlpXpBigfa Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:5fIu2Ct1WdzsTlpXpBigfa Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:3WXCm4NT1A88Cm65cPfe3m Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:3WXCm4NT1A88Cm65cPfe3m Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:2OVvSGxy7x6IhS32DztxTS Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:2OVvSGxy7x6IhS32DztxTS Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:49zy3fg8d7XtDj0dXlkAGd Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:49zy3fg8d7XtDj0dXlkAGd Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:62kPQDtHkx1azc4p5OLzId Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:62kPQDtHkx1azc4p5OLzId Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:1JtqT4H2y12gMJM6aGfKM5 Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:1JtqT4H2y12gMJM6aGfKM5 Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:6S0B7ZoQSKg2s1f1gr79xL Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:6S0B7ZoQSKg2s1f1gr79xL Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:7zz9C4DEuzmd8fzR1fh2Rd Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:7zz9C4DEuzmd8fzR1fh2Rd Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:2xbMFStoCq36qkYWGffArk Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:2xbMFStoCq36qkYWGffArk Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:7usXt2N6GSSdjVdcAi7vLR Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:7usXt2N6GSSdjVdcAi7vLR Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:2BnxkhENEfw61GXvQ7yV2F Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:2BnxkhENEfw61GXvQ7yV2F Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:1tmDWamsA4XR94f2zmTqcP Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:1tmDWamsA4XR94f2zmTqcP Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:33Ez2t468TSlYmuZPTwxRH Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:33Ez2t468TSlYmuZPTwxRH Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:0fsH5NxMhtcfo41WSHRu84 Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:0fsH5NxMhtcfo41WSHRu84 Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:70EhTtU0tA3raVjUrmLIti Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:70EhTtU0tA3raVjUrmLIti Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:2Lf1vsqB5TEIYZYq6jWoAI Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:2Lf1vsqB5TEIYZYq6jWoAI Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:5diT8Vf28DdzQll9ZohbJy Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:5diT8Vf28DdzQll9ZohbJy Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:4O9jDgn1phhCKnbuhiuXcU Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:4O9jDgn1phhCKnbuhiuXcU Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:5EgBtcrVYrmFIasmTh83NT Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:5EgBtcrVYrmFIasmTh83NT Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:28FgJspZCDMVQul17fUL0Y Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:28FgJspZCDMVQul17fUL0Y Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:7BoZqmUqVYlLAIcuiCtFjA Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:7BoZqmUqVYlLAIcuiCtFjA Dec 23 08:31:02 volumio-erg volumio[1185]: info: Adding Item to queue: spotify:track:463WnhwNkwPBeAgjsbsNz2 Dec 23 08:31:02 volumio-erg volumio[1185]: info: Using cached record of: spotify:track:463WnhwNkwPBeAgjsbsNz2 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::stop Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushQueue Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::saveQueue Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::play index undefined Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::updateTrackBlock Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrackBlock Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::startPlaybackTimer Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: [1766471462751] ControllerSpotify::clearAddPlayTrack Dec 23 08:31:02 volumio-erg volumio[1185]: info: Sending Spotify command with payload to local API: /player/play Dec 23 08:31:02 volumio-erg volumio[1185]: SPOTIFY: PUSH STATE SPOTIFY Dec 23 08:31:02 volumio-erg volumio[1185]: SPOTIFY: {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::servicePushState Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::pushState Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushState Dec 23 08:31:02 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output update for this device Dec 23 08:31:02 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: verbose: STATE SERVICE {"status":"stop","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 23 08:31:02 volumio-erg volumio[1185]: verbose: CURRENT POSITION 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::syncState stateService stop Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::syncState currentStatus stop Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::pushState Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushState Dec 23 08:31:02 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output update for this device Dec 23 08:31:02 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: No code Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreStateMachine::pushState Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushState Dec 23 08:31:02 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output update for this device Dec 23 08:31:02 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output Dec 23 08:31:02 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:31:02 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02:00" level=debug msg="pause track at 535ms" Dec 23 08:31:02 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=trace msg="emitting websocket event: paused" Dec 23 08:31:03 volumio-erg volumio[1185]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","play_origin":"go-librespot"}} Dec 23 08:31:03 volumio-erg volumio[1185]: SPOTIFY: PUSH STATE SPOTIFY Dec 23 08:31:03 volumio-erg volumio[1185]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 23 08:31:03 volumio-erg volumio[1185]: info: CoreCommandRouter::servicePushState Dec 23 08:31:03 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:03 volumio-erg volumio[1185]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 23 08:31:03 volumio-erg volumio[1185]: verbose: CURRENT POSITION 8 Dec 23 08:31:03 volumio-erg volumio[1185]: info: CoreStateMachine::syncState stateService pause Dec 23 08:31:03 volumio-erg volumio[1185]: info: CoreStateMachine::syncState currentStatus stop Dec 23 08:31:03 volumio-erg volumio[1185]: info: CoreStateMachine::pushState Dec 23 08:31:03 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:03 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 23 08:31:03 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushState Dec 23 08:31:03 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output update for this device Dec 23 08:31:03 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output Dec 23 08:31:03 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:31:03 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=debug msg="resolved context of track" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=trace msg="emitting websocket event: will_play" Dec 23 08:31:03 volumio-erg volumio[1185]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","play_origin":"go-librespot"}} Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=debug msg="selected format OGG_VORBIS_320 (f2e96fdd407d0228bf2de021a717aa359922baca)" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=debug msg="requested aes key for file f2e96fdd407d0228bf2de021a717aa359922baca, gid: 3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=debug msg="fetched first chunk of 21, total size is 10934416 bytes" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02: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, PCM format = FLOAT_LE" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=info msg="loaded track \"The Loving Touch\" (paused: false, position: 0ms, duration: 348733ms, prefetched: false)" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=trace msg="scheduling prefetch in 319s" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=trace msg="emitting websocket event: metadata" Dec 23 08:31:03 volumio-erg volumio[1185]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","name":"The Loving Touch","artist_names":["Yoshio Chin Suzuki","Tsuyoshi Yamamoto"],"album_name":"Loving Touch","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0276667016bfb418db75a52b5e","position":0,"duration":348733,"release_date":"year:2020 month:4 day:8","track_number":1,"disc_number":1}} Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=trace msg="emitting websocket event: playing" Dec 23 08:31:03 volumio-erg volumio[1185]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","resume":false,"play_origin":"go-librespot"}} Dec 23 08:31:03 volumio-erg volumio[1185]: SPOTIFY: PUSH STATE SPOTIFY Dec 23 08:31:03 volumio-erg volumio[1185]: SPOTIFY: {"status":"play","service":"spop","title":"The Loving Touch","artist":"Yoshio Chin Suzuki, Tsuyoshi Yamamoto","album":"Loving Touch","albumart":"https://i.scdn.co/image/ab67616d00001e0276667016bfb418db75a52b5e","uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","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} Dec 23 08:31:03 volumio-erg volumio[1185]: info: CoreCommandRouter::servicePushState Dec 23 08:31:03 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:03 volumio-erg volumio[1185]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"The Loving Touch","artist":"Yoshio Chin Suzuki, Tsuyoshi Yamamoto","album":"Loving Touch","albumart":"https://i.scdn.co/image/ab67616d00001e0276667016bfb418db75a52b5e","uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","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} Dec 23 08:31:03 volumio-erg volumio[1185]: verbose: CURRENT POSITION 8 Dec 23 08:31:03 volumio-erg volumio[1185]: info: CoreStateMachine::syncState stateService play Dec 23 08:31:03 volumio-erg volumio[1185]: info: CoreStateMachine::syncState currentStatus stop Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:03 volumio-erg go-librespot[1633]: time="2025-12-23T08:31:03+02:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:3qkkQOfWNAsI8QUEKvdphU" Dec 23 08:31:04 volumio-erg volumio[1185]: SPOTIFY: PUSH STATE SPOTIFY Dec 23 08:31:04 volumio-erg volumio[1185]: SPOTIFY: {"status":"play","service":"spop","title":"The Loving Touch","artist":"Yoshio Chin Suzuki, Tsuyoshi Yamamoto","album":"Loving Touch","albumart":"https://i.scdn.co/image/ab67616d00001e0276667016bfb418db75a52b5e","uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","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} Dec 23 08:31:04 volumio-erg volumio[1185]: info: CoreCommandRouter::servicePushState Dec 23 08:31:04 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:04 volumio-erg volumio[1185]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"The Loving Touch","artist":"Yoshio Chin Suzuki, Tsuyoshi Yamamoto","album":"Loving Touch","albumart":"https://i.scdn.co/image/ab67616d00001e0276667016bfb418db75a52b5e","uri":"spotify:track:3qkkQOfWNAsI8QUEKvdphU","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} Dec 23 08:31:04 volumio-erg volumio[1185]: verbose: CURRENT POSITION 8 Dec 23 08:31:04 volumio-erg volumio[1185]: info: CoreStateMachine::syncState stateService play Dec 23 08:31:04 volumio-erg volumio[1185]: info: CoreStateMachine::syncState currentStatus play Dec 23 08:31:04 volumio-erg volumio[1185]: info: Received an update from plugin. extracting info from payload Dec 23 08:31:04 volumio-erg volumio[1185]: info: CoreStateMachine::pushState Dec 23 08:31:04 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:04 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 23 08:31:04 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushState Dec 23 08:31:04 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output update for this device Dec 23 08:31:04 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output Dec 23 08:31:04 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:31:04 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:04 volumio-erg volumio[1185]: info: CoreStateMachine::pushState Dec 23 08:31:04 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:04 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioPushState Dec 23 08:31:04 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output update for this device Dec 23 08:31:04 volumio-erg volumio[1185]: info: MRS: Pushing multiroomSync output Dec 23 08:31:04 volumio-erg volumio[1185]: info: CoreCommandRouter::volumioGetState Dec 23 08:31:04 volumio-erg volumio[1185]: info: CorePlayQueue::getTrack 8 Dec 23 08:31:04 volumio-erg volumio[1185]: error: touch_display: Error waking up the screen: Error: Command failed: /usr/bin/xset -display : s reset dpms force on Dec 23 08:31:04 volumio-erg volumio[1185]: /usr/bin/xset: unable to open display ":" Dec 23 08:31:04 volumio-erg volumio[1185]: error: touch_display: Error setting screensaver timeout: Error: ENOENT: no such file or directory, stat '/tmp/.X11-unix/X' Dec 23 08:31:10 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 23 08:31:10 volumio-erg volumio[1185]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 23 08:31:14 volumio-erg volumio[1185]: info: Starting Uninstall of plugin user_interface - touch_display Dec 23 08:31:14 volumio-erg volumio[1185]: info: Uninstalling plugin touch_display Dec 23 08:31:14 volumio-erg sudo[5002]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/95-touch_display-plugin.conf Dec 23 08:31:14 volumio-erg sudo[5004]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start getty@tty1.service Dec 23 08:31:14 volumio-erg sudo[5002]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 08:31:14 volumio-erg sudo[5004]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 08:31:14 volumio-erg sudo[5002]: pam_unix(sudo:session): session closed for user root Dec 23 08:31:14 volumio-erg volumio[1185]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/95-touch_display-plugin.conf set. Dec 23 08:31:14 volumio-erg sudo[5006]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl enable getty@tty1.service Dec 23 08:31:14 volumio-erg sudo[5006]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 08:31:14 volumio-erg sudo[5008]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumio-kiosk.service Dec 23 08:31:14 volumio-erg sudo[5008]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 23 08:31:14 volumio-erg volumio[1185]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 23 08:31:14 volumio-erg volumio[1185]: TypeError: Cannot read properties of undefined (reading 'split') Dec 23 08:31:14 volumio-erg volumio[1185]: at /data/plugins/user_interface/touch_display/index.js:1298:37 Dec 23 08:31:14 volumio-erg volumio[1185]: at ChildProcess.exithandler (node:child_process:413:7) Dec 23 08:31:14 volumio-erg volumio[1185]: at ChildProcess.emit (node:events:514:28) Dec 23 08:31:14 volumio-erg volumio[1185]: at maybeClose (node:internal/child_process:1105:16) Dec 23 08:31:14 volumio-erg volumio[1185]: at ChildProcess._handle.onexit (node:internal/child_process:305:5) Dec 23 08:31:14 volumio-erg volumio[1185]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 23 08:31:14 volumio-erg systemd[1]: Reloading. Dec 23 08:31:16 volumio-erg systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 23 08:31:16 volumio-erg systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 23 08:31:16 volumio-erg systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 23 08:31:16 volumio-erg systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 23 08:31:16 volumio-erg sudo[5006]: pam_unix(sudo:session): session closed for user root Dec 23 08:31:17 volumio-erg systemd[1]: Created slice system-getty.slice - Slice /system/getty. Dec 23 08:31:17 volumio-erg systemd[1]: Started getty@tty1.service - Getty on tty1. Dec 23 08:31:17 volumio-erg sudo[5004]: pam_unix(sudo:session): session closed for user root Dec 23 08:31:17 volumio-erg sudo[5008]: pam_unix(sudo:session): session closed for user root Dec 23 08:31:17 volumio-erg sudo[5063]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-23 08:30' Dec 23 08:31:17 volumio-erg sudo[5063]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"