-- Logs begin at Sat 2025-02-15 23:00:54 CET, end at Sun 2025-02-16 12:50:21 CET. -- Feb 16 12:49:00 nad volumio[699]: verbose: New Socket.io Connection to 192.168.178.97:3000 from 192.168.178.35 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Feb 16 12:49:00 nad volumio[699]: verbose: New Socket.io Connection to 192.168.178.97:3000 from 192.168.178.35 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Feb 16 12:49:00 nad volumio[699]: info: Reloading queue from file Feb 16 12:49:01 nad volumio[699]: info: CoreStateMachine::setRepeat true single undefined Feb 16 12:49:01 nad volumio[699]: info: CoreStateMachine::pushState Feb 16 12:49:01 nad volumio[699]: info: CorePlayQueue::getTrack 0 Feb 16 12:49:01 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 16 12:49:01 nad volumio[699]: info: CoreCommandRouter::volumioPushState Feb 16 12:49:01 nad volumio[699]: info: CoreStateMachine::setRandom null Feb 16 12:49:01 nad volumio[699]: info: CoreStateMachine::pushState Feb 16 12:49:01 nad volumio[699]: info: CorePlayQueue::getTrack 0 Feb 16 12:49:01 nad volumio[699]: info: CoreCommandRouter::volumioPushState Feb 16 12:49:01 nad volumio[699]: info: Setting Device type: Raspberry PI Feb 16 12:49:01 nad volumio[699]: info: VolumeController:: Volume=38 Mute =false Feb 16 12:49:01 nad volumio[699]: info: CoreStateMachine::pushState Feb 16 12:49:01 nad volumio[699]: info: CorePlayQueue::getTrack 0 Feb 16 12:49:01 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 16 12:49:01 nad volumio[699]: info: CoreCommandRouter::volumioPushState Feb 16 12:49:01 nad volumio[699]: info: CoreStateMachine::updateTrackBlock Feb 16 12:49:01 nad volumio[699]: info: CorePlayQueue::getTrackBlock Feb 16 12:49:01 nad volumio[699]: info: CoreCommandRouter::volumioRetrievevolume Feb 16 12:49:02 nad volumio[699]: info: Discovery: adding 463b6452-7d7a-4e83-821a-34e4a88e9daf Feb 16 12:49:02 nad volumio[699]: info: Discovery: Found device NAD Feb 16 12:49:02 nad volumio[699]: info: CoreCommandRouter::volumioGetState Feb 16 12:49:02 nad volumio[699]: info: CorePlayQueue::getTrack 0 Feb 16 12:49:02 nad sudo[989]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 16 12:49:02 nad sudo[989]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:02 nad systemd[1]: Started UPnP Renderer front-end to MPD. Feb 16 12:49:02 nad sudo[989]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:02 nad volumio[699]: info: Discovery: adding 89a7d887-3bd7-45b3-a267-d774e046e4f1 Feb 16 12:49:02 nad volumio[699]: info: Discovery: Found device suz Feb 16 12:49:03 nad volumio[699]: info: Discovery: Connecting to remote: 192.168.178.35 Feb 16 12:49:03 nad volumio[699]: verbose: New Socket.io Connection to 192.168.178.97:3000 from 192.168.178.35 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Feb 16 12:49:03 nad volumio[699]: info: Completed loading Core Plugins Feb 16 12:49:03 nad volumio[699]: info: Preparing to generate the ALSA configuration file Feb 16 12:49:04 nad volumio[699]: info: VolumeController:: Volume=38 Mute =false Feb 16 12:49:04 nad volumio[699]: info: CoreStateMachine::pushState Feb 16 12:49:04 nad volumio[699]: info: CorePlayQueue::getTrack 0 Feb 16 12:49:04 nad volumio[699]: info: CoreCommandRouter::volumioPushState Feb 16 12:49:04 nad volumio[699]: info: Upmpdcli Daemon Started Feb 16 12:49:04 nad volumio[699]: info: Discovery: Connected to remote: 192.168.178.35 Feb 16 12:49:05 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Feb 16 12:49:05 nad volumio[699]: info: CoreCommandRouter::volumioGetState Feb 16 12:49:05 nad volumio[699]: info: CorePlayQueue::getTrack 0 Feb 16 12:49:05 nad volumio[699]: info: Asound.conf file unchanged, so no further update is needed Feb 16 12:49:05 nad volumio[699]: info: Output device has changed, restarting MPD Feb 16 12:49:06 nad volumio[699]: info: Output device has changed, restarting Shairport Sync Feb 16 12:49:06 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:06 nad sudo[998]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 16 12:49:06 nad sudo[998]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:06 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 12:49:06 nad volumio[699]: Starting albumart workers Feb 16 12:49:06 nad sudo[998]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:06 nad sudo[1000]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 16 12:49:06 nad sudo[1000]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:06 nad systemd[1]: Stopping Music Player Daemon... Feb 16 12:49:07 nad systemd[1]: mpd.service: Succeeded. Feb 16 12:49:07 nad systemd[1]: Stopped Music Player Daemon. Feb 16 12:49:07 nad volumio-remote-updater[410]: [2025-02-16 12:49:07] [connect] Successful connection Feb 16 12:49:07 nad systemd[1]: Starting Music Player Daemon... Feb 16 12:49:07 nad volumio[699]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 16 12:49:07 nad volumio[699]: info: ___________ START PLUGINS ___________ Feb 16 12:49:07 nad volumio[699]: info: ControllerMpd::onStart: Initializing MPD Feb 16 12:49:07 nad volumio[699]: info: Creating MPD Configuration file Feb 16 12:49:07 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 16 12:49:08 nad volumio[699]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 16 12:49:08 nad volumio[699]: info: [1739706548034] CoreMusicLibrary::Adding element Media Servers Feb 16 12:49:08 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 16 12:49:08 nad sudo[1006]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 16 12:49:08 nad sudo[1006]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:08 nad sudo[1006]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:08 nad sudo[1008]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 16 12:49:08 nad sudo[1008]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:08 nad sudo[1010]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 16 12:49:09 nad sudo[1010]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:09 nad sudo[1008]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:09 nad systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Feb 16 12:49:09 nad systemd[1]: mpd.service: Succeeded. Feb 16 12:49:09 nad systemd[1]: Stopped Music Player Daemon. Feb 16 12:49:09 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:09 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 12:49:09 nad systemd[1]: Starting Music Player Daemon... Feb 16 12:49:10 nad volumio[699]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 16 12:49:10 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:10 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 12:49:10 nad sudo[1029]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 16 12:49:10 nad sudo[1029]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:10 nad sudo[1029]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:11 nad volumio[699]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 16 12:49:11 nad volumio[699]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 16 12:49:11 nad volumio[699]: info: [1739706551564] CoreMusicLibrary::Adding element Last_100 Feb 16 12:49:11 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 16 12:49:11 nad volumio[699]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 16 12:49:11 nad volumio[699]: info: [1739706551642] CoreMusicLibrary::Adding element Webradio Feb 16 12:49:11 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 16 12:49:11 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 16 12:49:11 nad volumio[699]: info: Initializing BBC Radios Feb 16 12:49:13 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 16 12:49:13 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 12:49:14 nad volumio[699]: info: Creating Spotify config file Feb 16 12:49:14 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:14 nad volumio[699]: info: Volumio Calling Home Feb 16 12:49:16 nad systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Feb 16 12:49:16 nad systemd[1]: mpd.service: Failed with result 'protocol'. Feb 16 12:49:16 nad systemd[1]: Failed to start Music Player Daemon. Feb 16 12:49:16 nad sudo[1000]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:16 nad sudo[1010]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:16 nad systemd[1]: Starting Music Player Daemon... Feb 16 12:49:16 nad systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Feb 16 12:49:16 nad systemd[1]: mpd.service: Succeeded. Feb 16 12:49:16 nad systemd[1]: Stopped Music Player Daemon. Feb 16 12:49:16 nad systemd[1]: Starting Music Player Daemon... Feb 16 12:49:17 nad sudo[1094]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 16 12:49:18 nad sudo[1094]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:18 nad sudo[1094]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:21 nad volumio[699]: error: Cannot start MPD on system Start: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service Feb 16 12:49:21 nad volumio[699]: Job for mpd.service failed because the service did not take the steps required by its unit configuration. Feb 16 12:49:21 nad volumio[699]: See "systemctl status mpd.service" and "journalctl -xe" for details. Feb 16 12:49:21 nad volumio[699]: info: Completed starting Core Plugins Feb 16 12:49:21 nad volumio[699]: info: ------------------------------------------- Feb 16 12:49:21 nad volumio[699]: info: ----- MyVolumio plugins startup ---- Feb 16 12:49:21 nad volumio[699]: info: ------------------------------------------- Feb 16 12:49:21 nad volumio[699]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 16 12:49:21 nad volumio[699]: info: MPD Permissions set Feb 16 12:49:21 nad volumio[699]: info: Cannot restart MPD: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service Feb 16 12:49:21 nad volumio[699]: Job for mpd.service failed because the service did not take the steps required by its unit configuration. Feb 16 12:49:21 nad volumio[699]: See "systemctl status mpd.service" and "journalctl -xe" for details. Feb 16 12:49:21 nad volumio[699]: info: MPD Permissions set Feb 16 12:49:21 nad volumio[699]: info: Discovery: Disconnected from remote: 192.168.178.35 Feb 16 12:49:22 nad volumio-remote-updater[410]: [2025-02-16 12:49:22] [connect] Successful connection Feb 16 12:49:22 nad volumio[699]: info: Volumio called home Feb 16 12:49:22 nad volumio[699]: info: Spotify config file written Feb 16 12:49:23 nad sudo[1120]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 16 12:49:23 nad sudo[1120]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:23 nad volumio[699]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Feb 16 12:49:24 nad systemd[1]: Started go-librespot Daemon. Feb 16 12:49:24 nad go-librespot[1122]: Librespot-go daemon starting... Feb 16 12:49:24 nad sudo[1120]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:24 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:24 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:24 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:24 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:24 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 12:49:24 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:24 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:24 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:24 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:24 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:24 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:25 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 12:49:25 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 16 12:49:25 nad volumio[699]: info: No need to fix Spotify hosts Feb 16 12:49:25 nad go-librespot[1122]: time="2025-02-16T12:49:25+01:00" level=info msg="generated new device id: 5df6c5444b59619cbc230c558984f17012956f54" Feb 16 12:49:26 nad volumio-remote-updater[410]: [2025-02-16 12:49:26] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1739706562 101 Feb 16 12:49:26 nad volumio[699]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 6 Feb 16 12:49:26 nad volumio[699]: info: Discovery: Connected to remote: 192.168.178.35 Feb 16 12:49:26 nad volumio[699]: info: Starting Shairport Sync Feb 16 12:49:26 nad volumio[699]: info: Starting Shairport Sync Feb 16 12:49:27 nad volumio[699]: info: Starting Shairport Sync Feb 16 12:49:27 nad sudo[1138]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 16 12:49:27 nad sudo[1138]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:27 nad sudo[1140]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 16 12:49:28 nad sudo[1140]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:28 nad volumio[699]: info: CoreCommandRouter::volumioGetState Feb 16 12:49:28 nad systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 16 12:49:28 nad volumio[699]: info: CorePlayQueue::getTrack 0 Feb 16 12:49:28 nad systemd[1]: shairport-sync.service: Succeeded. Feb 16 12:49:28 nad systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 16 12:49:28 nad systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 16 12:49:28 nad sudo[1143]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 16 12:49:28 nad sudo[1143]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:28 nad sudo[1138]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:29 nad systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 16 12:49:29 nad systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Feb 16 12:49:29 nad systemd[1]: shairport-sync.service: Succeeded. Feb 16 12:49:29 nad systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 16 12:49:29 nad systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 16 12:49:29 nad sudo[1140]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:29 nad volumio[699]: info: go-librespot daemon successfully initialized Feb 16 12:49:29 nad systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 16 12:49:29 nad systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Feb 16 12:49:29 nad systemd[1]: shairport-sync.service: Succeeded. Feb 16 12:49:29 nad systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 16 12:49:30 nad systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 16 12:49:30 nad go-librespot[1122]: time="2025-02-16T12:49:30+01: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]" Feb 16 12:49:30 nad go-librespot[1122]: time="2025-02-16T12:49:30+01: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]" Feb 16 12:49:30 nad go-librespot[1122]: time="2025-02-16T12:49:30+01: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]" Feb 16 12:49:30 nad sudo[1143]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:30 nad volumio[699]: info: Shairport-Sync Started Feb 16 12:49:30 nad go-librespot[1122]: time="2025-02-16T12:49:30+01:00" level=debug msg="zeroconf server listening on port 38939" Feb 16 12:49:30 nad volumio[699]: Error adding Membership: Error: addMembership EINVAL Feb 16 12:49:30 nad volumio[699]: info: Shairport-Sync Started Feb 16 12:49:31 nad volumio[699]: info: Shairport-Sync Started Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 16 12:49:32 nad volumio[699]: info: Adding plugin bluetooth to MyMusic Plugins Feb 16 12:49:32 nad volumio[699]: info: Adding plugin multiroom to MyMusic Plugins Feb 16 12:49:32 nad volumio[699]: info: Adding plugin metavolumio to MyMusic Plugins Feb 16 12:49:32 nad volumio[699]: info: Adding plugin cd_controller to MyMusic Plugins Feb 16 12:49:32 nad volumio[699]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 16 12:49:32 nad volumio[699]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 16 12:49:32 nad volumio[699]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 16 12:49:41 nad mpd[1096]: Feb 16 12:49 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 16 12:49:41 nad systemd[1]: Started Music Player Daemon. Feb 16 12:49:41 nad mpd_monitor.sh[416]: MPD restarted due to no mpc output. Feb 16 12:49:44 nad volumio[699]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 16 12:49:44 nad volumio[699]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 16 12:49:44 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 12:49:44 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 12:49:44 nad volumio[699]: info: Starting MyVolumio Remote Streaming Endpoints Feb 16 12:49:44 nad volumio[699]: info: MyVolumio login type: Token Feb 16 12:49:45 nad volumio[699]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 16 12:49:45 nad volumio[699]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 16 12:49:52 nad volumio[699]: info: Starting Streaming Service Transparent Proxy Feb 16 12:49:52 nad volumio[699]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 16 12:49:52 nad volumio[699]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 16 12:49:52 nad volumio[699]: info: Streaming services startup Feb 16 12:49:52 nad volumio[699]: info: Starting Streaming Daemon Feb 16 12:49:53 nad sudo[1207]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 16 12:49:53 nad sudo[1207]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 16 12:49:53 nad volumio[699]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 16 12:49:53 nad sudo[1207]: pam_unix(sudo:session): session closed for user root Feb 16 12:49:53 nad volumio[699]: info: Initializing connection to go-librespot Websocket Feb 16 12:49:54 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 16 12:49:54 nad go-librespot[1122]: time="2025-02-16T12:49:54+01:00" level=debug msg="obtained new client token: AADKCONIJVIMqjZNwjeQaSl7ikNL2wqtBQuvxoXo9pGWdhkv1jR4+b7CYJmi/1hZeQEHJWTVDOZILxGucT+udDrsX2uC3dLWqFGrRXBHvWIiF1WotHwxx6/T58jOBpP+YvSJ3uwTrsZEXC7VNFZgEFglWSPpy4Uj0I7pjg9y6S4WWdup5kECpFQomVUwc97krWuBTVzNBEGUpC/hMGIfZBFrwqDTWj0bd1a3CpvuCVlh2nm8c2waksmJC1SZnw==" Feb 16 12:49:54 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 16 12:49:54 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 16 12:49:54 nad go-librespot[1122]: time="2025-02-16T12:49:54+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Feb 16 12:49:54 nad go-librespot[1122]: time="2025-02-16T12:49:54+01:00" level=debug msg="completed keyexchange" Feb 16 12:49:54 nad volumio[699]: Upnp client error: Error: This socket has been ended by the other party Feb 16 12:49:55 nad go-librespot[1122]: time="2025-02-16T12:49:55+01:00" level=debug msg="completed challenge" Feb 16 12:49:55 nad go-librespot[1122]: time="2025-02-16T12:49:55+01:00" level=debug msg="authenticated as 8w438n3iwvofhk9hvndy23wz8" Feb 16 12:49:55 nad go-librespot[1122]: time="2025-02-16T12:49:55+01:00" level=debug msg="authenticated as 8w438n3iwvofhk9hvndy23wz8" Feb 16 12:49:55 nad go-librespot[1122]: time="2025-02-16T12:49:55+01:00" level=debug msg="dealer connection opened" Feb 16 12:49:55 nad go-librespot[1122]: time="2025-02-16T12:49:55+01:00" level=info msg="accepted zeroconf user 8w438n3iwvofhk9hvndy23wz8 from iPhone" Feb 16 12:49:55 nad go-librespot[1122]: time="2025-02-16T12:49:55+01:00" level=debug msg="received connection id: MzYxZjcyNTgtNDczNi00NjhiLWI1MjUtODI1ZTQ1NDBiZGM3K2RlYWxlcit0Y3A6Ly8wYWNhNTlmZi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMTYwNUE4RjlCRjAwMkUwNDgyMjEwNUFFMTczQjlFMTRBNkZBRTJDOTY1QjMwNjAyRjQ2M0Q0ODBERTMxNzUyRA==" Feb 16 12:49:55 nad go-librespot[1122]: time="2025-02-16T12:49:55+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 16 12:49:55 nad go-librespot[1122]: time="2025-02-16T12:49:55+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 16 12:49:56 nad volumio-remote-updater[410]: [2025-02-16 12:49:56] [disconnect] Disconnect close local:[1008,Pong timeout] remote:[1006] Feb 16 12:49:56 nad go-librespot[1122]: time="2025-02-16T12:49:56+01:00" level=debug msg="put connect state because NEW_DEVICE" Feb 16 12:49:56 nad go-librespot[1122]: time="2025-02-16T12:49:56+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 16 12:49:56 nad go-librespot[1122]: time="2025-02-16T12:49:56+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 16 12:49:56 nad go-librespot[1122]: time="2025-02-16T12:49:56+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 16 12:49:56 nad go-librespot[1122]: time="2025-02-16T12:49:56+01:00" level=debug msg="autoplay enabled: false" Feb 16 12:49:56 nad go-librespot[1122]: time="2025-02-16T12:49:56+01:00" level=debug msg="handling transfer player command from 6ca11b824e49127ed782e4c5ec0884f1578c0190" Feb 16 12:49:56 nad volumio[699]: error: MPD error: The expression evaluated to a falsy value: Feb 16 12:49:56 nad volumio[699]: assert.ok(self.idling) Feb 16 12:49:56 nad volumio[699]: error: The expression evaluated to a falsy value: Feb 16 12:49:56 nad volumio[699]: assert.ok(self.idling) Feb 16 12:49:56 nad volumio[699]: error: Cannot start Volumio Streaming Daemon Feb 16 12:49:56 nad volumio[699]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 16 12:49:56 nad volumio[699]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 16 12:49:56 nad go-librespot[1122]: time="2025-02-16T12:49:56+01:00" level=debug msg="resolved context of track" uri="spotify:station:playlist:3Y6efjApSP1wL7HSV4aOPp" Feb 16 12:49:56 nad go-librespot[1122]: time="2025-02-16T12:49:56+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:station:playlist:3Y6efjApSP1wL7HSV4aOPp" Feb 16 12:49:56 nad volumio[699]: error: updateQueue error: null Feb 16 12:49:56 nad go-librespot[1122]: time="2025-02-16T12:49:56+01:00" level=debug msg="new websocket client" Feb 16 12:49:57 nad volumio[699]: info: Connection to go-librespot Websocket established Feb 16 12:49:57 nad go-librespot[1122]: time="2025-02-16T12:49:57+01:00" level=trace msg="fetched new page from (has next: true)" uri="spotify:station:playlist:3Y6efjApSP1wL7HSV4aOPp" Feb 16 12:49:57 nad go-librespot[1122]: time="2025-02-16T12:49:57+01:00" level=trace msg="fetched new page 1 with 50 items (list: 100)" uri="spotify:station:playlist:3Y6efjApSP1wL7HSV4aOPp" Feb 16 12:49:57 nad volumio[699]: error: MyVolumio Custom Token format not valid, refreshing it Feb 16 12:49:57 nad go-librespot[1122]: time="2025-02-16T12:49:57+01:00" level=trace msg="fetched new page from (has next: true)" uri="spotify:station:playlist:3Y6efjApSP1wL7HSV4aOPp" Feb 16 12:49:57 nad go-librespot[1122]: time="2025-02-16T12:49:57+01:00" level=trace msg="fetched new page 2 with 50 items (list: 150)" uri="spotify:station:playlist:3Y6efjApSP1wL7HSV4aOPp" Feb 16 12:49:58 nad go-librespot[1122]: time="2025-02-16T12:49:58+01:00" level=trace msg="fetched new page from (has next: true)" uri="spotify:station:playlist:3Y6efjApSP1wL7HSV4aOPp" Feb 16 12:49:58 nad go-librespot[1122]: time="2025-02-16T12:49:58+01:00" level=trace msg="fetched new page 3 with 50 items (list: 200)" uri="spotify:station:playlist:3Y6efjApSP1wL7HSV4aOPp" Feb 16 12:49:58 nad go-librespot[1122]: time="2025-02-16T12:49:58+01:00" level=warning msg="failed seeking to track in context spotify:station:playlist:3Y6efjApSP1wL7HSV4aOPp" error="failed fetching tracks for seek: failed moving to next index 200 (page 4): failed fetching next page: invalid status code from page at radio-apollo/v5/tracks/spotify:station:playlist:3Y6efjApSP1wL7HSV4aOPp?salt=457530&autoplay=false&count=50&isVideo=false&prev_tracks=3GYlZ7tbxLOxe6ewMNVTkw,4PwWESSlTwzvw9B7bmtTLS,00RLNHc2jkEjUoCUlFgPVT,5WbfFTuIldjL9x7W6y5l7R,0yc6Gst2xkRu0eMLeRMGCX,2nltARCkZyrzjQANViDpuX,5TxRUOsGeWeRl3xOML59Ai,11hEwcy9LMEvzAlOYAFhkK,5Mu5BFHb4vFS5cw0hbDICV,71BWZa1liIRyUiuJ3MB66o,6jgkEbmQ2F2onEqsEhiliL,10nyNJ6zNy2YVYLrcwLccB,6ZLt6fyonW1xOGMBC9vJPJ,1lb0KfG9EyfSBsEifTUtXY,5ZNrtDCYDwzIBKmZAclBOu,1FWsomP9StpCcXNWmJk8Cl,1i8dJGpKO0xQiKGCVslJqB,63OQupATfueTdZMWTxW03A,3kQfBtkQqgN1fAMfhks8TU,1LzNfuep1bnAUR9skqdHCK,4Rsv5fRmgTH88RLp7xN5sz,2262bWmqomIaJXwCRHr13j,2VtXANhW6YpAzsMDQCFkAv,5e0b9LgOfi3aJSKXFcOWRe,6QeYSvYqYUsfBzsApbjDHO,2fuYa3Lx06QQJAm0MjztKr,0tGqk0HlYMQ16aj7yJwleF,6Uwi2Qk3H7fM4b4W4ExrAp,135ArLV1euyyeegU9D8HVR,464XMdxuH3QmvwLpMrOhGj,3lhLML5eIwmPnw2xWKosZX,0z1o5L7HJx562xZSATcIpY,7EDcAz6iuKSkxH4VcC3Oko,70YTBH8vOGJNMhy6186yFm,2LMkwUfqC6S6s6qDVlEuzV,6jHvX8ZnHKC1PnrPMJ0Emt,6IPwKM3fUUzlElbvKw2sKl,013L1ZodWo9Ax2g9LejC9O,3IznIgmXtrUaoPWpQTy5jB,0SpkyS1Q4MD8GaVcP5YjT4,6cMMZ2pdP4PkYsVJqX2WUh,5URfZHMlUWTWxPvvSBWcPk,57j65yC2HggQfmYNc6rdOK,1hJXpII24ReABFg8Ig6k7w,0b6xZk9f96N77BfmYWnQNC,68FuXWn3fGYMB7sJzdRHPz,1xbOdb9kv5YKBIzJSrKNEy,2IVsRhKrx8hlQBOWy4qebo,6Hzle86uYcpy3QkcCmMKgE,7fyG2MquxykO3Ufiku1Dj2&minimal=true?salt=348785&autoplay=false&count=50&isVideo=false&prev_tracks=3GYlZ7tbxLOxe6ewMNVTkw,4PwWESSlTwzvw9B7bmtTLS,00RLNHc2jkEjUoCUlFgPVT,0yc6Gst2xkRu0eMLeRMGCX,5WbfFTuIldjL9x7W6y5l7R,5Mu5BFHb4vFS5cw0hbDICV,10nyNJ6zNy2YVYLrcwLccB,11hEwcy9LMEvzAlOYAFhkK,3kQfBtkQqgN1fAMfhks8TU,1LzNfuep1bnAUR9skqdHCK,71BWZa1liIRyUiuJ3MB66o,5ZNrtDCYDwzIBKmZAclBOu,63OQupATfueTdZMWTxW03A,1lb0KfG9EyfSBsEifTUtXY,2VtXANhW6YpAzsMDQCFkAv,6jgkEbmQ2F2onEqsEhiliL,4Rsv5fRmgTH88RLp7xN5sz,5e0b9LgOfi3aJSKXFcOWRe,2fuYa3Lx06QQJAm0MjztKr,1FWsomP9StpCcXNWmJk8Cl,6ZLt6fyonW1xOGMBC9vJPJ,1i8dJGpKO0xQiKGCVslJqB,6Uwi2Qk3H7fM4b4W4ExrAp,0tGqk0HlYMQ16aj7yJwleF,0z1o5L7HJx562xZSATcIpY,3qhlB30KknSejmIvZZLjOD,464XMdxuH3QmvwLpMrOhGj,70YTBH8vOGJNMhy6186yFm,3lhLML5eIwmPnw2xWKosZX,7EDcAz6iuKSkxH4VcC3Oko,013L1ZodWo9Ax2g9LejC9O,2LMkwUfqC6S6s6qDVlEuzV,0ol0kxeGvxBboZ3wVZ4ZTq,0SpkyS1Q4MD8GaVcP5YjT4,135ArLV1euyyeegU9D8HVR,70LcF31zb1H0PyJoS1Sx1r,4JdYapRlYv67LnjrkDhZVX,5VBjyOQzqlPNgdRPMM6prF,40MYrR5GY6f0ghFOnJJC9v,1xbOdb9kv5YKBIzJSrKNEy,3512x3piBwWSwfq3KM6zO4,6QeYSvYqYUsfBzsApbjDHO,0uvagCBJC0ClsR11W10T0Y,2rtGaCAeYtmcIvuZsvgTf6,6IPwKM3fUUzlElbvKw2sKl,6Hzle86uYcpy3QkcCmMKgE,5URfZHMlUWTWxPvvSBWcPk,6WlmEymaXKMRs3D2c4j6os,0Z94dtWElamDwU4NrcGoUR,6cMMZ2pdP4PkYsVJqX2WUh?salt=561282&autoplay=false&count=50&isVideo=false&prev_tracks=3GYlZ7tbxLOxe6ewMNVTkw,4PwWESSlTwzvw9B7bmtTLS,00RLNHc2jkEjUoCUlFgPVT,5WbfFTuIldjL9x7W6y5l7R,5Mu5BFHb4vFS5cw0hbDICV,0yc6Gst2xkRu0eMLeRMGCX,5TxRUOsGeWeRl3xOML59Ai,11hEwcy9LMEvzAlOYAFhkK,0tGqk0HlYMQ16aj7yJwleF,71BWZa1liIRyUiuJ3MB66o,10nyNJ6zNy2YVYLrcwLccB,5ZNrtDCYDwzIBKmZAclBOu,6ZLt6fyonW1xOGMBC9vJPJ,3kQfBtkQqgN1fAMfhks8TU,4Rsv5fRmgTH88RLp7xN5sz,6jgkEbmQ2F2onEqsEhiliL,1lb0KfG9EyfSBsEifTUtXY,2VtXANhW6YpAzsMDQCFkAv,1LzNfuep1bnAUR9skqdHCK,1FWsomP9StpCcXNWmJk8Cl,7EDcAz6iuKSkxH4VcC3Oko,63OQupATfueTdZMWTxW03A,1i8dJGpKO0xQiKGCVslJqB,2262bWmqomIaJXwCRHr13j,6jbYpRPTEFl1HFKHk1IC0m,5e0b9LgOfi3aJSKXFcOWRe,3lhLML5eIwmPnw2xWKosZX,0z1o5L7HJx562xZSATcIpY,6Uwi2Qk3H7fM4b4W4ExrAp,135ArLV1euyyeegU9D8HVR,70YTBH8vOGJNMhy6186yFm,464XMdxuH3QmvwLpMrOhGj,6QeYSvYqYUsfBzsApbjDHO,2fuYa3Lx06QQJAm0MjztKr,2LMkwUfqC6S6s6qDVlEuzV,013L1ZodWo9Ax2g9LejC9O,6jHvX8ZnHKC1PnrPMJ0Emt,0SpkyS1Q4MD8GaVcP5YjT4,6IPwKM3fUUzlElbvKw2sKl,6Hzle86uYcpy3QkcCmMKgE,6cMMZ2pdP4PkYsVJqX2WUh,1hJXpII24ReABFg8Ig6k7w,2rtGaCAeYtmcIvuZsvgTf6,5URfZHMlUWTWxPvvSBWcPk,40MYrR5GY6f0ghFOnJJC9v,4JdYapRlYv67LnjrkDhZVX,3IznIgmXtrUaoPWpQTy5jB,1xbOdb9kv5YKBIzJSrKNEy,68FuXWn3fGYMB7sJzdRHPz,57j65yC2HggQfmYNc6rdOK?salt=313746&autoplay=false&count=50&isVideo=false&prev_tracks=3GYlZ7tbxLOxe6ewMNVTkw,4PwWESSlTwzvw9B7bmtTLS,5Mu5BFHb4vFS5cw0hbDICV,00RLNHc2jkEjUoCUlFgPVT,2nltARCkZyrzjQANViDpuX,5WbfFTuIldjL9x7W6y5l7R,63OQupATfueTdZMWTxW03A,11hEwcy9LMEvzAlOYAFhkK,5ZNrtDCYDwzIBKmZAclBOu,0yc6Gst2xkRu0eMLeRMGCX,0tGqk0HlYMQ16aj7yJwleF,71BWZa1liIRyUiuJ3MB66o,10nyNJ6zNy2YVYLrcwLccB,6ZLt6fyonW1xOGMBC9vJPJ,6jgkEbmQ2F2onEqsEhiliL,2VtXANhW6YpAzsMDQCFkAv,4Rsv5fRmgTH88RLp7xN5sz,3kQfBtkQqgN1fAMfhks8TU,0z1o5L7HJx562xZSATcIpY,1LzNfuep1bnAUR9skqdHCK,5TxRUOsGeWeRl3xOML59Ai,1lb0KfG9EyfSBsEifTUtXY,1FWsomP9StpCcXNWmJk8Cl,1i8dJGpKO0xQiKGCVslJqB,2fuYa3Lx06QQJAm0MjztKr,7EDcAz6iuKSkxH4VcC3Oko,6Uwi2Qk3H7fM4b4W4ExrAp,135ArLV1euyyeegU9D8HVR,464XMdxuH3QmvwLpMrOhGj,0ol0kxeGvxBboZ3wVZ4ZTq,2LMkwUfqC6S6s6qDVlEuzV,013L1ZodWo9Ax2g9LejC9O,70LcF31zb1H0PyJoS1Sx1r,70YTBH8vOGJNMhy6186yFm,6jHvX8ZnHKC1PnrPMJ0Emt,6QeYSvYqYUsfBzsApbjDHO,1hJXpII24ReABFg8Ig6k7w,3k9YxSVB0gosEbSnM0oD43,2rtGaCAeYtmcIvuZsvgTf6,0SpkyS1Q4MD8GaVcP5YjT4,4JdYapRlYv67LnjrkDhZVX,6IPwKM3fUUzlElbvKw2sKl,3512x3piBwWSwfq3KM6zO4,5URfZHMlUWTWxPvvSBWcPk,0YJ9FWWHn9EfnN0lHwbzvV,1xbOdb9kv5YKBIzJSrKNEy,6cMMZ2pdP4PkYsVJqX2WUh,4NUhcsz9E1LrBe8nXLZqzp,0uvagCBJC0ClsR11W10T0Y,6Hzle86uYcpy3QkcCmMKgE: 414" Feb 16 12:49:58 nad go-librespot[1122]: time="2025-02-16T12:49:58+01:00" level=debug msg="loading track (paused: true, position: 20380ms)" uri="spotify:track:3GYlZ7tbxLOxe6ewMNVTkw" Feb 16 12:49:58 nad go-librespot[1122]: time="2025-02-16T12:49:58+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 16 12:49:58 nad go-librespot[1122]: time="2025-02-16T12:49:58+01:00" level=trace msg="emitting websocket event: will_play" Feb 16 12:49:58 nad go-librespot[1122]: time="2025-02-16T12:49:58+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Feb 16 12:49:58 nad go-librespot[1122]: time="2025-02-16T12:49:58+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1694" Feb 16 12:49:58 nad go-librespot[1122]: time="2025-02-16T12:49:58+01:00" level=debug msg="selected format OGG_VORBIS_320 (5367bb54f9565434f2afaba79b5d90e90c68768c)" uri="spotify:track:3GYlZ7tbxLOxe6ewMNVTkw" Feb 16 12:49:58 nad go-librespot[1122]: time="2025-02-16T12:49:58+01:00" level=debug msg="requested aes key for file 5367bb54f9565434f2afaba79b5d90e90c68768c, gid: 3GYlZ7tbxLOxe6ewMNVTkw" Feb 16 12:49:58 nad go-librespot[1122]: time="2025-02-16T12:49:58+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1289" Feb 16 12:49:59 nad volumio[699]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3GYlZ7tbxLOxe6ewMNVTkw","play_origin":""}} Feb 16 12:49:59 nad go-librespot[1122]: time="2025-02-16T12:49:59+01:00" level=debug msg="fetched first chunk of 20, total size is 10091040 bytes" uri="spotify:track:3GYlZ7tbxLOxe6ewMNVTkw" Feb 16 12:50:00 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Feb 16 12:50:00 nad volumio[699]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 16 12:50:01 nad volumio-remote-updater[410]: [2025-02-16 12:50:01] [connect] Successful connection Feb 16 12:50:02 nad go-librespot[1122]: time="2025-02-16T12:50:02+01:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:3GYlZ7tbxLOxe6ewMNVTkw" Feb 16 12:50:02 nad volumio[699]: info: Getting Spotify volume Feb 16 12:50:02 nad go-librespot[1122]: time="2025-02-16T12:50:02+01:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:3GYlZ7tbxLOxe6ewMNVTkw" Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:3GYlZ7tbxLOxe6ewMNVTkw" Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=debug msg="fetched chunk 4/19, size: 524288" uri="spotify:track:3GYlZ7tbxLOxe6ewMNVTkw" Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=trace msg="seek to 20380ms (diff: 189ms, samples: 898758, bytes: 640209)" uri="spotify:track:3GYlZ7tbxLOxe6ewMNVTkw" Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 10068 us, period size = 444 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 49 frames" Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=debug msg="created new output device" Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=info msg="loaded track \"TV\" (paused: true, position: 20380ms, duration: 281380ms, prefetched: false)" uri="spotify:track:3GYlZ7tbxLOxe6ewMNVTkw" Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=trace msg="emitting websocket event: metadata" Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=trace msg="emitting websocket event: active" Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=debug msg="sending successful reply for dealer request" Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 16 12:50:03 nad go-librespot[1122]: time="2025-02-16T12:50:03+01:00" level=trace msg="emitting websocket event: paused" Feb 16 12:50:04 nad volumio[699]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 16 12:50:04 nad volumio[699]: info: Spotify volume: 100 Feb 16 12:50:04 nad volumio[699]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3GYlZ7tbxLOxe6ewMNVTkw","name":"TV","artist_names":["Billie Eilish"],"album_name":"Guitar Songs","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027a4781629469bb83356cd318","position":20380,"duration":281380,"release_date":"year:2022 month:7 day:21","track_number":1,"disc_number":1}} Feb 16 12:50:04 nad volumio[699]: SPOTIFY: received: {"type":"active","data":null} Feb 16 12:50:04 nad volumio[699]: info: Aligning Spotify Volume to Volumio Volume Feb 16 12:50:04 nad volumio[699]: info: CoreCommandRouter::volumioGetState Feb 16 12:50:04 nad volumio[699]: info: CorePlayQueue::getTrack 0 Feb 16 12:50:04 nad volumio[699]: info: Setting Spotify Volume from Volumio: 38 Feb 16 12:50:04 nad volumio[699]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3GYlZ7tbxLOxe6ewMNVTkw","play_origin":""}} Feb 16 12:50:04 nad volumio[699]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 16 12:50:04 nad volumio[699]: TypeError: Cannot read property 'service' of undefined Feb 16 12:50:04 nad volumio[699]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Feb 16 12:50:04 nad volumio[699]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) Feb 16 12:50:04 nad volumio[699]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Feb 16 12:50:04 nad volumio[699]: at WebSocket.emit (events.js:315:20) Feb 16 12:50:04 nad volumio[699]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Feb 16 12:50:04 nad volumio[699]: at Receiver.emit (events.js:315:20) Feb 16 12:50:04 nad volumio[699]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Feb 16 12:50:04 nad volumio[699]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Feb 16 12:50:04 nad volumio[699]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Feb 16 12:50:04 nad volumio[699]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Feb 16 12:50:04 nad volumio[699]: at writeOrBuffer (internal/streams/writable.js:358:12) Feb 16 12:50:04 nad volumio[699]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Feb 16 12:50:04 nad volumio[699]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Feb 16 12:50:04 nad volumio[699]: at Socket.emit (events.js:315:20) Feb 16 12:50:04 nad volumio[699]: at addChunk (internal/streams/readable.js:309:12) Feb 16 12:50:04 nad volumio[699]: at readableAddChunk (internal/streams/readable.js:284:9) Feb 16 12:50:04 nad volumio[699]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 16 12:50:04 nad go-librespot[1122]: time="2025-02-16T12:50:04+01:00" level=debug msg="handling play player command from 6ca11b824e49127ed782e4c5ec0884f1578c0190" Feb 16 12:50:04 nad go-librespot[1122]: time="2025-02-16T12:50:04+01:00" level=debug msg="resolved context of track" uri="spotify:search:apple" Feb 16 12:50:04 nad go-librespot[1122]: time="2025-02-16T12:50:04+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:search:apple" Feb 16 12:50:04 nad go-librespot[1122]: time="2025-02-16T12:50:04+01:00" level=debug msg="loading track (paused: false, position: 13ms)" uri="spotify:track:5xA5MggKc3aQxuOzNzPUWB" Feb 16 12:50:05 nad go-librespot[1122]: time="2025-02-16T12:50:05+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 16 12:50:05 nad go-librespot[1122]: time="2025-02-16T12:50:05+01:00" level=trace msg="emitting websocket event: will_play" Feb 16 12:50:05 nad go-librespot[1122]: time="2025-02-16T12:50:05+01:00" level=debug msg="selected format OGG_VORBIS_320 (78bafcd50218cc41226b1b101ed81232b685c041)" uri="spotify:track:5xA5MggKc3aQxuOzNzPUWB" Feb 16 12:50:05 nad go-librespot[1122]: time="2025-02-16T12:50:05+01:00" level=debug msg="requested aes key for file 78bafcd50218cc41226b1b101ed81232b685c041, gid: 5xA5MggKc3aQxuOzNzPUWB" Feb 16 12:50:05 nad go-librespot[1122]: time="2025-02-16T12:50:05+01:00" level=debug msg="fetched first chunk of 14, total size is 7148948 bytes" uri="spotify:track:5xA5MggKc3aQxuOzNzPUWB" Feb 16 12:50:06 nad go-librespot[1122]: time="2025-02-16T12:50:06+01:00" level=trace msg="seek to 13ms (diff: 13ms, samples: 573, bytes: 0)" uri="spotify:track:5xA5MggKc3aQxuOzNzPUWB" Feb 16 12:50:06 nad go-librespot[1122]: time="2025-02-16T12:50:06+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 10068 us, period size = 444 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 49 frames" Feb 16 12:50:06 nad go-librespot[1122]: time="2025-02-16T12:50:06+01:00" level=info msg="loaded track \"Apple Cider\" (paused: false, position: 13ms, duration: 178918ms, prefetched: false)" uri="spotify:track:5xA5MggKc3aQxuOzNzPUWB" Feb 16 12:50:06 nad go-librespot[1122]: time="2025-02-16T12:50:06+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 16 12:50:06 nad go-librespot[1122]: time="2025-02-16T12:50:06+01:00" level=trace msg="scheduling prefetch in 149s" Feb 16 12:50:06 nad go-librespot[1122]: time="2025-02-16T12:50:06+01:00" level=trace msg="emitting websocket event: metadata" Feb 16 12:50:06 nad go-librespot[1122]: time="2025-02-16T12:50:06+01:00" level=debug msg="sending successful reply for dealer request" Feb 16 12:50:06 nad go-librespot[1122]: time="2025-02-16T12:50:06+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 16 12:50:06 nad go-librespot[1122]: time="2025-02-16T12:50:06+01:00" level=trace msg="emitting websocket event: playing" Feb 16 12:50:08 nad go-librespot[1122]: time="2025-02-16T12:50:08+01:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:5xA5MggKc3aQxuOzNzPUWB" Feb 16 12:50:09 nad go-librespot[1122]: time="2025-02-16T12:50:09+01:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:5xA5MggKc3aQxuOzNzPUWB" Feb 16 12:50:09 nad go-librespot[1122]: time="2025-02-16T12:50:09+01:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:5xA5MggKc3aQxuOzNzPUWB" Feb 16 12:50:11 nad go-librespot[1122]: time="2025-02-16T12:50:11+01:00" level=debug msg="update volume to 61439/65535" Feb 16 12:50:11 nad go-librespot[1122]: time="2025-02-16T12:50:11+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 16 12:50:11 nad go-librespot[1122]: time="2025-02-16T12:50:11+01:00" level=trace msg="emitting websocket event: volume" Feb 16 12:50:11 nad go-librespot[1122]: time="2025-02-16T12:50:11+01:00" level=debug msg="update volume to 57343/65535" Feb 16 12:50:11 nad go-librespot[1122]: time="2025-02-16T12:50:11+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 16 12:50:11 nad go-librespot[1122]: time="2025-02-16T12:50:11+01:00" level=trace msg="emitting websocket event: volume" Feb 16 12:50:11 nad go-librespot[1122]: time="2025-02-16T12:50:11+01:00" level=debug msg="update volume to 53247/65535" Feb 16 12:50:11 nad go-librespot[1122]: time="2025-02-16T12:50:11+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 16 12:50:11 nad go-librespot[1122]: time="2025-02-16T12:50:11+01:00" level=trace msg="emitting websocket event: volume" Feb 16 12:50:12 nad go-librespot[1122]: time="2025-02-16T12:50:12+01:00" level=debug msg="update volume to 49151/65535" Feb 16 12:50:12 nad go-librespot[1122]: time="2025-02-16T12:50:12+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 16 12:50:12 nad go-librespot[1122]: time="2025-02-16T12:50:12+01:00" level=trace msg="emitting websocket event: volume" Feb 16 12:50:12 nad go-librespot[1122]: time="2025-02-16T12:50:12+01:00" level=debug msg="update volume to 45055/65535" Feb 16 12:50:13 nad go-librespot[1122]: time="2025-02-16T12:50:13+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 16 12:50:13 nad go-librespot[1122]: time="2025-02-16T12:50:13+01:00" level=trace msg="emitting websocket event: volume" Feb 16 12:50:13 nad go-librespot[1122]: time="2025-02-16T12:50:13+01:00" level=debug msg="update volume to 40959/65535" Feb 16 12:50:13 nad go-librespot[1122]: time="2025-02-16T12:50:13+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 16 12:50:13 nad go-librespot[1122]: time="2025-02-16T12:50:13+01:00" level=trace msg="emitting websocket event: volume" Feb 16 12:50:13 nad volumio-remote-updater[410]: [2025-02-16 12:50:13] [connect] Successful connection Feb 16 12:50:14 nad go-librespot[1122]: time="2025-02-16T12:50:14+01:00" level=debug msg="update volume to 36863/65535" Feb 16 12:50:15 nad go-librespot[1122]: time="2025-02-16T12:50:15+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 16 12:50:15 nad go-librespot[1122]: time="2025-02-16T12:50:15+01:00" level=trace msg="emitting websocket event: volume" Feb 16 12:50:15 nad go-librespot[1122]: time="2025-02-16T12:50:15+01:00" level=debug msg="update volume to 28671/65535" Feb 16 12:50:16 nad go-librespot[1122]: time="2025-02-16T12:50:16+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 16 12:50:16 nad go-librespot[1122]: time="2025-02-16T12:50:16+01:00" level=trace msg="emitting websocket event: volume" Feb 16 12:50:21 nad sudo[1300]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-16 12:49 Feb 16 12:50:21 nad sudo[1300]: 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="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"