-- Logs begin at Wed 2024-10-30 15:29:03 +07, end at Wed 2024-10-30 15:35:37 +07. -- Oct 30 15:34:12 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 30 15:34:12 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 30 15:34:12 volumio volumio[947]: info: Discovery: Getting this device information Oct 30 15:34:12 volumio volumio[947]: info: CoreCommandRouter::volumioGetState Oct 30 15:34:12 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 30 15:34:15 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Oct 30 15:34:15 volumio volumio[947]: info: In handleBrowseUri, curUri=spotify:album:0tC4C7slhnBFgBsN5jCbnx Oct 30 15:34:15 volumio volumio[947]: info: Preload queue cleared Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:58A085gOcvysnGgsLq74Am Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:5SFJyEXkXrEnx2ThxdsnpV Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:6DKYJxRaBum5cJTJCshHhB Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:2I2UyZ9yDXDfIOrsWD07p6 Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:6ULacK46OsGy4AMlb44KaQ Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:0ZDpbo6BVCYvGV8cP6DiZ4 Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:1E7ppxojRzv9WXonhbjeYh Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:2nwPJWzIEinIJNd7EoAN1e Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:5suQx370V6HgaPsKQshpiN Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:2fEe4vIGQhj1StTANFyBnz Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:3DFGJzPya0OtvmS2zOxRgJ Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:2r2UwP45rFV5lEMtLUIdUg Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:1GMeuiQQmo5Ejz1pV9BKXV Oct 30 15:34:15 volumio volumio[947]: info: Preloading song: spotify:track:36s0Xok3lIXY16ygUjU7f7 Oct 30 15:34:15 volumio volumio[947]: info: Exploding uri spotify:track:58A085gOcvysnGgsLq74Am in service spop Oct 30 15:34:15 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:58A085gOcvysnGgsLq74Am Oct 30 15:34:15 volumio volumio[947]: info: Exploding uri spotify:track:5SFJyEXkXrEnx2ThxdsnpV in service spop Oct 30 15:34:15 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:5SFJyEXkXrEnx2ThxdsnpV Oct 30 15:34:15 volumio volumio[947]: info: Exploding uri spotify:track:6DKYJxRaBum5cJTJCshHhB in service spop Oct 30 15:34:15 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:6DKYJxRaBum5cJTJCshHhB Oct 30 15:34:15 volumio volumio[947]: info: No valid Plugin REST Endpoint Oct 30 15:34:15 volumio volumio[947]: info: No valid Plugin REST Endpoint Oct 30 15:34:15 volumio volumio[947]: info: No valid Plugin REST Endpoint Oct 30 15:34:15 volumio volumio[947]: info: Exploding uri spotify:track:2I2UyZ9yDXDfIOrsWD07p6 in service spop Oct 30 15:34:15 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:2I2UyZ9yDXDfIOrsWD07p6 Oct 30 15:34:15 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:58A085gOcvysnGgsLq74Am","service":"spop","name":"Đáp Án Của Bạn - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":206,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:15 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5SFJyEXkXrEnx2ThxdsnpV","service":"spop","name":"Ba La Boom - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":324,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:15 volumio volumio[947]: info: Exploding uri spotify:track:6ULacK46OsGy4AMlb44KaQ in service spop Oct 30 15:34:15 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:6ULacK46OsGy4AMlb44KaQ Oct 30 15:34:15 volumio volumio[947]: info: Exploding uri spotify:track:0ZDpbo6BVCYvGV8cP6DiZ4 in service spop Oct 30 15:34:15 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:0ZDpbo6BVCYvGV8cP6DiZ4 Oct 30 15:34:15 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6DKYJxRaBum5cJTJCshHhB","service":"spop","name":"ALSY Love Me - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":317,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:16 volumio volumio[947]: info: Exploding uri spotify:track:1E7ppxojRzv9WXonhbjeYh in service spop Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:1E7ppxojRzv9WXonhbjeYh Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2I2UyZ9yDXDfIOrsWD07p6","service":"spop","name":"Không Cần Gì Ngoài Em - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":290,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6ULacK46OsGy4AMlb44KaQ","service":"spop","name":"The Moon - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":159,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:16 volumio volumio[947]: info: Exploding uri spotify:track:2nwPJWzIEinIJNd7EoAN1e in service spop Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:2nwPJWzIEinIJNd7EoAN1e Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0ZDpbo6BVCYvGV8cP6DiZ4","service":"spop","name":"Lạnh Lẽo - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":390,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:16 volumio volumio[947]: info: Exploding uri spotify:track:5suQx370V6HgaPsKQshpiN in service spop Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:5suQx370V6HgaPsKQshpiN Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1E7ppxojRzv9WXonhbjeYh","service":"spop","name":"Girl Don't Cry - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":336,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:16 volumio volumio[947]: info: Exploding uri spotify:track:2fEe4vIGQhj1StTANFyBnz in service spop Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:2fEe4vIGQhj1StTANFyBnz Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2nwPJWzIEinIJNd7EoAN1e","service":"spop","name":"My Love - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":334,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:16 volumio volumio[947]: info: Exploding uri spotify:track:3DFGJzPya0OtvmS2zOxRgJ in service spop Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:3DFGJzPya0OtvmS2zOxRgJ Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5suQx370V6HgaPsKQshpiN","service":"spop","name":"Flowers - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":339,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:16 volumio volumio[947]: info: Exploding uri spotify:track:2r2UwP45rFV5lEMtLUIdUg in service spop Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:2r2UwP45rFV5lEMtLUIdUg Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2fEe4vIGQhj1StTANFyBnz","service":"spop","name":"Tatu - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":270,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:16 volumio volumio[947]: info: Exploding uri spotify:track:1GMeuiQQmo5Ejz1pV9BKXV in service spop Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:1GMeuiQQmo5Ejz1pV9BKXV Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3DFGJzPya0OtvmS2zOxRgJ","service":"spop","name":"Lollipop - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":258,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:16 volumio volumio[947]: info: Exploding uri spotify:track:36s0Xok3lIXY16ygUjU7f7 in service spop Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:track:36s0Xok3lIXY16ygUjU7f7 Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:2r2UwP45rFV5lEMtLUIdUg","service":"spop","name":"Another Song - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":264,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1GMeuiQQmo5Ejz1pV9BKXV","service":"spop","name":"We Like To Dance - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":244,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:16 volumio volumio[947]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:36s0Xok3lIXY16ygUjU7f7","service":"spop","name":"Lost In Love - Thái Hoàng Remix","artist":"Thái Hoàng","album":"Thái Hoàng Vinahouse (Part 1)","type":"song","duration":239,"albumart":"https://i.scdn.co/image/ab67616d0000b27370de2c8131eff1de0bb234b0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 30 15:34:19 volumio volumio[947]: info: Preload queue cleared Oct 30 15:34:19 volumio volumio[947]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::ClearQueue Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::stop Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::serviceStop Oct 30 15:34:19 volumio volumio[947]: info: CoreCommandRouter::serviceStop Oct 30 15:34:19 volumio volumio[947]: info: Airplay Stop Oct 30 15:34:19 volumio volumio[947]: info: Stopping Airplay Playback and sending pause command to client via USR2 Oct 30 15:34:19 volumio volumio[947]: info: CorePlayQueue::clearPlayQueue Oct 30 15:34:19 volumio volumio[947]: info: CorePlayQueue::saveQueue Oct 30 15:34:19 volumio volumio[947]: info: CoreCommandRouter::volumioPushQueue Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::addQueueItems Oct 30 15:34:19 volumio volumio[947]: info: CorePlayQueue::addQueueItems Oct 30 15:34:19 volumio volumio[947]: info: Preload queue cleared Oct 30 15:34:19 volumio volumio[947]: info: Adding Item to queue: spotify:album:0tC4C7slhnBFgBsN5jCbnx Oct 30 15:34:19 volumio volumio[947]: info: Exploding uri spotify:album:0tC4C7slhnBFgBsN5jCbnx in service spop Oct 30 15:34:19 volumio volumio[947]: SPOTIFY: EXPLODING URI:spotify:album:0tC4C7slhnBFgBsN5jCbnx Oct 30 15:34:19 volumio sudo[2213]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/kill -USR2 1632 Oct 30 15:34:19 volumio sudo[2213]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 15:34:19 volumio sudo[2213]: pam_unix(sudo:session): session closed for user root Oct 30 15:34:19 volumio volumio[947]: info: Shairport-Sync paused with USR2 Oct 30 15:34:19 volumio volumio[947]: info: CoreCommandRouter::volumioPushQueue Oct 30 15:34:19 volumio volumio[947]: info: CorePlayQueue::saveQueue Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::updateTrackBlock Oct 30 15:34:19 volumio volumio[947]: info: CorePlayQueue::getTrackBlock Oct 30 15:34:19 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:34:19 volumio volumio[947]: verbose: UNSET VOLATILE: Service: airplay_emulation Oct 30 15:34:19 volumio volumio[947]: info: Stopping Airplay Playback and sending pause command to client via USR2 Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::play index 0 Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::stop Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::stPlaybackTimer Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::updateTrackBlock Oct 30 15:34:19 volumio volumio[947]: info: CorePlayQueue::getTrackBlock Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:34:19 volumio volumio[947]: info: CorePlayQueue::getTrack 50 Oct 30 15:34:19 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 15:34:19 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::serviceStop Oct 30 15:34:19 volumio volumio[947]: info: CorePlayQueue::getTrack 50 Oct 30 15:34:19 volumio volumio[947]: info: ControllerMpd::stop Oct 30 15:34:19 volumio volumio[947]: verbose: ControllerMpd::sendMpdCommand stop Oct 30 15:34:19 volumio sudo[2217]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/kill -USR2 1632 Oct 30 15:34:19 volumio sudo[2217]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 15:34:19 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 30 15:34:19 volumio volumio[947]: info: sendMpdCommand stop took 47 milliseconds Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:19 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:19 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:19 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:19 volumio volumio[947]: info: [1730277259984] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:19 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:19 volumio sudo[2217]: pam_unix(sudo:session): session closed for user root Oct 30 15:34:20 volumio volumio[947]: info: Shairport-Sync paused with USR2 Oct 30 15:34:20 volumio go-librespot[1536]: time="2024-10-30T15:34:20+07:00" level=debug msg="resolved context of track" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:20 volumio go-librespot[1536]: time="2024-10-30T15:34:20+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:20 volumio go-librespot[1536]: time="2024-10-30T15:34:20+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:20 volumio go-librespot[1536]: time="2024-10-30T15:34:20+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:20 volumio go-librespot[1536]: time="2024-10-30T15:34:20+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:20 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:58A085gOcvysnGgsLq74Am","play_origin":"go-librespot"}} Oct 30 15:34:20 volumio go-librespot[1536]: time="2024-10-30T15:34:20+07:00" level=debug msg="selected format OGG_VORBIS_320 (a059aaa8b76f2a5d2f2287e1c41174e0cf2eefc5)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:20 volumio go-librespot[1536]: time="2024-10-30T15:34:20+07:00" level=debug msg="requested aes key for file a059aaa8b76f2a5d2f2287e1c41174e0cf2eefc5, gid: 58A085gOcvysnGgsLq74Am" Oct 30 15:34:20 volumio go-librespot[1536]: time="2024-10-30T15:34:20+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:58A085gOcvysnGgsLq74Am: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:20 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:20 volumio volumio[947]: info: camilladsp spawned new process with pid 2219, instance 1, run: true Oct 30 15:34:20 volumio volumio[947]: info: Restarting Shairport-Sync after stop Oct 30 15:34:20 volumio sudo[2227]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 30 15:34:20 volumio sudo[2227]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 15:34:20 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 30 15:34:20 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 30 15:34:20 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 30 15:34:20 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 30 15:34:20 volumio sudo[2227]: pam_unix(sudo:session): session closed for user root Oct 30 15:34:20 volumio volumio[947]: info: Shairport-Sync retarted Oct 30 15:34:21 volumio volumio[947]: info: Restarting Shairport-Sync after stop Oct 30 15:34:21 volumio sudo[2233]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 30 15:34:21 volumio sudo[2233]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 15:34:21 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 30 15:34:21 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 30 15:34:21 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 30 15:34:21 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 30 15:34:21 volumio sudo[2233]: pam_unix(sudo:session): session closed for user root Oct 30 15:34:21 volumio volumio[947]: info: Shairport-Sync retarted Oct 30 15:34:21 volumio volumio[947]: info: VolumeController::SetAlsaVolume- Oct 30 15:34:21 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:34:21 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:21 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 15:34:21 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:34:21 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 99 Oct 30 15:34:21 volumio volumio[947]: SPOTIFY: SPOTIFY VOLUME 100 Oct 30 15:34:21 volumio volumio[947]: SPOTIFY: VOLUMIO VOLUME 99 Oct 30 15:34:21 volumio volumio[947]: SPOTIFY: DELTA VOLUME ENOUGH: false Oct 30 15:34:27 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:34:27 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:27 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:27 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:27 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:27 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:27 volumio volumio[947]: info: [1730277267314] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:27 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:27 volumio go-librespot[1536]: time="2024-10-30T15:34:27+07:00" level=debug msg="resolved context of track" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:27 volumio go-librespot[1536]: time="2024-10-30T15:34:27+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:27 volumio go-librespot[1536]: time="2024-10-30T15:34:27+07:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:27 volumio go-librespot[1536]: time="2024-10-30T15:34:27+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:27 volumio go-librespot[1536]: time="2024-10-30T15:34:27+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:27 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:58A085gOcvysnGgsLq74Am","play_origin":"go-librespot"}} Oct 30 15:34:27 volumio go-librespot[1536]: time="2024-10-30T15:34:27+07:00" level=debug msg="selected format OGG_VORBIS_320 (a059aaa8b76f2a5d2f2287e1c41174e0cf2eefc5)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:27 volumio go-librespot[1536]: time="2024-10-30T15:34:27+07:00" level=debug msg="requested aes key for file a059aaa8b76f2a5d2f2287e1c41174e0cf2eefc5, gid: 58A085gOcvysnGgsLq74Am" Oct 30 15:34:27 volumio go-librespot[1536]: time="2024-10-30T15:34:27+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:58A085gOcvysnGgsLq74Am: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:27 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:33 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:34:33 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:33 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:33 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:33 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:33 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:33 volumio volumio[947]: info: [1730277273172] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:33 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:33 volumio go-librespot[1536]: time="2024-10-30T15:34:33+07:00" level=debug msg="resolved context of track" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:33 volumio go-librespot[1536]: time="2024-10-30T15:34:33+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:33 volumio go-librespot[1536]: time="2024-10-30T15:34:33+07:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:33 volumio go-librespot[1536]: time="2024-10-30T15:34:33+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:33 volumio go-librespot[1536]: time="2024-10-30T15:34:33+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:33 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:58A085gOcvysnGgsLq74Am","play_origin":"go-librespot"}} Oct 30 15:34:33 volumio go-librespot[1536]: time="2024-10-30T15:34:33+07:00" level=debug msg="selected format OGG_VORBIS_320 (a059aaa8b76f2a5d2f2287e1c41174e0cf2eefc5)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:33 volumio go-librespot[1536]: time="2024-10-30T15:34:33+07:00" level=debug msg="requested aes key for file a059aaa8b76f2a5d2f2287e1c41174e0cf2eefc5, gid: 58A085gOcvysnGgsLq74Am" Oct 30 15:34:33 volumio go-librespot[1536]: time="2024-10-30T15:34:33+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:58A085gOcvysnGgsLq74Am: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:33 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:34 volumio volumio[947]: info: Preload queue cleared Oct 30 15:34:34 volumio volumio[947]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 30 15:34:34 volumio volumio[947]: info: CoreStateMachine::ClearQueue Oct 30 15:34:34 volumio volumio[947]: info: CoreStateMachine::stop Oct 30 15:34:34 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:34 volumio volumio[947]: info: CorePlayQueue::clearPlayQueue Oct 30 15:34:34 volumio volumio[947]: info: CorePlayQueue::saveQueue Oct 30 15:34:34 volumio volumio[947]: info: CoreCommandRouter::volumioPushQueue Oct 30 15:34:34 volumio volumio[947]: info: CoreStateMachine::addQueueItems Oct 30 15:34:34 volumio volumio[947]: info: CorePlayQueue::addQueueItems Oct 30 15:34:34 volumio volumio[947]: info: Preload queue cleared Oct 30 15:34:34 volumio volumio[947]: info: Adding Item to queue: spotify:album:0tC4C7slhnBFgBsN5jCbnx Oct 30 15:34:34 volumio volumio[947]: info: Using cached record of: spotify:album:0tC4C7slhnBFgBsN5jCbnx Oct 30 15:34:34 volumio volumio[947]: info: CoreCommandRouter::volumioPushQueue Oct 30 15:34:34 volumio volumio[947]: info: CorePlayQueue::saveQueue Oct 30 15:34:34 volumio volumio[947]: info: CoreStateMachine::updateTrackBlock Oct 30 15:34:34 volumio volumio[947]: info: CorePlayQueue::getTrackBlock Oct 30 15:34:34 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:34:34 volumio volumio[947]: info: CoreStateMachine::play index 0 Oct 30 15:34:34 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:34 volumio volumio[947]: info: CoreStateMachine::stop Oct 30 15:34:34 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:34 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:34 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:34 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:34 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:34 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:34 volumio volumio[947]: info: [1730277274782] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:34 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:34 volumio go-librespot[1536]: time="2024-10-30T15:34:34+07:00" level=debug msg="resolved context of track" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:34 volumio go-librespot[1536]: time="2024-10-30T15:34:34+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:34 volumio go-librespot[1536]: time="2024-10-30T15:34:34+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:34 volumio go-librespot[1536]: time="2024-10-30T15:34:34+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:34 volumio go-librespot[1536]: time="2024-10-30T15:34:34+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:34 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:58A085gOcvysnGgsLq74Am","play_origin":"go-librespot"}} Oct 30 15:34:34 volumio go-librespot[1536]: time="2024-10-30T15:34:34+07:00" level=debug msg="selected format OGG_VORBIS_320 (a059aaa8b76f2a5d2f2287e1c41174e0cf2eefc5)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:34 volumio go-librespot[1536]: time="2024-10-30T15:34:34+07:00" level=debug msg="requested aes key for file a059aaa8b76f2a5d2f2287e1c41174e0cf2eefc5, gid: 58A085gOcvysnGgsLq74Am" Oct 30 15:34:34 volumio go-librespot[1536]: time="2024-10-30T15:34:34+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:58A085gOcvysnGgsLq74Am: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:34 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:36 volumio ntpd[908]: Soliciting pool server 203.113.174.44 Oct 30 15:34:38 volumio ntpd[908]: Soliciting pool server 2a0c:b847:ffff:79::e53c Oct 30 15:34:39 volumio volumio[947]: info: CoreCommandRouter::volumioplayNextItems Oct 30 15:34:39 volumio volumio[947]: info: CoreStateMachine::playNextItems Oct 30 15:34:39 volumio volumio[947]: info: CorePlayQueue::addPlayNextItems Oct 30 15:34:39 volumio volumio[947]: info: Preload queue cleared Oct 30 15:34:39 volumio volumio[947]: info: Adding Item to play next: spotify:album:0tC4C7slhnBFgBsN5jCbnx Oct 30 15:34:39 volumio volumio[947]: info: Using cached record of: spotify:album:0tC4C7slhnBFgBsN5jCbnx Oct 30 15:34:39 volumio volumio[947]: info: CoreCommandRouter::volumioPushQueue Oct 30 15:34:39 volumio volumio[947]: info: CorePlayQueue::saveQueue Oct 30 15:34:39 volumio volumio[947]: info: CoreStateMachine::updateTrackBlock Oct 30 15:34:39 volumio volumio[947]: info: CorePlayQueue::getTrackBlock Oct 30 15:34:41 volumio ntpd[908]: Soliciting pool server 203.113.174.44 Oct 30 15:34:41 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:34:41 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:41 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:41 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:41 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:41 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:41 volumio volumio[947]: info: [1730277281493] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:41 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:41 volumio go-librespot[1536]: time="2024-10-30T15:34:41+07:00" level=debug msg="resolved context of track" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:41 volumio go-librespot[1536]: time="2024-10-30T15:34:41+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:41 volumio go-librespot[1536]: time="2024-10-30T15:34:41+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:41 volumio go-librespot[1536]: time="2024-10-30T15:34:41+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:41 volumio go-librespot[1536]: time="2024-10-30T15:34:41+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:41 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:58A085gOcvysnGgsLq74Am","play_origin":"go-librespot"}} Oct 30 15:34:41 volumio go-librespot[1536]: time="2024-10-30T15:34:41+07:00" level=debug msg="selected format OGG_VORBIS_320 (a059aaa8b76f2a5d2f2287e1c41174e0cf2eefc5)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:41 volumio go-librespot[1536]: time="2024-10-30T15:34:41+07:00" level=debug msg="requested aes key for file a059aaa8b76f2a5d2f2287e1c41174e0cf2eefc5, gid: 58A085gOcvysnGgsLq74Am" Oct 30 15:34:41 volumio go-librespot[1536]: time="2024-10-30T15:34:41+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:58A085gOcvysnGgsLq74Am: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:41 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:42 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 30 15:34:42 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 30 15:34:42 volumio volumio[947]: info: Discovery: Getting this device information Oct 30 15:34:42 volumio volumio[947]: info: CoreCommandRouter::volumioGetState Oct 30 15:34:42 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:42 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 30 15:34:43 volumio ntpd[908]: Soliciting pool server 203.113.174.44 Oct 30 15:34:45 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:34:45 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:45 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:45 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:45 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:45 volumio volumio[947]: info: CorePlayQueue::getTrack 0 Oct 30 15:34:45 volumio volumio[947]: info: [1730277285808] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:45 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:45 volumio go-librespot[1536]: time="2024-10-30T15:34:45+07:00" level=debug msg="resolved context of track" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:45 volumio go-librespot[1536]: time="2024-10-30T15:34:45+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:45 volumio go-librespot[1536]: time="2024-10-30T15:34:45+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:45 volumio go-librespot[1536]: time="2024-10-30T15:34:45+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:45 volumio go-librespot[1536]: time="2024-10-30T15:34:45+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:45 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:58A085gOcvysnGgsLq74Am","play_origin":"go-librespot"}} Oct 30 15:34:45 volumio go-librespot[1536]: time="2024-10-30T15:34:45+07:00" level=debug msg="selected format OGG_VORBIS_320 (a059aaa8b76f2a5d2f2287e1c41174e0cf2eefc5)" uri="spotify:track:58A085gOcvysnGgsLq74Am" Oct 30 15:34:45 volumio go-librespot[1536]: time="2024-10-30T15:34:45+07:00" level=debug msg="requested aes key for file a059aaa8b76f2a5d2f2287e1c41174e0cf2eefc5, gid: 58A085gOcvysnGgsLq74Am" Oct 30 15:34:46 volumio go-librespot[1536]: time="2024-10-30T15:34:46+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:58A085gOcvysnGgsLq74Am: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:46 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:46 volumio volumio[947]: info: CoreCommandRouter::volumioNext Oct 30 15:34:46 volumio volumio[947]: info: CoreStateMachine::next Oct 30 15:34:46 volumio volumio[947]: info: CoreStateMachine::stop Oct 30 15:34:46 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:46 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:46 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:46 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:46 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:46 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:46 volumio volumio[947]: info: [1730277286449] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:46 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:46 volumio volumio[947]: info: CoreStateMachine::updateTrackBlock Oct 30 15:34:46 volumio volumio[947]: info: CorePlayQueue::getTrackBlock Oct 30 15:34:46 volumio go-librespot[1536]: time="2024-10-30T15:34:46+07:00" level=debug msg="resolved context of track" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:46 volumio go-librespot[1536]: time="2024-10-30T15:34:46+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:46 volumio go-librespot[1536]: time="2024-10-30T15:34:46+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:46 volumio go-librespot[1536]: time="2024-10-30T15:34:46+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:46 volumio go-librespot[1536]: time="2024-10-30T15:34:46+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:46 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:36s0Xok3lIXY16ygUjU7f7","play_origin":"go-librespot"}} Oct 30 15:34:46 volumio go-librespot[1536]: time="2024-10-30T15:34:46+07:00" level=debug msg="selected format OGG_VORBIS_320 (8d096b177a20102329bbeff9f6da794294a7a7e7)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:46 volumio go-librespot[1536]: time="2024-10-30T15:34:46+07:00" level=debug msg="requested aes key for file 8d096b177a20102329bbeff9f6da794294a7a7e7, gid: 36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:46 volumio go-librespot[1536]: time="2024-10-30T15:34:46+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:36s0Xok3lIXY16ygUjU7f7: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:46 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:49 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:34:49 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:49 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:49 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:49 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:49 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:49 volumio volumio[947]: info: [1730277289288] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:49 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=debug msg="resolved context of track" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:49 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:36s0Xok3lIXY16ygUjU7f7","play_origin":"go-librespot"}} Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=debug msg="selected format OGG_VORBIS_320 (8d096b177a20102329bbeff9f6da794294a7a7e7)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=debug msg="requested aes key for file 8d096b177a20102329bbeff9f6da794294a7a7e7, gid: 36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:36s0Xok3lIXY16ygUjU7f7: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:49 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:49 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:34:49 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:49 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:49 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:49 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:49 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:49 volumio volumio[947]: info: [1730277289788] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:49 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=debug msg="resolved context of track" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:49 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:36s0Xok3lIXY16ygUjU7f7","play_origin":"go-librespot"}} Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=debug msg="selected format OGG_VORBIS_320 (8d096b177a20102329bbeff9f6da794294a7a7e7)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=debug msg="requested aes key for file 8d096b177a20102329bbeff9f6da794294a7a7e7, gid: 36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:49 volumio go-librespot[1536]: time="2024-10-30T15:34:49+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:36s0Xok3lIXY16ygUjU7f7: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:49 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:50 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:34:50 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:50 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:50 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:50 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:50 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:50 volumio volumio[947]: info: [1730277290205] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:50 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=debug msg="resolved context of track" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:50 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:36s0Xok3lIXY16ygUjU7f7","play_origin":"go-librespot"}} Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=debug msg="selected format OGG_VORBIS_320 (8d096b177a20102329bbeff9f6da794294a7a7e7)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=debug msg="requested aes key for file 8d096b177a20102329bbeff9f6da794294a7a7e7, gid: 36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:36s0Xok3lIXY16ygUjU7f7: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:50 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:50 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:34:50 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:50 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:50 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:50 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:50 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:50 volumio volumio[947]: info: [1730277290570] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:50 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=debug msg="resolved context of track" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:50 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:36s0Xok3lIXY16ygUjU7f7","play_origin":"go-librespot"}} Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=debug msg="selected format OGG_VORBIS_320 (8d096b177a20102329bbeff9f6da794294a7a7e7)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=debug msg="requested aes key for file 8d096b177a20102329bbeff9f6da794294a7a7e7, gid: 36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:36s0Xok3lIXY16ygUjU7f7: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:50 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:50 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:34:50 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:50 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:50 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:50 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:50 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:50 volumio volumio[947]: info: [1730277290924] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:50 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=debug msg="resolved context of track" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:50 volumio go-librespot[1536]: time="2024-10-30T15:34:50+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:51 volumio go-librespot[1536]: time="2024-10-30T15:34:51+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:51 volumio go-librespot[1536]: time="2024-10-30T15:34:51+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:51 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:36s0Xok3lIXY16ygUjU7f7","play_origin":"go-librespot"}} Oct 30 15:34:51 volumio go-librespot[1536]: time="2024-10-30T15:34:51+07:00" level=debug msg="selected format OGG_VORBIS_320 (8d096b177a20102329bbeff9f6da794294a7a7e7)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:51 volumio go-librespot[1536]: time="2024-10-30T15:34:51+07:00" level=debug msg="requested aes key for file 8d096b177a20102329bbeff9f6da794294a7a7e7, gid: 36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:51 volumio go-librespot[1536]: time="2024-10-30T15:34:51+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:36s0Xok3lIXY16ygUjU7f7: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:51 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:56 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:34:56 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:34:56 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:34:56 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:56 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:34:56 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:34:56 volumio volumio[947]: info: [1730277296695] ControllerSpotify::clearAddPlayTrack Oct 30 15:34:56 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:34:56 volumio go-librespot[1536]: time="2024-10-30T15:34:56+07:00" level=debug msg="resolved context of track" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:56 volumio go-librespot[1536]: time="2024-10-30T15:34:56+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:56 volumio go-librespot[1536]: time="2024-10-30T15:34:56+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:56 volumio go-librespot[1536]: time="2024-10-30T15:34:56+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:34:56 volumio go-librespot[1536]: time="2024-10-30T15:34:56+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:34:56 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:36s0Xok3lIXY16ygUjU7f7","play_origin":"go-librespot"}} Oct 30 15:34:56 volumio go-librespot[1536]: time="2024-10-30T15:34:56+07:00" level=debug msg="selected format OGG_VORBIS_320 (8d096b177a20102329bbeff9f6da794294a7a7e7)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:56 volumio go-librespot[1536]: time="2024-10-30T15:34:56+07:00" level=debug msg="requested aes key for file 8d096b177a20102329bbeff9f6da794294a7a7e7, gid: 36s0Xok3lIXY16ygUjU7f7" Oct 30 15:34:56 volumio go-librespot[1536]: time="2024-10-30T15:34:56+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:36s0Xok3lIXY16ygUjU7f7: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:34:56 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:34:59 volumio volumio[947]: info: CoreCommandRouter::volumioPrevious Oct 30 15:34:59 volumio volumio[947]: info: CoreStateMachine::previous Oct 30 15:34:59 volumio volumio[947]: info: CoreStateMachine::updateTrackBlock Oct 30 15:34:59 volumio volumio[947]: info: CorePlayQueue::getTrackBlock Oct 30 15:34:59 volumio volumio[947]: info: CoreStateMachine::serviceClearAddPlay Oct 30 15:34:59 volumio volumio[947]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 30 15:34:59 volumio volumio[947]: error: WARNING: No clearAddPlayTracks method for service spop Oct 30 15:35:00 volumio volumio[947]: info: CoreCommandRouter::volumioPrevious Oct 30 15:35:00 volumio volumio[947]: info: CoreStateMachine::previous Oct 30 15:35:00 volumio volumio[947]: info: CoreStateMachine::updateTrackBlock Oct 30 15:35:00 volumio volumio[947]: info: CorePlayQueue::getTrackBlock Oct 30 15:35:00 volumio volumio[947]: info: CoreStateMachine::serviceClearAddPlay Oct 30 15:35:00 volumio volumio[947]: info: CoreCommandRouter::serviceClearAddPlayTracks Oct 30 15:35:00 volumio volumio[947]: error: WARNING: No clearAddPlayTracks method for service spop Oct 30 15:35:01 volumio volumio[947]: info: CoreCommandRouter::volumioNext Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::next Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::stop Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:01 volumio volumio[947]: info: CorePlayQueue::getTrack 5 Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:35:01 volumio volumio[947]: info: CorePlayQueue::getTrack 5 Oct 30 15:35:01 volumio volumio[947]: info: [1730277301043] ControllerSpotify::clearAddPlayTrack Oct 30 15:35:01 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::updateTrackBlock Oct 30 15:35:01 volumio volumio[947]: info: CorePlayQueue::getTrackBlock Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=debug msg="resolved context of track" uri="spotify:track:0ZDpbo6BVCYvGV8cP6DiZ4" Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0ZDpbo6BVCYvGV8cP6DiZ4" Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0ZDpbo6BVCYvGV8cP6DiZ4" Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:35:01 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0ZDpbo6BVCYvGV8cP6DiZ4","play_origin":"go-librespot"}} Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=debug msg="selected format OGG_VORBIS_320 (fc8eeb3ee83b86802b493a7b7551c53a8d9a7782)" uri="spotify:track:0ZDpbo6BVCYvGV8cP6DiZ4" Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=debug msg="requested aes key for file fc8eeb3ee83b86802b493a7b7551c53a8d9a7782, gid: 0ZDpbo6BVCYvGV8cP6DiZ4" Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:0ZDpbo6BVCYvGV8cP6DiZ4: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:35:01 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:35:01 volumio volumio[947]: info: CoreCommandRouter::volumioNext Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::next Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::stop Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:01 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:35:01 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:01 volumio volumio[947]: info: [1730277301764] ControllerSpotify::clearAddPlayTrack Oct 30 15:35:01 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:35:01 volumio volumio[947]: info: CoreStateMachine::updateTrackBlock Oct 30 15:35:01 volumio volumio[947]: info: CorePlayQueue::getTrackBlock Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=debug msg="resolved context of track" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:35:01 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:36s0Xok3lIXY16ygUjU7f7","play_origin":"go-librespot"}} Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=debug msg="selected format OGG_VORBIS_320 (8d096b177a20102329bbeff9f6da794294a7a7e7)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=debug msg="requested aes key for file 8d096b177a20102329bbeff9f6da794294a7a7e7, gid: 36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:01 volumio go-librespot[1536]: time="2024-10-30T15:35:01+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:36s0Xok3lIXY16ygUjU7f7: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:35:01 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:35:02 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:35:02 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:35:02 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:02 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:02 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:35:02 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:02 volumio volumio[947]: info: [1730277302406] ControllerSpotify::clearAddPlayTrack Oct 30 15:35:02 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=debug msg="resolved context of track" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:35:02 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:36s0Xok3lIXY16ygUjU7f7","play_origin":"go-librespot"}} Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=debug msg="selected format OGG_VORBIS_320 (8d096b177a20102329bbeff9f6da794294a7a7e7)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=debug msg="requested aes key for file 8d096b177a20102329bbeff9f6da794294a7a7e7, gid: 36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:36s0Xok3lIXY16ygUjU7f7: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:35:02 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:35:02 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:35:02 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:35:02 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:02 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:02 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:35:02 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:02 volumio volumio[947]: info: [1730277302833] ControllerSpotify::clearAddPlayTrack Oct 30 15:35:02 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=debug msg="resolved context of track" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:35:02 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:36s0Xok3lIXY16ygUjU7f7","play_origin":"go-librespot"}} Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=debug msg="selected format OGG_VORBIS_320 (8d096b177a20102329bbeff9f6da794294a7a7e7)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:02 volumio go-librespot[1536]: time="2024-10-30T15:35:02+07:00" level=debug msg="requested aes key for file 8d096b177a20102329bbeff9f6da794294a7a7e7, gid: 36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:03 volumio go-librespot[1536]: time="2024-10-30T15:35:03+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:36s0Xok3lIXY16ygUjU7f7: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:35:03 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:35:03 volumio volumio[947]: info: CoreCommandRouter::volumioPlay Oct 30 15:35:03 volumio volumio[947]: info: CoreStateMachine::play index undefined Oct 30 15:35:03 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:03 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:03 volumio volumio[947]: info: CoreStateMachine::startPlaybackTimer Oct 30 15:35:03 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:03 volumio volumio[947]: info: [1730277303282] ControllerSpotify::clearAddPlayTrack Oct 30 15:35:03 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/play Oct 30 15:35:03 volumio go-librespot[1536]: time="2024-10-30T15:35:03+07:00" level=debug msg="resolved context of track" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:03 volumio go-librespot[1536]: time="2024-10-30T15:35:03+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:03 volumio go-librespot[1536]: time="2024-10-30T15:35:03+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:03 volumio go-librespot[1536]: time="2024-10-30T15:35:03+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 30 15:35:03 volumio go-librespot[1536]: time="2024-10-30T15:35:03+07:00" level=trace msg="emitting websocket event: will_play" Oct 30 15:35:03 volumio volumio[947]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:36s0Xok3lIXY16ygUjU7f7","play_origin":"go-librespot"}} Oct 30 15:35:03 volumio go-librespot[1536]: time="2024-10-30T15:35:03+07:00" level=debug msg="selected format OGG_VORBIS_320 (8d096b177a20102329bbeff9f6da794294a7a7e7)" uri="spotify:track:36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:03 volumio go-librespot[1536]: time="2024-10-30T15:35:03+07:00" level=debug msg="requested aes key for file 8d096b177a20102329bbeff9f6da794294a7a7e7, gid: 36s0Xok3lIXY16ygUjU7f7" Oct 30 15:35:03 volumio go-librespot[1536]: time="2024-10-30T15:35:03+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:36s0Xok3lIXY16ygUjU7f7: failed retrieving audio key: failed retrieving aes key with code 1" Oct 30 15:35:03 volumio volumio[947]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 30 15:35:11 volumio volumio[947]: info: VolumeController::SetAlsaVolume- Oct 30 15:35:11 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:11 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:11 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 15:35:11 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:11 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Oct 30 15:35:11 volumio volumio[947]: SPOTIFY: SPOTIFY VOLUME 100 Oct 30 15:35:11 volumio volumio[947]: SPOTIFY: VOLUMIO VOLUME 98 Oct 30 15:35:11 volumio volumio[947]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 30 15:35:11 volumio volumio[947]: info: Setting Spotify Volume from Volumio: 98 Oct 30 15:35:12 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 30 15:35:12 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 30 15:35:12 volumio volumio[947]: info: Discovery: Getting this device information Oct 30 15:35:12 volumio volumio[947]: info: CoreCommandRouter::volumioGetState Oct 30 15:35:12 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:12 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 30 15:35:13 volumio volumio[947]: SPOTIFY: SETTING SPOTIFY VOLUME 98 Oct 30 15:35:13 volumio volumio[947]: info: Sending Spotify command with payload to local API: /player/volume Oct 30 15:35:13 volumio go-librespot[1536]: time="2024-10-30T15:35:13+07:00" level=debug msg="update volume to 64224/65535" Oct 30 15:35:13 volumio go-librespot[1536]: time="2024-10-30T15:35:13+07:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 30 15:35:13 volumio go-librespot[1536]: time="2024-10-30T15:35:13+07:00" level=trace msg="emitting websocket event: volume" Oct 30 15:35:13 volumio volumio[947]: SPOTIFY: received: {"type":"volume","data":{"value":98,"max":100}} Oct 30 15:35:13 volumio volumio[947]: SPOTIFY: RECEIVED SPOTIFY VOLUME 98 Oct 30 15:35:15 volumio volumio[947]: info: Airplay started streaming, receiving metadatas Oct 30 15:35:15 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:15 volumio volumio[947]: info: CoreCommandRouter::volumioStop Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::stop Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:15 volumio volumio[947]: info: Airplay started streaming, receiving metadatas Oct 30 15:35:15 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:15 volumio volumio[947]: info: CoreCommandRouter::volumioStop Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::stop Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:15 volumio volumio[947]: info: Airplay started streaming, receiving metadatas Oct 30 15:35:15 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:15 volumio volumio[947]: info: CoreCommandRouter::volumioStop Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::stop Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:15 volumio volumio[947]: info: Airplay started streaming, receiving metadatas Oct 30 15:35:15 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:15 volumio volumio[947]: info: CoreCommandRouter::volumioStop Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::stop Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:15 volumio shairport-sync[2235]: % Total % Received % Xferd Average Speed Time Time Time Current Oct 30 15:35:15 volumio shairport-sync[2235]: Dload Upload Total Spent Left Speed Oct 30 15:35:15 volumio volumio[947]: info: Oct 30 15:35:15 volumio volumio[947]: ---------------------------- Client requests Start Airplay PlaybackRoutine Oct 30 15:35:15 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startAirplayPlayback Oct 30 15:35:15 volumio volumio[947]: info: Airplay playback start Oct 30 15:35:15 volumio volumio[947]: info: CorePlayQueue::getTrack 13 Oct 30 15:35:15 volumio volumio[947]: info: CoreCommandRouter::volumioStop Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::stop Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:15 volumio volumio[947]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 30 15:35:15 volumio shairport-sync[2235]: [158B blob data] Oct 30 15:35:16 volumio shairport-sync[2235]: {"time":1730277315886,"response":"startAirplayPlayback Success"}ALSA lib /home/volumio-hook-plugin/src/pcm_volumiohook.c:101:(_snd_pcm_volumiohook_execute) The PCM fusiondsphook failed to run command echo '44100,S32_LE,2,32' >/tmp/fusiondsp_stream_params.log Oct 30 15:35:16 volumio volumio[947]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Oct 30 15:35:16 volumio volumio[947]: info: FusionDsp - ---- read samplerate from file: 44100 Oct 30 15:35:16 volumio volumio[947]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 30 15:35:16 volumio volumio[947]: info: FusionDsp - {"Reload":{"result":"Ok"}} Oct 30 15:35:16 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:16 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:16 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 15:35:16 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:16 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Oct 30 15:35:16 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:16 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:16 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:16 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:16 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:16 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:16 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:16 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:16 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:16 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Oct 30 15:35:16 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:16 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:16 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:16 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:17 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:17 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:17 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:17 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:17 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:17 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:17 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::servicePushState Oct 30 15:35:17 volumio volumio[947]: info: CoreStateMachine::pushState Oct 30 15:35:17 volumio volumio[947]: info: CoreCommandRouter::volumioPushState Oct 30 15:35:17 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Oct 30 15:35:17 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Oct 30 15:35:17 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Oct 30 15:35:17 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Oct 30 15:35:17 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Oct 30 15:35:17 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Oct 30 15:35:17 volumio volumio[947]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Oct 30 15:35:36 volumio volumio[947]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 15:35:36 volumio volumio[947]: Error: connect ETIMEDOUT 151.101.78.79:443 Oct 30 15:35:36 volumio volumio[947]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { Oct 30 15:35:36 volumio volumio[947]: errno: -110, Oct 30 15:35:36 volumio volumio[947]: code: 'ETIMEDOUT', Oct 30 15:35:36 volumio volumio[947]: syscall: 'connect', Oct 30 15:35:36 volumio volumio[947]: address: '151.101.78.79', Oct 30 15:35:36 volumio volumio[947]: port: 443 Oct 30 15:35:36 volumio volumio[947]: } Oct 30 15:35:36 volumio volumio[947]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 15:35:37 volumio sudo[2311]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-30 15:34 Oct 30 15:35:37 volumio sudo[2311]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:33:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="ee834e1c2a28de3c5d8c48611ecf1167"