Jul 08 19:54:00 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:00 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:00 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:00 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:00 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:00 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:01 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:01 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:01 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:01 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:02 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:02 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:02 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:02 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:03 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:03 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:03 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:04 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:04 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:04 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:04 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:05 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:05 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:05 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:05 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:05 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:05 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index 2 Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: [1751997246352] ControllerSpotify::clearAddPlayTrack Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:54:06 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:06+02:00" level=debug msg="resolved context of track" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:06 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:06+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:06 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:06+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:06 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:06 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:06+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 08 19:54:06 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jul 08 19:54:06 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:06+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 08 19:54:06 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 19:54:06 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:06+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 19:54:06 rpi5-ws840 volumio[1369]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7s1xIVKnVj4hhsO607RC8k","play_origin":"go-librespot"}} Jul 08 19:54:06 rpi5-ws840 volumio[1369]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7s1xIVKnVj4hhsO607RC8k","play_origin":"go-librespot"}} Jul 08 19:54:06 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1127" Jul 08 19:54:06 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:06+02:00" level=debug msg="selected format OGG_VORBIS_320 (a5e0a5745a5e3e9ca53ff5c90544646f64776b89)" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:06 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:06+02:00" level=debug msg="requested aes key for file a5e0a5745a5e3e9ca53ff5c90544646f64776b89, gid: 7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:07 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:07+02:00" level=debug msg="fetched first chunk of 28, total size is 14354512 bytes" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:07 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:07+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:07 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:07+02:00" level=debug msg="created new output device" Jul 08 19:54:07 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:07+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jul 08 19:54:07 rpi5-ws840 go-librespot[2526]: time="2025-07-08T19:54:07+02:00" level=info msg="loaded track \"Nothing Else Matters - Remastered 2021\" (paused: false, position: 1ms, duration: 388733ms, prefetched: false)" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:07 rpi5-ws840 go-librespot[2526]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 19:54:07 rpi5-ws840 go-librespot[2525]: Aborted Jul 08 19:54:07 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 19:54:07 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 19:54:07 rpi5-ws840 volumio[1369]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: Connection to go-librespot Websocket closed Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: Connection to go-librespot Websocket closed Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: Received Get System Version Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: Received Get System Info Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: Discovery: Getting this device information Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:07 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:08 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:08 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:08 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:08 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:09 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:09 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:09 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:09 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:09 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:09 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:10 rpi5-ws840 volumio[1369]: info: Initializing connection to go-librespot Websocket Jul 08 19:54:10 rpi5-ws840 volumio[1369]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 19:54:10 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jul 08 19:54:10 rpi5-ws840 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 19:54:10 rpi5-ws840 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 19:54:10 rpi5-ws840 go-librespot[2603]: go-librespot daemon starting... Jul 08 19:54:10 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:10+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 19:54:10 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:10+02:00" level=debug msg="app state loaded" Jul 08 19:54:10 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 19:54:10 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:10 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:10 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:10 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:11 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:11 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:11 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:11 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:12 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:12 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:12 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:12 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:12 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:12 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:13 rpi5-ws840 volumio[1369]: info: Initializing connection to go-librespot Websocket Jul 08 19:54:13 rpi5-ws840 volumio[1369]: info: Connection to go-librespot Websocket established Jul 08 19:54:13 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:13+02:00" level=debug msg="new websocket client" Jul 08 19:54:13 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:13 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:13 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:13 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:14 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:14 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:14 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:14 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:14 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:14 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:15 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:15 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=info msg="zeroconf server listening on port 37927" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="obtained new client token: AADAZo6OyKrGpGR1YDzfdpaITOofgsKTSkbY+dOtm6AZ7BVyvYGAVDGkjUOI6eroNO6n+BccyyttoRFcgNWm8BjOiqdJMU704MMbVJP+98zAX/t82pwTjM+RH/w5Yd3uTmPM5Yfwp6mV0CSlJqUGhrvjIcoQHuNDT+XZ/wStAeJE74D7BZnkpe/hscAyrCPr3TFno82aOk6iSj9pux88/fiNV+o8GUykTqAAO27swApw7Zan6KLOLEu4I1c=" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="completed keyexchange" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="completed challenge" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=info msg="authenticated AP as z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:54:15 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:15 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=info msg="authenticated Login5 as z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="initializing zeroconf session, username: z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="dealer connection opened" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=trace msg="starting dealer recv loop" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=trace msg="received accesspoint ping" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=debug msg="received connection id: NDdhZDE0NzUtYWNiMC00YjE3LWExYjMtNjBiYjdhZmI5OGE5K2RlYWxlcit0Y3A6Ly8wYWIxNTE5MS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQUVDQThDNUQ2M0VBQTcxQThGMTRGQjZCQUQ0RTYxOUJGMTZCREFFOEFEMjYxOUM2MTc0RDZBRUY3MTMyMDVFMw==" Jul 08 19:54:15 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:15+02:00" level=trace msg="received accesspoint pong ack" Jul 08 19:54:16 rpi5-ws840 volumio[1369]: info: Getting Spotify volume Jul 08 19:54:16 rpi5-ws840 volumio[1369]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 19 Jul 08 19:54:16 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:16 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:16 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:16 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:16 rpi5-ws840 volumio[1369]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 08 19:54:16 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:16+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 19:54:16 rpi5-ws840 volumio[1369]: info: Spotify volume: 100 Jul 08 19:54:16 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:16 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:16 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:16 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:17 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:17 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:17 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:17 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:18 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:18 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:18 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:19 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:19 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:19 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:19 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:19 rpi5-ws840 systemd[1]: systemd-timedated.service: Deactivated successfully. Jul 08 19:54:20 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:20 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:20 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:20 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:20 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:20 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:21 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:21 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:21 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:21 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index 2 Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: [1751997262422] ControllerSpotify::clearAddPlayTrack Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:22 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:22 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:22+02:00" level=debug msg="resolved context of track" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:22 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:22+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:22 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:22+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:22 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 19:54:22 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:22+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 19:54:22 rpi5-ws840 volumio[1369]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7s1xIVKnVj4hhsO607RC8k","play_origin":"go-librespot"}} Jul 08 19:54:22 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:22+02:00" level=debug msg="selected format OGG_VORBIS_320 (a5e0a5745a5e3e9ca53ff5c90544646f64776b89)" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:22 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:22+02:00" level=debug msg="requested aes key for file a5e0a5745a5e3e9ca53ff5c90544646f64776b89, gid: 7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:23 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:23 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:23 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:23+02:00" level=debug msg="fetched first chunk of 28, total size is 14354512 bytes" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:23 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:23+02:00" level=debug msg="created new output device" Jul 08 19:54:23 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:23+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jul 08 19:54:23 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:23+02:00" level=info msg="loaded track \"Nothing Else Matters - Remastered 2021\" (paused: false, position: 0ms, duration: 388733ms, prefetched: false)" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:23 rpi5-ws840 go-librespot[2604]: time="2025-07-08T19:54:23+02:00" level=debug msg="fetched chunk 2/27, size: 524288" uri="spotify:track:7s1xIVKnVj4hhsO607RC8k" Jul 08 19:54:23 rpi5-ws840 go-librespot[2604]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 19:54:23 rpi5-ws840 go-librespot[2603]: Aborted Jul 08 19:54:23 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 19:54:23 rpi5-ws840 volumio[1369]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 19:54:23 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 19:54:23 rpi5-ws840 volumio[1369]: info: Connection to go-librespot Websocket closed Jul 08 19:54:23 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:23 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:23 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:23 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:24 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:24 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:24 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:24 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:24 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:24 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:25 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:25 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:25 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:25 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:25 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:25 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:26 rpi5-ws840 volumio[1369]: info: Initializing connection to go-librespot Websocket Jul 08 19:54:26 rpi5-ws840 volumio[1369]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 19:54:26 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:26 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:26 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jul 08 19:54:26 rpi5-ws840 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 19:54:26 rpi5-ws840 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 19:54:26 rpi5-ws840 go-librespot[2645]: go-librespot daemon starting... Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="app state loaded" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=info msg="zeroconf server listening on port 43545" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="obtained new client token: AACxonnjlGpjIung0ln/ASxUGbQeECANczQNFbAYs14dLCNBwfpx+Oh4SGw/Shn6hBabakE1g8bQc7fg48dbTGIOokm9bkMTYLsCrUU6gmnUv0onRqM2AhWYZczO4t6KQcOOqH6r6ugZ8e+X65Bvn8+hgmQhTuBNN+bXlV7S7/vKaIqA+S5JXKAvHH6pC+XZngUt/Wz81T3cdhMGh2hl0cl1RDsjaHpftm8lBcI6ihAWthGdjf8T3P09DlQ=" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="completed keyexchange" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="completed challenge" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=info msg="authenticated AP as z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:54:26 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:26 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=info msg="authenticated Login5 as z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="initializing zeroconf session, username: z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:54:26 rpi5-ws840 volumio[1369]: info: Executing endpoint metavolumio Jul 08 19:54:26 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:54:26 rpi5-ws840 volumio[1369]: info: Executing endpoint metavolumio Jul 08 19:54:26 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:54:26 rpi5-ws840 volumio[1369]: info: Executing endpoint metavolumio Jul 08 19:54:26 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="dealer connection opened" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=trace msg="starting dealer recv loop" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=trace msg="received accesspoint ping" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=debug msg="received connection id: N2E3ZGEyZDAtYzFkNy00Yzc2LTkwOGItNTU3MGNkZGVhZTc3K2RlYWxlcit0Y3A6Ly8wYWIxNTFmZS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMTk0MUQxRDQ2MUE1OTRDQjFBMTg0MTZDNEU0MjVERUFCMjM4QTYwNTkxNjU5RTU0QTA5RkQ0NzRBQzAyRURBMQ==" Jul 08 19:54:26 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:26+02:00" level=trace msg="received accesspoint pong ack" Jul 08 19:54:27 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:27 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:27 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:27+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 19:54:27 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:27 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:27 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:27 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:27 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:27 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:28 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:28 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:28 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:28 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: Initializing connection to go-librespot Websocket Jul 08 19:54:29 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:29+02:00" level=debug msg="new websocket client" Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: Connection to go-librespot Websocket established Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: Executing endpoint metavolumio Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: Executing endpoint metavolumio Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: Executing endpoint metavolumio Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:29 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:30 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:30 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:30 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:30 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:30 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jul 08 19:54:30 rpi5-ws840 volumio[1369]: info: In handleBrowseUri, curUri=spotify Jul 08 19:54:30 rpi5-ws840 volumio[1369]: info: Preload queue cleared Jul 08 19:54:30 rpi5-ws840 volumio[1369]: info: Preload queue cleared Jul 08 19:54:30 rpi5-ws840 volumio[1369]: info: Preload queue cleared Jul 08 19:54:30 rpi5-ws840 volumio[1369]: info: Preload queue cleared Jul 08 19:54:31 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:31 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:31 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:31 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:32 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:32 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:32 rpi5-ws840 volumio[1369]: info: Getting Spotify volume Jul 08 19:54:32 rpi5-ws840 volumio[1369]: info: Spotify volume: 100 Jul 08 19:54:32 rpi5-ws840 volumio[1369]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 14 Jul 08 19:54:32 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:32 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:32 rpi5-ws840 volumio[1369]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 08 19:54:32 rpi5-ws840 volumio[1369]: SPOTIFY: SPOTIFY VOLUME 100 Jul 08 19:54:32 rpi5-ws840 volumio[1369]: SPOTIFY: VOLUMIO VOLUME 46 Jul 08 19:54:32 rpi5-ws840 volumio[1369]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 08 19:54:32 rpi5-ws840 volumio[1369]: info: Setting Spotify Volume from Volumio: 46 Jul 08 19:54:32 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:32 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:32 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:32 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:33 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:33 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:33 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:33 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:33 rpi5-ws840 volumio[1369]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Jul 08 19:54:33 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/volume Jul 08 19:54:33 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:33+02:00" level=debug msg="update volume to 30146/65535" Jul 08 19:54:34 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:34 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:34 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:34 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:34 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:34 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:35 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:35+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 08 19:54:35 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:35+02:00" level=trace msg="emitting websocket event: volume" Jul 08 19:54:35 rpi5-ws840 volumio[1369]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Jul 08 19:54:35 rpi5-ws840 volumio[1369]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Jul 08 19:54:35 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:35 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:35 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:35 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:36 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:36 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:36 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:36 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:36 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:36 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:37 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:37 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:37 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:37 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:38 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:38 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:38 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:38 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:38 rpi5-ws840 volumio[1369]: Searching plugin music_service/spop Jul 08 19:54:38 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 19:54:38 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:38 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:39 rpi5-ws840 volumio[1369]: info: All search sources collected, pushing search results Jul 08 19:54:39 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:39 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:39 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:39 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:40 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:40 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:40 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:40 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:40 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:40 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:41 rpi5-ws840 volumio[1369]: Searching plugin music_service/spop Jul 08 19:54:41 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 08 19:54:41 rpi5-ws840 volumio[1369]: verbose: New Socket.io Connection to 192.168.1.215:3000 from 192.168.1.171 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 14 Jul 08 19:54:41 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:41 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:41 rpi5-ws840 volumio[1369]: info: All search sources collected, pushing search results Jul 08 19:54:41 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:41 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:42 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:42 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:42 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:42 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:43 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:43 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:43 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:43 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:43 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:43 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:44 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:44 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:44 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:44 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:45 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:45 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:45 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:45 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:45 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:45 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:46 rpi5-ws840 volumio[1369]: info: MRS: Pushing multiroomSync output for this device Jul 08 19:54:46 rpi5-ws840 volumio[1369]: info: MRS: Pushing multiroomSync output Jul 08 19:54:46 rpi5-ws840 volumio[1369]: info: Adding audio output: Jul 08 19:54:46 rpi5-ws840 volumio[1369]: info: Adding audio output: Jul 08 19:54:46 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:46 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:46 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:46 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:47 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:47 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:47 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:47 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:47 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:47 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:48 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:48 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:48 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:48 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:49 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:49 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:49 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:49 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:49 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:49 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:50 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:50 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:50 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:50 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:51 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:51 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:51 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:51 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:51 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:51 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:52 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:52 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:52 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:52 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Preload queue cleared Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::ClearQueue Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CorePlayQueue::clearPlayQueue Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CorePlayQueue::saveQueue Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPushQueue Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::addQueueItems Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CorePlayQueue::addQueueItems Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Preload queue cleared Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:6QAsrXPnMSXIbV0yEJHlEX Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:6QAsrXPnMSXIbV0yEJHlEX in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:6QAsrXPnMSXIbV0yEJHlEX Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 2 Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6QAsrXPnMSXIbV0yEJHlEX","service":"spop","name":"Nothing Else Matters - Remastered 2021","artist":"Metallica","album":"Metallica (Remastered Deluxe Box Set)","type":"song","duration":388,"albumart":"https://i.scdn.co/image/ab67616d0000b273c1a13209dfe146aef3296e34","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPushQueue Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CorePlayQueue::saveQueue Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::updateTrackBlock Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrackBlock Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index 0 Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::addQueueItems Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CorePlayQueue::addQueueItems Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Preload queue cleared Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:1EuBmBZDaYFif5entO016n Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:1EuBmBZDaYFif5entO016n in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:1EuBmBZDaYFif5entO016n Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:7s1xIVKnVj4hhsO607RC8k Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:7s1xIVKnVj4hhsO607RC8k in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:7s1xIVKnVj4hhsO607RC8k Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:6jN5vKdqowVvx3Z1lzw1id Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:6jN5vKdqowVvx3Z1lzw1id in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:6jN5vKdqowVvx3Z1lzw1id Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:0ymH4sMuRBdeAlmMbxvFbj Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:0ymH4sMuRBdeAlmMbxvFbj in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:0ymH4sMuRBdeAlmMbxvFbj Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:3uErbNGaNIPJkRlMrLxR9Z Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:3uErbNGaNIPJkRlMrLxR9Z in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:3uErbNGaNIPJkRlMrLxR9Z Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:5jEfQZmmwwKymr9cfmgfsd Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:5jEfQZmmwwKymr9cfmgfsd in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:5jEfQZmmwwKymr9cfmgfsd Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:4koCXQuTwiqrGgNEvSNdCf Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:4koCXQuTwiqrGgNEvSNdCf in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:4koCXQuTwiqrGgNEvSNdCf Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:4iXpWOc7dW65GjgR2Trjco Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:4iXpWOc7dW65GjgR2Trjco in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:4iXpWOc7dW65GjgR2Trjco Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:0QyMJHgcLfy9J8sOY17SpV Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:0QyMJHgcLfy9J8sOY17SpV in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:0QyMJHgcLfy9J8sOY17SpV Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:3RqedgMNJm1tEIpjQnmTpT Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:3RqedgMNJm1tEIpjQnmTpT in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:3RqedgMNJm1tEIpjQnmTpT Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:5E4AZovp9kZAoX2mHPpsb6 Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:5E4AZovp9kZAoX2mHPpsb6 in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:5E4AZovp9kZAoX2mHPpsb6 Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:5gMWdzYh8ozzbK9kTP9p1v Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:5gMWdzYh8ozzbK9kTP9p1v in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:5gMWdzYh8ozzbK9kTP9p1v Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:7sAJH3KsjrZG7tuQvd2OeE Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:7sAJH3KsjrZG7tuQvd2OeE in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:7sAJH3KsjrZG7tuQvd2OeE Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:4OF0yDOPvfPObyhOCRUpPY Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:4OF0yDOPvfPObyhOCRUpPY in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:4OF0yDOPvfPObyhOCRUpPY Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:0bflIQnvaGK5USahQuvohu Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:0bflIQnvaGK5USahQuvohu in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:0bflIQnvaGK5USahQuvohu Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:3S8fown0JN18TinaqGMplu Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:3S8fown0JN18TinaqGMplu in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:3S8fown0JN18TinaqGMplu Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:0JzBsBjPUCC9uEi53dTvIg Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:0JzBsBjPUCC9uEi53dTvIg in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:0JzBsBjPUCC9uEi53dTvIg Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Adding Item to queue: spotify:track:06QEX2cpzBydoHDRh72BIL Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Exploding uri spotify:track:06QEX2cpzBydoHDRh72BIL in service spop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: EXPLODING URI:spotify:track:06QEX2cpzBydoHDRh72BIL Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetVisibleSources Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: [1751997293581] ControllerSpotify::clearAddPlayTrack Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:53 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:53 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:53+02:00" level=debug msg="resolved context of track" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:53 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:53+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:53 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:53+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1EuBmBZDaYFif5entO016n","service":"spop","name":"Nothing Else Matters - Original Edit","artist":"Zany","album":"Nothing Else Matters","type":"song","duration":187,"albumart":"https://i.scdn.co/image/ab67616d0000b273a64a423538a79d5c01df144d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7s1xIVKnVj4hhsO607RC8k","service":"spop","name":"Nothing Else Matters - Remastered 2021","artist":"Metallica","album":"Metallica (Remastered 2021)","type":"song","duration":388,"albumart":"https://i.scdn.co/image/ab67616d0000b27376c60d2128c8e4649b85f2b2","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6jN5vKdqowVvx3Z1lzw1id","service":"spop","name":"Nothing Else Matters (Acoustic)","artist":"Kfir Ochaion","album":"VIII","type":"song","duration":336,"albumart":"https://i.scdn.co/image/ab67616d0000b2734679c09a9c3f98908306b55b","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3uErbNGaNIPJkRlMrLxR9Z","service":"spop","name":"Nothing Else Matters","artist":"Apocalyptica","album":"Inquisition Symphony","type":"song","duration":285,"albumart":"https://i.scdn.co/image/ab67616d0000b273aafd1a955eda9a0f8bbf50a1","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0ymH4sMuRBdeAlmMbxvFbj","service":"spop","name":"Nothing Else Matters - Edit","artist":"Zany","album":"Defqon.1 2017","type":"song","duration":187,"albumart":"https://i.scdn.co/image/ab67616d0000b273a4ed2da022f0a883c42f3a13","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5jEfQZmmwwKymr9cfmgfsd","service":"spop","name":"Nothing Else Matters - Live","artist":"Metallica","album":"S&M","type":"song","duration":407,"albumart":"https://i.scdn.co/image/ab67616d0000b2732a2e23c85aef280bffd824e7","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4koCXQuTwiqrGgNEvSNdCf","service":"spop","name":"Nothing Else Matters (Instrumental)","artist":"Kfir Ochaion","album":"VI","type":"song","duration":386,"albumart":"https://i.scdn.co/image/ab67616d0000b2734f7f9cff2627e5e019faaebd","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 19:54:53 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:53+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6QAsrXPnMSXIbV0yEJHlEX","play_origin":"go-librespot"}} Jul 08 19:54:53 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:53+02:00" level=debug msg="selected format OGG_VORBIS_320 (004b8a787e861e2a2df69a327ec9bfaae911c167)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:53 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:53+02:00" level=debug msg="requested aes key for file 004b8a787e861e2a2df69a327ec9bfaae911c167, gid: 6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4iXpWOc7dW65GjgR2Trjco","service":"spop","name":"Nothing Else Matters - Radio Edit","artist":"Metallica","album":"Metallica (Remastered Deluxe Box Set)","type":"song","duration":300,"albumart":"https://i.scdn.co/image/ab67616d0000b273c1a13209dfe146aef3296e34","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0QyMJHgcLfy9J8sOY17SpV","service":"spop","name":"Nothing Else Matters - Manifest Destiny Edit","artist":"Barber","album":"Nothing Else Matters (Manifest Destiny Edit)","type":"song","duration":181,"albumart":"https://i.scdn.co/image/ab67616d0000b2738aebec6113d34879aa064026","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5gMWdzYh8ozzbK9kTP9p1v","service":"spop","name":"Nothing Else Matters","artist":"Barber","album":"Live And Have Fun","type":"song","duration":168,"albumart":"https://i.scdn.co/image/ab67616d0000b27359c04333508d3353d2898cf4","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3RqedgMNJm1tEIpjQnmTpT","service":"spop","name":"Nothing Else Matters","artist":"Drainers","album":"Nothing Else Matters","type":"song","duration":140,"albumart":"https://i.scdn.co/image/ab67616d0000b2737edbade1d79ce38edcbae6c9","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5E4AZovp9kZAoX2mHPpsb6","service":"spop","name":"To Worship You I Live - Live","artist":"Israel & New Breed","album":"Alive In South Africa","type":"song","duration":407,"albumart":"https://i.scdn.co/image/ab67616d0000b27351784436ad469d10c9336023","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:7sAJH3KsjrZG7tuQvd2OeE","service":"spop","name":"Nothing Else - Live","artist":"The Belonging Co","album":"Awe + Wonder (Live)","type":"song","duration":510,"albumart":"https://i.scdn.co/image/ab67616d0000b273f2f00f2676dba29fa52d1528","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:53 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4OF0yDOPvfPObyhOCRUpPY","service":"spop","name":"To Worship You I Live","artist":"Israel & New Breed","album":"Feels Like Home, Vol. 1","type":"song","duration":485,"albumart":"https://i.scdn.co/image/ab67616d0000b273081846ad9e99c9721e3e15b4","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:54 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3S8fown0JN18TinaqGMplu","service":"spop","name":"Nothing Else - Live","artist":"The Belonging Co","album":"Worship Songs For Healing 2024","type":"song","duration":510,"albumart":"https://i.scdn.co/image/ab67616d0000b2736508410dadd1d5920d6f9458","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:54 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0bflIQnvaGK5USahQuvohu","service":"spop","name":"Nothing Else","artist":"Relena-Rochelle","album":"Nothing Else","type":"song","duration":183,"albumart":"https://i.scdn.co/image/ab67616d0000b273107741faefa1369de74279d3","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:54 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:54 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:54 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:06QEX2cpzBydoHDRh72BIL","service":"spop","name":"Nothing To Lose","artist":"Douwe Bob","album":"Where Did All The Cool Kids Go?","type":"song","duration":184,"albumart":"https://i.scdn.co/image/ab67616d0000b27327adcfb765e41caa6b0bc9c0","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:54 rpi5-ws840 volumio[1369]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0JzBsBjPUCC9uEi53dTvIg","service":"spop","name":"Lean in (Live)","artist":"Victory House Worship","album":"You Won It All (Live)","type":"song","duration":387,"albumart":"https://i.scdn.co/image/ab67616d0000b2737670729d61445d1823bb20b7","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 08 19:54:54 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPushQueue Jul 08 19:54:54 rpi5-ws840 volumio[1369]: info: CorePlayQueue::saveQueue Jul 08 19:54:54 rpi5-ws840 volumio[1369]: info: CoreStateMachine::updateTrackBlock Jul 08 19:54:54 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrackBlock Jul 08 19:54:54 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:54+02:00" level=debug msg="fetched first chunk of 28, total size is 14354512 bytes" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:54 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:54+02:00" level=debug msg="created new output device" Jul 08 19:54:54 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:54+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jul 08 19:54:54 rpi5-ws840 go-librespot[2646]: time="2025-07-08T19:54:54+02:00" level=info msg="loaded track \"Nothing Else Matters - Remastered 2021\" (paused: false, position: 0ms, duration: 388733ms, prefetched: false)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:54 rpi5-ws840 go-librespot[2646]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 19:54:54 rpi5-ws840 go-librespot[2645]: Aborted Jul 08 19:54:54 rpi5-ws840 volumio[1369]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 19:54:54 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 19:54:54 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 19:54:54 rpi5-ws840 volumio[1369]: info: Connection to go-librespot Websocket closed Jul 08 19:54:54 rpi5-ws840 systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jul 08 19:54:54 rpi5-ws840 dbus-daemon[987]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.35' (uid=0 pid=2698 comm="timedatectl show --property=NTPSynchronized --valu") Jul 08 19:54:54 rpi5-ws840 systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jul 08 19:54:54 rpi5-ws840 dbus-daemon[987]: [system] Successfully activated service 'org.freedesktop.timedate1' Jul 08 19:54:54 rpi5-ws840 systemd[1]: Started systemd-timedated.service - Time & Date Service. Jul 08 19:54:54 rpi5-ws840 setdatetime-helper.sh[2697]: Time is not synchronized. Attempting to sync... Jul 08 19:54:54 rpi5-ws840 sudo[2706]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Tue, 08 Jul 2025 17:54:55 GMT#015' Jul 08 19:54:54 rpi5-ws840 sudo[2706]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jul 08 19:54:55 rpi5-ws840 setdatetime-helper.sh[2707]: Tue Jul 8 19:54:55 CEST 2025 Jul 08 19:54:55 rpi5-ws840 sudo[2706]: pam_unix(sudo:session): session closed for user root Jul 08 19:54:55 rpi5-ws840 setdatetime-helper.sh[2697]: Time synchronized successfully. Jul 08 19:54:55 rpi5-ws840 systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jul 08 19:54:55 rpi5-ws840 systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jul 08 19:54:55 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:55 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:55 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:55 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:55 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:55 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:56 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:56 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:56 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:56 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:57 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:57 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:57 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:57 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:57 rpi5-ws840 volumio[1369]: info: Initializing connection to go-librespot Websocket Jul 08 19:54:57 rpi5-ws840 volumio[1369]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 19:54:57 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jul 08 19:54:57 rpi5-ws840 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 19:54:57 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:57 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:57 rpi5-ws840 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 19:54:57 rpi5-ws840 go-librespot[2708]: go-librespot daemon starting... Jul 08 19:54:57 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:57+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 19:54:57 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:57+02:00" level=debug msg="app state loaded" Jul 08 19:54:57 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:57+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=info msg="zeroconf server listening on port 37073" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="obtained new client token: AABnFBnwc+O38NBsTsDlmWsftJMTJq5p0yNBI9mLaMctSq70H8BbjZNrOX64W2B9Ir8msbp8Zqe4Z1XZGfhH2Q2uclfl1aMfDR9NzivErF7KAGoVEtErL/1J+7chnZ/zIjPYLFPs+C+eEx65e/nFJ2LFuO5ylf6Cec9FDDwcCWURRQmHC8vFg+FampFIWRhFBhPCqFHgcvP/vmC/Hryrp+YHScBBWiL5yOCKpFyy3uT5izsbZkTy2ov/NPY=" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="completed keyexchange" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="completed challenge" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=info msg="authenticated AP as z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:54:58 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:58 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=info msg="authenticated Login5 as z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="initializing zeroconf session, username: z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="dealer connection opened" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=trace msg="starting dealer recv loop" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=trace msg="received accesspoint ping" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="received connection id: NWVkYjZkNmYtZjdmMi00Y2Q4LWE1MWMtYWE3MjQyMDBiYmFlK2RlYWxlcit0Y3A6Ly8wYWIxNTIwZi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRDg5RTg3OEU0RjE1QzhENUQwRDAzRjQ1REE2MkI3QTQzMDBFOERCNDAzRTZCMTFDOTREMTlFNDQ3OTg5RDhDNw==" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=trace msg="received accesspoint pong ack" Jul 08 19:54:58 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:58+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 19:54:58 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:58 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: [1751997299307] ControllerSpotify::clearAddPlayTrack Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:59+02:00" level=debug msg="resolved context of track" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:59+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:59+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:59+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:59+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:59+02:00" level=debug msg="selected format OGG_VORBIS_320 (004b8a787e861e2a2df69a327ec9bfaae911c167)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:59+02:00" level=debug msg="requested aes key for file 004b8a787e861e2a2df69a327ec9bfaae911c167, gid: 6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:59+02:00" level=debug msg="fetched first chunk of 28, total size is 14354512 bytes" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:59+02:00" level=debug msg="created new output device" Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:59+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:59+02:00" level=debug msg="fetched chunk 2/27, size: 524288" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: time="2025-07-08T19:54:59+02:00" level=info msg="loaded track \"Nothing Else Matters - Remastered 2021\" (paused: false, position: 0ms, duration: 388733ms, prefetched: false)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:54:59 rpi5-ws840 go-librespot[2709]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 19:54:59 rpi5-ws840 go-librespot[2708]: Aborted Jul 08 19:54:59 rpi5-ws840 volumio[1369]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up Jul 08 19:54:59 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 19:54:59 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:54:59 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:00 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:00 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:00 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:00 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:00 rpi5-ws840 volumio[1369]: info: Initializing connection to go-librespot Websocket Jul 08 19:55:00 rpi5-ws840 volumio[1369]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index 0 Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: [1751997301939] ControllerSpotify::clearAddPlayTrack Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:55:01 rpi5-ws840 volumio[1369]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:01 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:02 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jul 08 19:55:02 rpi5-ws840 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 08 19:55:02 rpi5-ws840 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 08 19:55:02 rpi5-ws840 go-librespot[2722]: go-librespot daemon starting... Jul 08 19:55:02 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:02+02:00" level=info msg="running go-librespot 0.2.0" Jul 08 19:55:02 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:02+02:00" level=debug msg="app state loaded" Jul 08 19:55:02 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:02+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index 0 Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: [1751997302991] ControllerSpotify::clearAddPlayTrack Jul 08 19:55:02 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=info msg="zeroconf server listening on port 34337" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="obtained new client token: AABZ0p4rShkaLyEv1y3ou27mDZls+uA0bhb3ztqC3Wwag6yn+QSo0WQ+PrpN4ScJxpeXHvTDSg6tYFN/S9ROspQdmCSGWofUqsLGBnLMia2EpOKMfexmfeljhwPEmMTsTh9jQ+2Lf7cf86kNJMe6/0Rp+o61Td8mnnORZjjmcyxpqCY3O46vrE1O3VRzyhzchsJwztcYFSruaVhIp1fJBy6/J+N0CA2NXcp/eBYm7nDf9Wm+LYFLcrJja4Q=" Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: [1751997303182] ControllerSpotify::clearAddPlayTrack Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="completed keyexchange" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="completed challenge" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=info msg="authenticated AP as z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: [1751997303351] ControllerSpotify::clearAddPlayTrack Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=info msg="authenticated Login5 as z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="initializing zeroconf session, username: z4ujt0w8jsm3yt93kz6hrseoy" Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: [1751997303495] ControllerSpotify::clearAddPlayTrack Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="dealer connection opened" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=trace msg="starting accesspoint recv loop" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=trace msg="starting dealer recv loop" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=trace msg="received accesspoint ping" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="resolved context of track" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: [1751997303663] ControllerSpotify::clearAddPlayTrack Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: Initializing connection to go-librespot Websocket Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: Connection to go-librespot Websocket established Jul 08 19:55:03 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:03+02:00" level=debug msg="new websocket client" Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: [1751997303806] ControllerSpotify::clearAddPlayTrack Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: [1751997303973] ControllerSpotify::clearAddPlayTrack Jul 08 19:55:03 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioPlay Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index 0 Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CoreStateMachine::stop Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CoreStateMachine::play index undefined Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CoreStateMachine::startPlaybackTimer Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: [1751997304145] ControllerSpotify::clearAddPlayTrack Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: Sending Spotify command with payload to local API: /player/play Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:04 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:04+02:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:04 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:05 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:05 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:05 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:05 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:05 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:05+02:00" level=debug msg="put state request failed with status 400: Require at least one of callback url or connection id" Jul 08 19:55:05 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:05+02:00" level=error msg="failed put state after update" error="put state request failed with status 400: Require at least one of callback url or connection id" Jul 08 19:55:05 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:05+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 19:55:05 rpi5-ws840 volumio[1369]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6QAsrXPnMSXIbV0yEJHlEX","play_origin":"go-librespot"}} Jul 08 19:55:05 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:05+02:00" level=debug msg="selected format OGG_VORBIS_320 (004b8a787e861e2a2df69a327ec9bfaae911c167)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:05 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:05+02:00" level=debug msg="requested aes key for file 004b8a787e861e2a2df69a327ec9bfaae911c167, gid: 6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:06 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:06 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:06 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:06 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:06 rpi5-ws840 volumio[1369]: info: Getting Spotify volume Jul 08 19:55:06 rpi5-ws840 volumio[1369]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 15 Jul 08 19:55:06 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:06 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:06 rpi5-ws840 volumio[1369]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 08 19:55:06 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:06 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:07 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:07 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:07 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:07 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:08 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:08 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:08 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:08 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:08 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:08 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:09 rpi5-ws840 volumio[1369]: verbose: New Socket.io Connection to 192.168.1.215:3000 from 192.168.1.171 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 14 Jul 08 19:55:09 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:09 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:09 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:09 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:10 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:10 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:10 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:10 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:10 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:10 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:11 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:11 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:11 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:11 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:12 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:12 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:12 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:12 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:13 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:13 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:13 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:13 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:13 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:13 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:13 rpi5-ws840 volumio[1369]: verbose: New Socket.io Connection to 192.168.1.215 from 192.168.1.106 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/138.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 14 Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetQueue Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CoreStateMachine::getQueue Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getQueue Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getHwuuid Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getUpdaterChannel Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CALLMETHOD: music_service inputs serialMonitorAction [object Object] Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: inputs , serialMonitorAction Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: Error : CoreCommandRouter::executeOnPlugin: No method [serialMonitorAction] in plugin inputs Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CALLMETHOD: system_controller motivocontrol displaySelection [object Object] Jul 08 19:55:14 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: motivocontrol , displaySelection Jul 08 19:55:15 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:15 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:15 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:15 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:15 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:15 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:16 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:16 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:16 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:16 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:16 rpi5-ws840 volumio[1369]: info: CALLMETHOD: system_controller system setTestPlugins true Jul 08 19:55:16 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , setTestPlugins Jul 08 19:55:16 rpi5-ws840 volumio[1369]: info: Plugins store is now in test mode Jul 08 19:55:17 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:17 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:17 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:17 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:17 rpi5-ws840 volumio[1369]: info: CALLMETHOD: system_controller system enableSSH true Jul 08 19:55:17 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , enableSSH Jul 08 19:55:17 rpi5-ws840 sudo[2759]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start ssh.service Jul 08 19:55:17 rpi5-ws840 sudo[2759]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 08 19:55:17 rpi5-ws840 sudo[2759]: pam_unix(sudo:session): session closed for user root Jul 08 19:55:17 rpi5-ws840 sudo[2761]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl enable ssh.service Jul 08 19:55:17 rpi5-ws840 sudo[2761]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 08 19:55:17 rpi5-ws840 systemd[1]: Reloading. Jul 08 19:55:17 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:17 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:18 rpi5-ws840 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. Jul 08 19:55:18 rpi5-ws840 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. Jul 08 19:55:18 rpi5-ws840 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. Jul 08 19:55:18 rpi5-ws840 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. Jul 08 19:55:18 rpi5-ws840 systemd[1]: Reloading. Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:18 rpi5-ws840 volumio[1369]: verbose: New Socket.io Connection to 192.168.1.215 from 192.168.1.106 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/138.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 14 Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:18 rpi5-ws840 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. Jul 08 19:55:18 rpi5-ws840 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. Jul 08 19:55:18 rpi5-ws840 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. Jul 08 19:55:18 rpi5-ws840 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. Jul 08 19:55:18 rpi5-ws840 systemd[1]: Reloading. Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetVisibleSources Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetQueue Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreStateMachine::getQueue Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getQueue Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: Listing playlists Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: Received Get System Info Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: Discovery: Getting this device information Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:18 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:19 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jul 08 19:55:19 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 08 19:55:19 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jul 08 19:55:19 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:19 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:19 rpi5-ws840 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. Jul 08 19:55:19 rpi5-ws840 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. Jul 08 19:55:19 rpi5-ws840 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. Jul 08 19:55:19 rpi5-ws840 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. Jul 08 19:55:19 rpi5-ws840 sudo[2761]: pam_unix(sudo:session): session closed for user root Jul 08 19:55:19 rpi5-ws840 volumio[1369]: info: enable SSH service success Jul 08 19:55:19 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:19 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: Received Get System Info Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: Discovery: Getting this device information Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jul 08 19:55:20 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:20+02:00" level=debug msg="received connection id: Mzc3ODQ3NDctMTJiZC00YTM5LWI2YjEtODJjZDdmMjFiNmNhK2RlYWxlcit0Y3A6Ly8wYWIxNTFhMy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQjAzQURCNzE1OTM5NjMyQkM5MDc4RTBGNjlGMzNEMzdGQTZFM0M0MDg2RjZFOEI1MDYwNUJBNTJBMzMzRTE4OA==" Jul 08 19:55:20 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:20+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:6QAsrXPnMSXIbV0yEJHlEX: failed retrieving audio key: context deadline exceeded" Jul 08 19:55:20 rpi5-ws840 volumio[1369]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:20 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:20 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:20+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 19:55:20 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:20+02:00" level=debug msg="resolved context of track" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:20 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:20+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:20 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:20+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:21 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 19:55:21 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:21+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 19:55:21 rpi5-ws840 volumio[1369]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6QAsrXPnMSXIbV0yEJHlEX","play_origin":"go-librespot"}} Jul 08 19:55:21 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:21+02:00" level=debug msg="selected format OGG_VORBIS_320 (004b8a787e861e2a2df69a327ec9bfaae911c167)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:21 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:21+02:00" level=debug msg="requested aes key for file 004b8a787e861e2a2df69a327ec9bfaae911c167, gid: 6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:21 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:21 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:21 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 08 19:55:21 rpi5-ws840 volumio[1369]: info: Received Get System Info Jul 08 19:55:21 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:55:21 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:55:21 rpi5-ws840 volumio[1369]: info: Discovery: Getting this device information Jul 08 19:55:21 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:21 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:21 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:55:21 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:21 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:22 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:22 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:22 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:22 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:22 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:22 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:22 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:22 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:23 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:23 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:23 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:23 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:24 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:24 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:24 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:24 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:24 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:24 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:24 rpi5-ws840 systemd[1]: systemd-timedated.service: Deactivated successfully. Jul 08 19:55:25 rpi5-ws840 volumio[1369]: info: Executing endpoint metavolumio Jul 08 19:55:25 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:55:25 rpi5-ws840 volumio[1369]: info: Executing endpoint metavolumio Jul 08 19:55:25 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:55:25 rpi5-ws840 volumio[1369]: info: Executing endpoint metavolumio Jul 08 19:55:25 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:55:25 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:25 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:25 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:25 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:26 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:26 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:26 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:26 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:26 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:26 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:26 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:26 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:27 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:27 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:27 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:27 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: Executing endpoint metavolumio Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: Executing endpoint metavolumio Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: Executing endpoint metavolumio Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:28 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:29 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:29 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:29 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:29 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:30 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:30 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:30 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:30 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:31 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:31 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:31 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:31 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:31 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:31 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:32 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:32 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:32 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:32 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:33 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:33 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:33 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:33 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:33 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:33+02:00" level=trace msg="sent dealer ping" Jul 08 19:55:33 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:33+02:00" level=trace msg="received dealer pong" Jul 08 19:55:33 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:33 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:34 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:34 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:34 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:34 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:35 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:35 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:35 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:35 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:35 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:35 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:36 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:36+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:6QAsrXPnMSXIbV0yEJHlEX: failed retrieving audio key: context deadline exceeded" Jul 08 19:55:36 rpi5-ws840 volumio[1369]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Jul 08 19:55:36 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:36+02:00" level=debug msg="resolved context of track" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:36 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:36+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:36 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:36+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:36 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 19:55:36 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:36+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 19:55:36 rpi5-ws840 volumio[1369]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6QAsrXPnMSXIbV0yEJHlEX","play_origin":"go-librespot"}} Jul 08 19:55:36 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:36+02:00" level=debug msg="selected format OGG_VORBIS_320 (004b8a787e861e2a2df69a327ec9bfaae911c167)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:36 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:36+02:00" level=debug msg="requested aes key for file 004b8a787e861e2a2df69a327ec9bfaae911c167, gid: 6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: Received Get System Version Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: Received Get System Info Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: Discovery: Getting this device information Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:36 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:37 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:37 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:37 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:37 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:37 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:37 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:38 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:38 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:38 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:38 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:39 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:39 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:39 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:39 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:39 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:39 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:40 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:40 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:40 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:40 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:41 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:41 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:41 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:41 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:42 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:42 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:42 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:42 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:42 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jul 08 19:55:42 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:42 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:43 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:43 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:43 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:43 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:44 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:44 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:44 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:44 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:44 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:44 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:45 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 08 19:55:45 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 08 19:55:45 rpi5-ws840 volumio[1369]: info: Discovery: Getting this device information Jul 08 19:55:45 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:45 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:45 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 08 19:55:45 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:45 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:45 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:45 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:46 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:46 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:46 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:46 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:46 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:46 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:47 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:47 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:47 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:47 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:48 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:48 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:48 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:48 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:48 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:48 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:49 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:49 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:49 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:49 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:50 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:50 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:50 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:50 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:51 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:51 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:6QAsrXPnMSXIbV0yEJHlEX: failed retrieving audio key: context deadline exceeded" Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=trace msg="received accesspoint pong ack" Jul 08 19:55:51 rpi5-ws840 volumio[1369]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Jul 08 19:55:51 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:51 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=debug msg="resolved context of track" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=trace msg="emitting websocket event: will_play" Jul 08 19:55:51 rpi5-ws840 volumio[1369]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6QAsrXPnMSXIbV0yEJHlEX","play_origin":"go-librespot"}} Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=debug msg="selected format OGG_VORBIS_320 (004b8a787e861e2a2df69a327ec9bfaae911c167)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=debug msg="requested aes key for file 004b8a787e861e2a2df69a327ec9bfaae911c167, gid: 6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:51 rpi5-ws840 volumio[1369]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatest/spop/volumio/bookworm/armhf Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=debug msg="fetched first chunk of 28, total size is 14354512 bytes" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=debug msg="created new output device" Jul 08 19:55:51 rpi5-ws840 volumio[1369]: info: CoreCommandRouter::volumioGetState Jul 08 19:55:51 rpi5-ws840 volumio[1369]: info: CorePlayQueue::getTrack 0 Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: time="2025-07-08T19:55:51+02:00" level=info msg="loaded track \"Nothing Else Matters - Remastered 2021\" (paused: false, position: 0ms, duration: 388733ms, prefetched: false)" uri="spotify:track:6QAsrXPnMSXIbV0yEJHlEX" Jul 08 19:55:51 rpi5-ws840 go-librespot[2723]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Jul 08 19:55:51 rpi5-ws840 go-librespot[2722]: Aborted Jul 08 19:55:51 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Jul 08 19:55:51 rpi5-ws840 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 08 19:55:51 rpi5-ws840 volumio[1369]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 19:55:51 rpi5-ws840 volumio[1369]: Error: socket hang up Jul 08 19:55:51 rpi5-ws840 volumio[1369]: at connResetException (node:internal/errors:720:14) Jul 08 19:55:51 rpi5-ws840 volumio[1369]: at Socket.socketOnEnd (node:_http_client:519:23) Jul 08 19:55:51 rpi5-ws840 volumio[1369]: at Socket.emit (node:events:526:35) Jul 08 19:55:51 rpi5-ws840 volumio[1369]: at endReadableNT (node:internal/streams/readable:1376:12) Jul 08 19:55:51 rpi5-ws840 volumio[1369]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jul 08 19:55:51 rpi5-ws840 volumio[1369]: code: 'ECONNRESET', Jul 08 19:55:51 rpi5-ws840 volumio[1369]: response: undefined Jul 08 19:55:51 rpi5-ws840 volumio[1369]: } Jul 08 19:55:51 rpi5-ws840 volumio[1369]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 19:55:52 rpi5-ws840 sudo[2886]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-07-08 19:54' Jul 08 19:55:52 rpi5-ws840 sudo[2886]: 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="4f980d5cf693b4272997a2fa2da8bb8036ddf1ab" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="811ff8312d42f9da0260be1d353081a805678820" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Jul 5 02:50:33 UTC 2025" VOLUMIO_VERSION="4.015" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d42ab79cc13d24482826e04fda2e8350"