-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Tue 2025-04-29 22:26:50 CEST. -- Apr 29 22:25:00 beolab-8000 volumio[983]: info: Getting Spotify volume Apr 29 22:25:00 beolab-8000 volumio[983]: info: Spotify volume: 100 Apr 29 22:25:00 beolab-8000 volumio[983]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Apr 29 22:25:01 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioGetState Apr 29 22:25:01 beolab-8000 volumio[983]: info: CorePlayQueue::getTrack 0 Apr 29 22:25:01 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:25:01 beolab-8000 volumio[983]: SPOTIFY: SPOTIFY VOLUME 100 Apr 29 22:25:01 beolab-8000 volumio[983]: SPOTIFY: VOLUMIO VOLUME 20 Apr 29 22:25:01 beolab-8000 volumio[983]: SPOTIFY: DELTA VOLUME ENOUGH: true Apr 29 22:25:01 beolab-8000 volumio[983]: info: Setting Spotify Volume from Volumio: 20 Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Apr 29 22:25:01 beolab-8000 volumio[983]: info: Adding plugin bluetooth to MyMusic Plugins Apr 29 22:25:01 beolab-8000 volumio[983]: info: Adding plugin multiroom to MyMusic Plugins Apr 29 22:25:01 beolab-8000 volumio[983]: info: Adding plugin metavolumio to MyMusic Plugins Apr 29 22:25:01 beolab-8000 volumio[983]: info: Adding plugin cd_controller to MyMusic Plugins Apr 29 22:25:01 beolab-8000 volumio[983]: info: Adding plugin smart_inputs to MyMusic Plugins Apr 29 22:25:01 beolab-8000 volumio[983]: info: Adding plugin tidalconnect to MyMusic Plugins Apr 29 22:25:01 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Apr 29 22:25:02 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Apr 29 22:25:02 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Apr 29 22:25:02 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 29 22:25:02 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 29 22:25:02 beolab-8000 volumio[983]: info: Starting MyVolumio Remote Streaming Endpoints Apr 29 22:25:02 beolab-8000 volumio[983]: info: MyVolumio login type: Token Apr 29 22:25:02 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Apr 29 22:25:02 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Apr 29 22:25:04 beolab-8000 volumio[983]: info: Starting Streaming Service Transparent Proxy Apr 29 22:25:04 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Apr 29 22:25:04 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Apr 29 22:25:04 beolab-8000 volumio[983]: info: Streaming services startup Apr 29 22:25:04 beolab-8000 volumio[983]: info: Starting Streaming Daemon Apr 29 22:25:04 beolab-8000 sudo[1279]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Apr 29 22:25:04 beolab-8000 sudo[1279]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 29 22:25:04 beolab-8000 volumio[983]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Apr 29 22:25:04 beolab-8000 sudo[1279]: pam_unix(sudo:session): session closed for user root Apr 29 22:25:04 beolab-8000 volumio[983]: SPOTIFY: SETTING SPOTIFY VOLUME 20 Apr 29 22:25:04 beolab-8000 volumio[983]: info: Sending Spotify command with payload to local API: /player/volume Apr 29 22:25:04 beolab-8000 go-librespot[1183]: time="2025-04-29T22:25:04+02:00" level=debug msg="update volume to 13107/65535" Apr 29 22:25:04 beolab-8000 volumio[983]: error: Cannot start Volumio Streaming Daemon Apr 29 22:25:04 beolab-8000 volumio[983]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Apr 29 22:25:04 beolab-8000 volumio[983]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Apr 29 22:25:04 beolab-8000 volumio[983]: error: MyVolumio Custom Token format not valid, refreshing it Apr 29 22:25:04 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 29 22:25:05 beolab-8000 volumio[983]: STREAMING PROXY: Starting server on port 3245 Apr 29 22:25:05 beolab-8000 volumio[983]: Node JS runtime: 14 Apr 29 22:25:05 beolab-8000 go-librespot[1183]: time="2025-04-29T22:25:05+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 29 22:25:05 beolab-8000 go-librespot[1183]: time="2025-04-29T22:25:05+02:00" level=trace msg="emitting websocket event: volume" Apr 29 22:25:05 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"volume","data":{"value":20,"max":100}} Apr 29 22:25:05 beolab-8000 volumio[983]: SPOTIFY: RECEIVED SPOTIFY VOLUME 20 Apr 29 22:25:06 beolab-8000 volumio[983]: info: MyVolumio login type: Token Apr 29 22:25:06 beolab-8000 volumio[983]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Apr 29 22:25:07 beolab-8000 volumio[983]: info: MyVolumio token set successfully Apr 29 22:25:07 beolab-8000 volumio[983]: info: MYVOLUMIO: Adding device Apr 29 22:25:07 beolab-8000 volumio[983]: info: MYVOLUMIO: Evaluating Server Apr 29 22:25:07 beolab-8000 volumio[983]: info: MyVolumio status changed Apr 29 22:25:07 beolab-8000 volumio[983]: info: Streaming services startup Apr 29 22:25:07 beolab-8000 volumio[983]: info: Starting Streaming Daemon Apr 29 22:25:07 beolab-8000 volumio[983]: info: Removing browser output: myVolumio user plan is not superstar Apr 29 22:25:07 beolab-8000 volumio[983]: info: Removing audio output: Apr 29 22:25:07 beolab-8000 volumio[983]: info: Stoppping Tunnel 1 Apr 29 22:25:07 beolab-8000 sudo[1319]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Apr 29 22:25:07 beolab-8000 sudo[1319]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 29 22:25:07 beolab-8000 sudo[1319]: pam_unix(sudo:session): session closed for user root Apr 29 22:25:07 beolab-8000 volumio[983]: error: Cannot start Volumio Streaming Daemon Apr 29 22:25:07 beolab-8000 volumio[983]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Apr 29 22:25:07 beolab-8000 volumio[983]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Apr 29 22:25:07 beolab-8000 sudo[1322]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Apr 29 22:25:07 beolab-8000 sudo[1322]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 29 22:25:07 beolab-8000 sudo[1322]: pam_unix(sudo:session): session closed for user root Apr 29 22:25:07 beolab-8000 volumio[983]: info: Remote SSH Stopped Apr 29 22:25:07 beolab-8000 volumio[983]: info: Setting Geolocation for MyVolumio to eu2 Apr 29 22:25:07 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 29 22:25:07 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 29 22:25:07 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 29 22:25:08 beolab-8000 volumio[983]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Apr 29 22:25:08 beolab-8000 volumio[983]: info: Updating MyVolumio device info Apr 29 22:25:08 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 29 22:25:08 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 29 22:25:08 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 29 22:25:09 beolab-8000 systemd[1]: systemd-timedated.service: Succeeded. Apr 29 22:25:09 beolab-8000 volumio[983]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Apr 29 22:25:12 beolab-8000 volumio[983]: info: MYVOLUMIO: Adding device Apr 29 22:25:12 beolab-8000 volumio[983]: info: MYVOLUMIO: Evaluating Server Apr 29 22:25:12 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 29 22:25:12 beolab-8000 volumio[983]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Apr 29 22:25:12 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Apr 29 22:25:12 beolab-8000 volumio[983]: info: Received Get System Version Apr 29 22:25:12 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 29 22:25:12 beolab-8000 volumio[983]: info: Received Get System Info Apr 29 22:25:12 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 29 22:25:12 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 29 22:25:12 beolab-8000 volumio[983]: info: Discovery: Getting this device information Apr 29 22:25:12 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioGetState Apr 29 22:25:12 beolab-8000 volumio[983]: info: CorePlayQueue::getTrack 0 Apr 29 22:25:12 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 29 22:25:13 beolab-8000 volumio[1252]: .......................................................................................................................++++ Apr 29 22:25:13 beolab-8000 volumio[1252]: e is 65537 (0x010001) Apr 29 22:25:13 beolab-8000 volumio[1252]: writing RSA key Apr 29 22:25:17 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 29 22:25:17 beolab-8000 volumio[983]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Apr 29 22:25:17 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioGetState Apr 29 22:25:17 beolab-8000 volumio[983]: info: CorePlayQueue::getTrack 0 Apr 29 22:25:17 beolab-8000 volumio[983]: info: Setting Geolocation for MyVolumio to eu2 Apr 29 22:25:17 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 29 22:25:17 beolab-8000 volumiologrotate[570]: ls: cannot access '/var/log/samba/log.wb-BEOLAB': No such file or directory Apr 29 22:25:17 beolab-8000 volumiologrotate[570]: ls: cannot access '8000': No such file or directory Apr 29 22:25:18 beolab-8000 volumio[983]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Apr 29 22:25:18 beolab-8000 volumio[983]: info: Updating MyVolumio device info Apr 29 22:25:18 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 29 22:25:19 beolab-8000 volumio[983]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Apr 29 22:25:21 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 29 22:25:21 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 29 22:25:21 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 29 22:25:21 beolab-8000 volumio-remote-updater[613]: No test mode Apr 29 22:25:21 beolab-8000 volumio-remote-updater[613]: No alpha test mode Apr 29 22:25:21 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Apr 29 22:25:21 beolab-8000 volumio[983]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Apr 29 22:25:21 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Apr 29 22:25:22 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 29 22:25:22 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 29 22:25:22 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Apr 29 22:25:22 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Apr 29 22:25:22 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Apr 29 22:25:22 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Apr 29 22:25:22 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioGetBrowseSources Apr 29 22:25:22 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 29 22:25:23 beolab-8000 go-librespot[1183]: time="2025-04-29T22:25:23+02:00" level=trace msg="sent dealer ping" Apr 29 22:25:23 beolab-8000 go-librespot[1183]: time="2025-04-29T22:25:23+02:00" level=trace msg="received dealer pong" Apr 29 22:25:24 beolab-8000 volumio[983]: error: MyVolumio Plugin failed to authenticate in a timely fashion Apr 29 22:25:24 beolab-8000 volumio[983]: info: Completed starting MyVolumio Plugin Apr 29 22:25:24 beolab-8000 volumio[983]: [Metrics] CommandRouter: 42s 551.83ms Apr 29 22:25:24 beolab-8000 volumio[983]: info: CoreCommandRouter::volumiosetStartupVolume Apr 29 22:25:24 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 29 22:25:24 beolab-8000 volumio[983]: info: VolumeController:: Setting startup Volume 20 Apr 29 22:25:24 beolab-8000 volumio[983]: info: VolumeController::SetAlsaVolume20 Apr 29 22:25:24 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 29 22:25:24 beolab-8000 volumio[983]: info: CoreCommandRouter::Close All Modals sent Apr 29 22:25:24 beolab-8000 volumio[983]: info: CoreCommandRouter::Close All Modals sent Apr 29 22:25:24 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:25:24 beolab-8000 volumio[983]: info: CorePlayQueue::getTrack 0 Apr 29 22:25:24 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:25:24 beolab-8000 volumio[983]: info: [ASDebug] CurState: stop PrevState: stop Apr 29 22:25:24 beolab-8000 volumio[983]: info: [GPIO_Control] Status changed: stop Apr 29 22:25:24 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:25:25 beolab-8000 ntpd[763]: Soliciting pool server 194.104.0.153 Apr 29 22:25:25 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Apr 29 22:25:25 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Apr 29 22:25:25 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Apr 29 22:25:26 beolab-8000 ntpd[763]: Soliciting pool server 5.255.99.180 Apr 29 22:25:26 beolab-8000 ntpd[763]: Soliciting pool server 162.159.200.123 Apr 29 22:25:27 beolab-8000 ntpd[763]: Soliciting pool server 45.32.4.67 Apr 29 22:25:27 beolab-8000 ntpd[763]: Soliciting pool server 81.172.248.188 Apr 29 22:25:28 beolab-8000 ntpd[763]: Soliciting pool server 45.159.204.28 Apr 29 22:25:28 beolab-8000 ntpd[763]: Soliciting pool server 94.198.159.15 Apr 29 22:25:28 beolab-8000 ntpd[763]: Soliciting pool server 185.51.192.61 Apr 29 22:25:29 beolab-8000 ntpd[763]: Soliciting pool server 185.71.60.123 Apr 29 22:25:29 beolab-8000 ntpd[763]: Soliciting pool server 185.244.24.70 Apr 29 22:25:29 beolab-8000 ntpd[763]: Soliciting pool server 193.111.32.123 Apr 29 22:25:30 beolab-8000 ntpd[763]: Soliciting pool server 185.51.192.63 Apr 29 22:25:30 beolab-8000 ntpd[763]: Soliciting pool server 191.96.11.19 Apr 29 22:25:30 beolab-8000 ntpd[763]: Soliciting pool server 95.211.123.72 Apr 29 22:25:31 beolab-8000 ntpd[763]: Soliciting pool server 5.200.6.34 Apr 29 22:25:31 beolab-8000 ntpd[763]: Soliciting pool server 45.138.55.62 Apr 29 22:25:31 beolab-8000 ntpd[763]: Soliciting pool server 80.60.67.39 Apr 29 22:25:31 beolab-8000 volumio[983]: info: BOOT COMPLETED Apr 29 22:25:34 beolab-8000 ntpd[763]: receive: Unexpected origin timestamp 0xebbbb43e.0247dece does not match aorg 0000000000.00000000 from server@185.244.24.70 xmt 0xebbbb43e.900684b8 Apr 29 22:25:34 beolab-8000 ntpd[763]: receive: Unexpected origin timestamp 0xebbbb43e.024a14ff does not match aorg 0000000000.00000000 from server@81.172.248.188 xmt 0xebbbb43e.901d883e Apr 29 22:25:34 beolab-8000 ntpd[763]: receive: Unexpected origin timestamp 0xebbbb43e.02443017 does not match aorg 0000000000.00000000 from server@45.138.55.62 xmt 0xebbbb43e.906e2419 Apr 29 22:25:34 beolab-8000 ntpd[763]: receive: Unexpected origin timestamp 0xebbbb43e.02491092 does not match aorg 0000000000.00000000 from server@45.32.4.67 xmt 0xebbbb43e.99e3d106 Apr 29 22:25:53 beolab-8000 go-librespot[1183]: time="2025-04-29T22:25:53+02:00" level=trace msg="sent dealer ping" Apr 29 22:25:53 beolab-8000 go-librespot[1183]: time="2025-04-29T22:25:53+02:00" level=trace msg="received dealer pong" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=debug msg="handling transfer player command from 6f5c6e580f70ac6059c59a68c520a14227b2eae0" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=debug msg="resolved context of track" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page 1 with 11 items (list: 21)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page 2 with 3 items (list: 24)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page 3 with 2 items (list: 26)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page 4 with 1 items (list: 27)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page 5 with 5 items (list: 32)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page 6 with 1 items (list: 33)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page 7 with 1 items (list: 34)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page 8 with 1 items (list: 35)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page 9 with 1 items (list: 36)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page 10 with 1 items (list: 37)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page from (has next: false)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="fetched new page 11 with 1 items (list: 38)" uri="spotify:artist:3k3RY7kR8f0vp8Cq27P141" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=debug msg="loading track (paused: false, position: 4812741ms)" uri="spotify:track:62MSbv3IJNlQdN2NMfOGny" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=trace msg="emitting websocket event: will_play" Apr 29 22:26:02 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:62MSbv3IJNlQdN2NMfOGny","play_origin":"free-tier-artist"}} Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=debug msg="selected format OGG_VORBIS_320 (1c2451b8af5468bf47bef0f129fb026ceec446bf)" uri="spotify:track:62MSbv3IJNlQdN2NMfOGny" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=debug msg="requested aes key for file 1c2451b8af5468bf47bef0f129fb026ceec446bf, gid: 62MSbv3IJNlQdN2NMfOGny" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3264" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=debug msg="fetched first chunk of 14, total size is 7267324 bytes" uri="spotify:track:62MSbv3IJNlQdN2NMfOGny" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2080" Apr 29 22:26:02 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:02+02:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:62MSbv3IJNlQdN2NMfOGny" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:62MSbv3IJNlQdN2NMfOGny" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="fetched chunk 13/13, size: 451580" uri="spotify:track:62MSbv3IJNlQdN2NMfOGny" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=trace msg="seek to 192000ms (diff: 2298ms, samples: 8467200, bytes: 7254487)" uri="spotify:track:62MSbv3IJNlQdN2NMfOGny" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="created new output device" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+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" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=info msg="loaded track \"ascension\" (paused: false, position: 4812741ms, duration: 192000ms, prefetched: false)" uri="spotify:track:62MSbv3IJNlQdN2NMfOGny" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=trace msg="emitting websocket event: metadata" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="prefetching next track" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=trace msg="emitting websocket event: active" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="sending successful reply for dealer request" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:62MSbv3IJNlQdN2NMfOGny","name":"ascension","artist_names":["berlioz"],"album_name":"open this wall","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","position":4812741,"duration":192000,"release_date":"year:2024 month:7 day:12","track_number":1,"disc_number":1}} Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"active","data":null} Apr 29 22:26:03 beolab-8000 volumio[983]: info: Aligning Spotify Volume to Volumio Volume Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioGetState Apr 29 22:26:03 beolab-8000 volumio[983]: info: CorePlayQueue::getTrack 0 Apr 29 22:26:03 beolab-8000 volumio[983]: info: Setting Spotify Volume from Volumio: 20 Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="selected format OGG_VORBIS_320 (e6b71c2224f8b9a42acf48673802c6a5431a7686)" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="requested aes key for file e6b71c2224f8b9a42acf48673802c6a5431a7686, gid: 4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:62MSbv3IJNlQdN2NMfOGny" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=trace msg="emitting websocket event: playing" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=trace msg="emitting websocket event: not_playing" Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:62MSbv3IJNlQdN2NMfOGny","play_origin":"free-tier-artist"}} Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:03 beolab-8000 volumio[983]: info: Spotify is playing in volatile mode Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: UNSET VOLATILE Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":20,"dbVolume":null,"mute":false,"disableVolumeControl":false,"random":null,"repeat":null,"repeatSingle":false,"updatedb":false,"consume":false} Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: {"status":"play","service":"spop","title":"ascension","artist":"berlioz","album":"open this wall","albumart":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","uri":"spotify:track:62MSbv3IJNlQdN2NMfOGny","trackType":"spotify","seek":4812741,"duration":192,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreCommandRouter::servicePushState Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:62MSbv3IJNlQdN2NMfOGny","play_origin":"free-tier-artist"}} Apr 29 22:26:03 beolab-8000 volumio[983]: error: Failed to decode event: not_playing Apr 29 22:26:03 beolab-8000 volumio[983]: info: [ASDebug] CurState: play PrevState: stop Apr 29 22:26:03 beolab-8000 volumio[983]: info: [ASDebug] Togle GPIO: ON Apr 29 22:26:03 beolab-8000 volumio[983]: info: [GPIO_Control] Status changed: play Apr 29 22:26:03 beolab-8000 volumio[983]: info: [GPIO_Control] Handling event: musicPlay Apr 29 22:26:03 beolab-8000 volumio[983]: info: [GPIO_Control] *** musicPlay *** Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:26:03 beolab-8000 volumio[983]: info: [GPIO_Control] Turning GPIO 0 On (musicPlay) Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=trace msg="emitting websocket event: will_play" Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","play_origin":"free-tier-artist"}} Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="selected format OGG_VORBIS_320 (e6b71c2224f8b9a42acf48673802c6a5431a7686)" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="requested aes key for file e6b71c2224f8b9a42acf48673802c6a5431a7686, gid: 4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: {"status":"play","service":"spop","title":"ascension","artist":"berlioz","album":"open this wall","albumart":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","uri":"spotify:track:62MSbv3IJNlQdN2NMfOGny","trackType":"spotify","seek":4812741,"duration":192,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreCommandRouter::servicePushState Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="fetched first chunk of 12, total size is 5829847 bytes" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=info msg="prefetched track \"open this wall\" (duration: 156688ms)" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="fetched first chunk of 12, total size is 5829847 bytes" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:03 beolab-8000 volumio[983]: info: [ASDebug] CurState: play PrevState: play Apr 29 22:26:03 beolab-8000 volumio[983]: info: [GPIO_Control] Status changed: play Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+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" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=info msg="loaded track \"open this wall\" (paused: false, position: 0ms, duration: 156688ms, prefetched: false)" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=trace msg="scheduling prefetch in 127s" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=trace msg="emitting websocket event: metadata" Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","name":"open this wall","artist_names":["berlioz"],"album_name":"open this wall","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","position":0,"duration":156688,"release_date":"year:2024 month:7 day:12","track_number":2,"disc_number":1}} Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:03 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:03+02:00" level=trace msg="emitting websocket event: playing" Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","play_origin":"free-tier-artist"}} Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 22:26:03 beolab-8000 volumio[983]: SPOTIFY: {"status":"play","service":"spop","title":"open this wall","artist":"berlioz","album":"open this wall","albumart":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","trackType":"spotify","seek":0,"duration":156,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreCommandRouter::servicePushState Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 22:26:03 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:26:03 beolab-8000 volumio[983]: info: [ASDebug] CurState: play PrevState: play Apr 29 22:26:04 beolab-8000 volumio[983]: info: [GPIO_Control] Status changed: play Apr 29 22:26:04 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:26:04 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:04+02:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:04 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:04+02:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:04 beolab-8000 volumio[983]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 22:26:04 beolab-8000 volumio[983]: SPOTIFY: {"status":"play","service":"spop","title":"open this wall","artist":"berlioz","album":"open this wall","albumart":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","trackType":"spotify","seek":0,"duration":156,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 29 22:26:04 beolab-8000 volumio[983]: info: CoreCommandRouter::servicePushState Apr 29 22:26:04 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:26:04 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:26:04 beolab-8000 volumio[983]: info: [ASDebug] CurState: play PrevState: play Apr 29 22:26:04 beolab-8000 volumio[983]: info: [GPIO_Control] Status changed: play Apr 29 22:26:04 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:26:04 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:04+02:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:04 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:04+02:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:04 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:04+02:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:04 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:04+02:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:04 beolab-8000 volumio[983]: SPOTIFY: SETTING SPOTIFY VOLUME 20 Apr 29 22:26:04 beolab-8000 volumio[983]: info: Sending Spotify command with payload to local API: /player/volume Apr 29 22:26:04 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:04+02:00" level=debug msg="update volume to 13107/65535" Apr 29 22:26:05 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:05+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 29 22:26:05 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:05+02:00" level=trace msg="emitting websocket event: volume" Apr 29 22:26:05 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"volume","data":{"value":20,"max":100}} Apr 29 22:26:05 beolab-8000 volumio[983]: SPOTIFY: RECEIVED SPOTIFY VOLUME 20 Apr 29 22:26:09 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:09+02:00" level=debug msg="handling pause player command from 6f5c6e580f70ac6059c59a68c520a14227b2eae0" Apr 29 22:26:09 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:09+02:00" level=debug msg="pause track at 6200ms" Apr 29 22:26:09 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:09+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:09 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:09+02:00" level=debug msg="sending successful reply for dealer request" Apr 29 22:26:09 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:09+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:09 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:09+02:00" level=trace msg="emitting websocket event: paused" Apr 29 22:26:09 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","play_origin":"free-tier-artist"}} Apr 29 22:26:09 beolab-8000 volumio[983]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 22:26:09 beolab-8000 volumio[983]: SPOTIFY: {"status":"pause","service":"spop","title":"open this wall","artist":"berlioz","album":"open this wall","albumart":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","trackType":"spotify","seek":6000,"duration":156,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 29 22:26:09 beolab-8000 volumio[983]: info: CoreCommandRouter::servicePushState Apr 29 22:26:09 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:26:09 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 22:26:09 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:26:10 beolab-8000 volumio[983]: info: [ASDebug] CurState: pause PrevState: play Apr 29 22:26:10 beolab-8000 volumio[983]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Apr 29 22:26:10 beolab-8000 volumio[983]: info: [GPIO_Control] Status changed: pause Apr 29 22:26:10 beolab-8000 volumio[983]: info: [GPIO_Control] Handling event: musicPause Apr 29 22:26:10 beolab-8000 volumio[983]: info: [GPIO_Control] *** musicPause *** Apr 29 22:26:10 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:26:10 beolab-8000 volumio[983]: info: [GPIO_Control] Turning GPIO 0 Off (musicPause) Apr 29 22:26:10 beolab-8000 volumio[983]: info: [ASDebug] Togle GPIO: OFF Apr 29 22:26:13 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:13+02:00" level=debug msg="handling resume player command from 6f5c6e580f70ac6059c59a68c520a14227b2eae0" Apr 29 22:26:13 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:13+02:00" level=trace msg="seek to 6200ms (diff: 107ms, samples: 273420, bytes: 224400)" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:13 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:13+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" Apr 29 22:26:13 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:13+02:00" level=debug msg="resume track at 6093ms" Apr 29 22:26:13 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:13 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:13+02:00" level=trace msg="scheduling prefetch in 121s" Apr 29 22:26:13 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:13+02:00" level=debug msg="sending successful reply for dealer request" Apr 29 22:26:13 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:13 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:13+02:00" level=trace msg="emitting websocket event: playing" Apr 29 22:26:13 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","play_origin":"free-tier-artist"}} Apr 29 22:26:13 beolab-8000 volumio[983]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 22:26:13 beolab-8000 volumio[983]: SPOTIFY: {"status":"play","service":"spop","title":"open this wall","artist":"berlioz","album":"open this wall","albumart":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","trackType":"spotify","seek":6000,"duration":156,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 29 22:26:13 beolab-8000 volumio[983]: info: CoreCommandRouter::servicePushState Apr 29 22:26:13 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:26:13 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 22:26:13 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:26:13 beolab-8000 volumio[983]: info: [ASDebug] CurState: play PrevState: pause Apr 29 22:26:13 beolab-8000 volumio[983]: info: [ASDebug] Togle GPIO: ON Apr 29 22:26:13 beolab-8000 volumio[983]: info: [GPIO_Control] Status changed: play Apr 29 22:26:13 beolab-8000 volumio[983]: info: [GPIO_Control] Handling event: musicPlay Apr 29 22:26:13 beolab-8000 volumio[983]: info: [GPIO_Control] *** musicPlay *** Apr 29 22:26:13 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:26:13 beolab-8000 volumio[983]: info: [GPIO_Control] Turning GPIO 0 On (musicPlay) Apr 29 22:26:14 beolab-8000 volumio[983]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 22:26:14 beolab-8000 volumio[983]: SPOTIFY: {"status":"play","service":"spop","title":"open this wall","artist":"berlioz","album":"open this wall","albumart":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","trackType":"spotify","seek":6000,"duration":156,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 29 22:26:14 beolab-8000 volumio[983]: info: CoreCommandRouter::servicePushState Apr 29 22:26:14 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:26:14 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:26:14 beolab-8000 volumio[983]: info: [ASDebug] CurState: play PrevState: play Apr 29 22:26:14 beolab-8000 volumio[983]: info: [GPIO_Control] Status changed: play Apr 29 22:26:14 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:26:15 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:15+02:00" level=debug msg="handling pause player command from 6f5c6e580f70ac6059c59a68c520a14227b2eae0" Apr 29 22:26:15 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:15+02:00" level=debug msg="pause track at 7953ms" Apr 29 22:26:15 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:15+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:15 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:15+02:00" level=debug msg="sending successful reply for dealer request" Apr 29 22:26:15 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:15+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:15 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:15+02:00" level=trace msg="emitting websocket event: paused" Apr 29 22:26:15 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","play_origin":"free-tier-artist"}} Apr 29 22:26:15 beolab-8000 volumio[983]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 22:26:15 beolab-8000 volumio[983]: SPOTIFY: {"status":"pause","service":"spop","title":"open this wall","artist":"berlioz","album":"open this wall","albumart":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","trackType":"spotify","seek":7000,"duration":156,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 29 22:26:15 beolab-8000 volumio[983]: info: CoreCommandRouter::servicePushState Apr 29 22:26:15 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:26:15 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 22:26:15 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:26:15 beolab-8000 volumio[983]: info: [ASDebug] CurState: pause PrevState: play Apr 29 22:26:15 beolab-8000 volumio[983]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Apr 29 22:26:15 beolab-8000 volumio[983]: info: [GPIO_Control] Status changed: pause Apr 29 22:26:15 beolab-8000 volumio[983]: info: [GPIO_Control] Handling event: musicPause Apr 29 22:26:15 beolab-8000 volumio[983]: info: [GPIO_Control] *** musicPause *** Apr 29 22:26:15 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:26:15 beolab-8000 volumio[983]: info: [GPIO_Control] Turning GPIO 0 Off (musicPause) Apr 29 22:26:16 beolab-8000 volumio[983]: info: [ASDebug] Togle GPIO: OFF Apr 29 22:26:17 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:17+02:00" level=debug msg="handling resume player command from 6f5c6e580f70ac6059c59a68c520a14227b2eae0" Apr 29 22:26:17 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:17+02:00" level=trace msg="seek to 7953ms (diff: 168ms, samples: 350727, bytes: 288235)" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:17 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:17+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" Apr 29 22:26:17 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:17+02:00" level=debug msg="resume track at 7785ms" Apr 29 22:26:17 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:17+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:17 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:17+02:00" level=trace msg="scheduling prefetch in 119s" Apr 29 22:26:17 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:17+02:00" level=debug msg="sending successful reply for dealer request" Apr 29 22:26:17 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:17+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:17 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:17+02:00" level=trace msg="emitting websocket event: playing" Apr 29 22:26:17 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","play_origin":"free-tier-artist"}} Apr 29 22:26:17 beolab-8000 volumio[983]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 22:26:17 beolab-8000 volumio[983]: SPOTIFY: {"status":"play","service":"spop","title":"open this wall","artist":"berlioz","album":"open this wall","albumart":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","trackType":"spotify","seek":7000,"duration":156,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 29 22:26:17 beolab-8000 volumio[983]: info: CoreCommandRouter::servicePushState Apr 29 22:26:17 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:26:17 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 22:26:17 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:26:17 beolab-8000 volumio[983]: info: [ASDebug] CurState: play PrevState: pause Apr 29 22:26:17 beolab-8000 volumio[983]: info: [ASDebug] Togle GPIO: ON Apr 29 22:26:17 beolab-8000 volumio[983]: info: [GPIO_Control] Status changed: play Apr 29 22:26:17 beolab-8000 volumio[983]: info: [GPIO_Control] Handling event: musicPlay Apr 29 22:26:17 beolab-8000 volumio[983]: info: [GPIO_Control] *** musicPlay *** Apr 29 22:26:17 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:26:17 beolab-8000 volumio[983]: info: [GPIO_Control] Turning GPIO 0 On (musicPlay) Apr 29 22:26:17 beolab-8000 volumio[983]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 22:26:17 beolab-8000 volumio[983]: SPOTIFY: {"status":"play","service":"spop","title":"open this wall","artist":"berlioz","album":"open this wall","albumart":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","trackType":"spotify","seek":7000,"duration":156,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 29 22:26:17 beolab-8000 volumio[983]: info: CoreCommandRouter::servicePushState Apr 29 22:26:17 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:26:17 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:26:18 beolab-8000 volumio[983]: info: [ASDebug] CurState: play PrevState: play Apr 29 22:26:18 beolab-8000 volumio[983]: info: [GPIO_Control] Status changed: play Apr 29 22:26:18 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:26:18 beolab-8000 volumiologrotate[570]: ls: cannot access '/var/log/samba/log.wb-BEOLAB': No such file or directory Apr 29 22:26:18 beolab-8000 volumiologrotate[570]: ls: cannot access '8000': No such file or directory Apr 29 22:26:19 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:19+02:00" level=debug msg="handling pause player command from 6f5c6e580f70ac6059c59a68c520a14227b2eae0" Apr 29 22:26:19 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:19+02:00" level=debug msg="pause track at 10024ms" Apr 29 22:26:19 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:19 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:19+02:00" level=debug msg="sending successful reply for dealer request" Apr 29 22:26:19 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:19 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:19+02:00" level=trace msg="emitting websocket event: paused" Apr 29 22:26:19 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","play_origin":"free-tier-artist"}} Apr 29 22:26:19 beolab-8000 volumio[983]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 22:26:19 beolab-8000 volumio[983]: SPOTIFY: {"status":"pause","service":"spop","title":"open this wall","artist":"berlioz","album":"open this wall","albumart":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","trackType":"spotify","seek":9000,"duration":156,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 29 22:26:19 beolab-8000 volumio[983]: info: CoreCommandRouter::servicePushState Apr 29 22:26:19 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:26:19 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 22:26:19 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:26:20 beolab-8000 volumio[983]: info: [ASDebug] CurState: pause PrevState: play Apr 29 22:26:20 beolab-8000 volumio[983]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Apr 29 22:26:20 beolab-8000 volumio[983]: info: [GPIO_Control] Status changed: pause Apr 29 22:26:20 beolab-8000 volumio[983]: info: [GPIO_Control] Handling event: musicPause Apr 29 22:26:20 beolab-8000 volumio[983]: info: [GPIO_Control] *** musicPause *** Apr 29 22:26:20 beolab-8000 volumio[983]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Apr 29 22:26:20 beolab-8000 volumio[983]: info: [GPIO_Control] Turning GPIO 0 Off (musicPause) Apr 29 22:26:20 beolab-8000 volumio[983]: info: [ASDebug] Togle GPIO: OFF Apr 29 22:26:23 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:23+02:00" level=trace msg="sent dealer ping" Apr 29 22:26:23 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:23+02:00" level=trace msg="received dealer pong" Apr 29 22:26:24 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 29 22:26:24 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 29 22:26:29 beolab-8000 volumio[983]: info: [ASDebug] Port: 2 Apr 29 22:26:29 beolab-8000 volumio[983]: info: [ASDebug] Inverted: false Apr 29 22:26:29 beolab-8000 volumio[983]: info: [ASDebug] Delay: 720 Apr 29 22:26:30 beolab-8000 volumio[983]: info: [GPIO_Control] Destroying GPIO 0 Apr 29 22:26:30 beolab-8000 volumio[983]: info: [GPIO_Control] Destroying GPIO 0 Apr 29 22:26:30 beolab-8000 volumio[983]: info: [GPIO_Control] GPIOs destroyed Apr 29 22:26:30 beolab-8000 volumio[983]: info: Disabling plugin gpio_control Apr 29 22:26:30 beolab-8000 volumio[983]: info: Done. Apr 29 22:26:33 beolab-8000 volumio[983]: info: Enabling plugin ampswitch Apr 29 22:26:33 beolab-8000 volumio[983]: info: Loading plugin "ampswitch"... Apr 29 22:26:33 beolab-8000 volumio[983]: info: Applying required configuration parameters for plugin ampswitch Apr 29 22:26:33 beolab-8000 volumio[983]: info: PLUGIN START: ampswitch Apr 29 22:26:33 beolab-8000 volumio[983]: info: Done. Apr 29 22:26:33 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioGetState Apr 29 22:26:33 beolab-8000 volumio[983]: info: [ASDebug] CurState: pause PrevState: pause Apr 29 22:26:33 beolab-8000 volumio[983]: info: [ASDebug] CurState: pause PrevState: pause Apr 29 22:26:33 beolab-8000 volumio[983]: info: [ASDebug] CurState: pause PrevState: pause Apr 29 22:26:35 beolab-8000 sudo[1706]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 29 22:26:35 beolab-8000 sudo[1706]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 29 22:26:35 beolab-8000 sudo[1706]: pam_unix(sudo:session): session closed for user root Apr 29 22:26:36 beolab-8000 sudo[1708]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 29 22:26:36 beolab-8000 sudo[1708]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 29 22:26:36 beolab-8000 sudo[1708]: pam_unix(sudo:session): session closed for user root Apr 29 22:26:36 beolab-8000 volumio[983]: verbose: New Socket.io Connection to 192.168.2.56 from 192.168.2.12 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioGetVisibleSources Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioGetState Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 29 22:26:36 beolab-8000 volumio[983]: info: Received Get System Info Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 29 22:26:36 beolab-8000 volumio[983]: info: Discovery: Getting this device information Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioGetState Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioGetState Apr 29 22:26:36 beolab-8000 volumio[983]: info: Listing playlists Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 29 22:26:36 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 29 22:26:37 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 29 22:26:37 beolab-8000 volumio[983]: info: Received Get System Info Apr 29 22:26:37 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 29 22:26:37 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 29 22:26:37 beolab-8000 volumio[983]: info: Discovery: Getting this device information Apr 29 22:26:37 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioGetState Apr 29 22:26:37 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 29 22:26:37 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 29 22:26:37 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Apr 29 22:26:40 beolab-8000 volumio[983]: info: Starting Uninstall of plugin system_controller - ampswitch Apr 29 22:26:40 beolab-8000 volumio[983]: info: Uninstalling plugin ampswitch Apr 29 22:26:40 beolab-8000 volumio[983]: info: [ASDebug] Port: 2 Apr 29 22:26:40 beolab-8000 volumio[983]: info: [ASDebug] Inverted: false Apr 29 22:26:40 beolab-8000 volumio[983]: info: [ASDebug] Delay: 720 Apr 29 22:26:41 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 29 22:26:41 beolab-8000 volumio[983]: info: Received Get System Info Apr 29 22:26:41 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 29 22:26:41 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 29 22:26:41 beolab-8000 volumio[983]: info: Discovery: Getting this device information Apr 29 22:26:41 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioGetState Apr 29 22:26:41 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 29 22:26:46 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 29 22:26:49 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:49+02:00" level=debug msg="handling resume player command from 6f5c6e580f70ac6059c59a68c520a14227b2eae0" Apr 29 22:26:49 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:49+02:00" level=trace msg="seek to 10024ms (diff: 159ms, samples: 442058, bytes: 371116)" uri="spotify:track:4m30cfL2qOwlFsuGqMOZ8k" Apr 29 22:26:49 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:49+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" Apr 29 22:26:49 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:49+02:00" level=debug msg="resume track at 9865ms" Apr 29 22:26:49 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:49+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:49 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:49+02:00" level=trace msg="scheduling prefetch in 117s" Apr 29 22:26:49 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:49+02:00" level=debug msg="sending successful reply for dealer request" Apr 29 22:26:50 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:50+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 29 22:26:50 beolab-8000 go-librespot[1183]: time="2025-04-29T22:26:50+02:00" level=trace msg="emitting websocket event: playing" Apr 29 22:26:50 beolab-8000 volumio[983]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","play_origin":"free-tier-artist"}} Apr 29 22:26:50 beolab-8000 volumio[983]: SPOTIFY: PUSH STATE SPOTIFY Apr 29 22:26:50 beolab-8000 volumio[983]: SPOTIFY: {"status":"play","service":"spop","title":"open this wall","artist":"berlioz","album":"open this wall","albumart":"https://i.scdn.co/image/ab67616d00001e02c1c672fa0dd740c2db9e66ae","uri":"spotify:track:4m30cfL2qOwlFsuGqMOZ8k","trackType":"spotify","seek":9000,"duration":156,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Apr 29 22:26:50 beolab-8000 volumio[983]: info: CoreCommandRouter::servicePushState Apr 29 22:26:50 beolab-8000 volumio[983]: info: CoreStateMachine::pushState Apr 29 22:26:50 beolab-8000 volumio[983]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 29 22:26:50 beolab-8000 volumio[983]: info: CoreCommandRouter::volumioPushState Apr 29 22:26:50 beolab-8000 volumio[983]: info: [ASDebug] CurState: play PrevState: pause Apr 29 22:26:50 beolab-8000 volumio[983]: info: [ASDebug] Togle GPIO: ON Apr 29 22:26:50 beolab-8000 volumio[983]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 29 22:26:50 beolab-8000 volumio[983]: Error: EBADF: bad file descriptor, write Apr 29 22:26:50 beolab-8000 volumio[983]: at Object.writeSync (fs.js:711:3) Apr 29 22:26:50 beolab-8000 volumio[983]: at Gpio.writeSync (/data/plugins/system_controller/ampswitch/node_modules/onoff/onoff.js:243:8) Apr 29 22:26:50 beolab-8000 volumio[983]: at AmpSwitchController.on (/data/plugins/system_controller/ampswitch/index.js:207:23) Apr 29 22:26:50 beolab-8000 volumio[983]: at AmpSwitchController.parseStatus (/data/plugins/system_controller/ampswitch/index.js:190:86) Apr 29 22:26:50 beolab-8000 volumio[983]: at Socket.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) Apr 29 22:26:50 beolab-8000 volumio[983]: at Socket.onevent (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/socket.js:278:10) Apr 29 22:26:50 beolab-8000 volumio[983]: at Socket.onpacket (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/socket.js:236:12) Apr 29 22:26:50 beolab-8000 volumio[983]: at Manager. (/data/plugins/system_controller/ampswitch/node_modules/component-bind/index.js:21:15) Apr 29 22:26:50 beolab-8000 volumio[983]: at Manager.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) Apr 29 22:26:50 beolab-8000 volumio[983]: at Manager.ondecoded (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/manager.js:349:8) Apr 29 22:26:50 beolab-8000 volumio[983]: at Decoder. (/data/plugins/system_controller/ampswitch/node_modules/component-bind/index.js:21:15) Apr 29 22:26:50 beolab-8000 volumio[983]: at Decoder.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) Apr 29 22:26:50 beolab-8000 volumio[983]: at Decoder.add (/data/plugins/system_controller/ampswitch/node_modules/socket.io-parser/index.js:254:12) Apr 29 22:26:50 beolab-8000 volumio[983]: at Manager.ondata (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/manager.js:339:16) Apr 29 22:26:50 beolab-8000 volumio[983]: at Socket. (/data/plugins/system_controller/ampswitch/node_modules/component-bind/index.js:21:15) Apr 29 22:26:50 beolab-8000 volumio[983]: at Socket.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) { Apr 29 22:26:50 beolab-8000 volumio[983]: errno: -9, Apr 29 22:26:50 beolab-8000 volumio[983]: syscall: 'write', Apr 29 22:26:50 beolab-8000 volumio[983]: code: 'EBADF' Apr 29 22:26:50 beolab-8000 volumio[983]: } Apr 29 22:26:50 beolab-8000 volumio[983]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 29 22:26:50 beolab-8000 sudo[1751]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-29 22:25 Apr 29 22:26:50 beolab-8000 sudo[1751]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 24 Apr 2025 09:33:57 AM CEST" VOLUMIO_VERSION="3.804" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="354f95cf0a6c2cbcd57b1aca3179c81c"