-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sun 2025-09-14 17:19:56 CEST. -- Sep 14 17:19:18 volumio-woonkamer systemd-timedated[889]: Changed local time to Sun Sep 14 17:19:18 2025 Sep 14 17:19:18 volumio-woonkamer sudo[887]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:18 volumio-woonkamer volumio-time-update[544]: volumio-time-update-util: System time updated successfully. Sep 14 17:19:18 volumio-woonkamer systemd[1]: Started Volumio Time Update Utility. Sep 14 17:19:20 volumio-woonkamer nmbd[667]: [2025/09/14 17:19:20.121693, 0] ../lib/util/become_daemon.c:138(daemon_ready) Sep 14 17:19:20 volumio-woonkamer nmbd[667]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Sep 14 17:19:20 volumio-woonkamer systemd[1]: Started Samba NMB Daemon. Sep 14 17:19:20 volumio-woonkamer systemd[1]: Starting Samba Winbind Daemon... Sep 14 17:19:20 volumio-woonkamer winbindd[890]: [2025/09/14 17:19:20.726083, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Sep 14 17:19:20 volumio-woonkamer winbindd[890]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Sep 14 17:19:20 volumio-woonkamer winbindd[890]: [2025/09/14 17:19:20.766292, 0] ../lib/util/become_daemon.c:138(daemon_ready) Sep 14 17:19:20 volumio-woonkamer systemd[1]: Started Samba Winbind Daemon. Sep 14 17:19:20 volumio-woonkamer winbindd[890]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Sep 14 17:19:20 volumio-woonkamer systemd[1]: Starting Samba SMB Daemon... Sep 14 17:19:21 volumio-woonkamer volumio[865]: info: ------------------------------------------- Sep 14 17:19:21 volumio-woonkamer volumio[865]: info: ----- Volumio3 ---- Sep 14 17:19:21 volumio-woonkamer volumio[865]: info: ------------------------------------------- Sep 14 17:19:21 volumio-woonkamer volumio[865]: info: ----- System startup ---- Sep 14 17:19:21 volumio-woonkamer volumio[865]: info: ------------------------------------------- Sep 14 17:19:21 volumio-woonkamer smbd[904]: [2025/09/14 17:19:21.713871, 0] ../lib/util/become_daemon.c:138(daemon_ready) Sep 14 17:19:21 volumio-woonkamer systemd[1]: Started Samba SMB Daemon. Sep 14 17:19:21 volumio-woonkamer smbd[904]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Sep 14 17:19:21 volumio-woonkamer systemd[1]: Reached target Multi-User System. Sep 14 17:19:21 volumio-woonkamer systemd[1]: Reached target Graphical Interface. Sep 14 17:19:21 volumio-woonkamer systemd[1]: Starting Update UTMP about System Runlevel Changes... Sep 14 17:19:21 volumio-woonkamer systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Sep 14 17:19:21 volumio-woonkamer systemd[1]: Started Update UTMP about System Runlevel Changes. Sep 14 17:19:21 volumio-woonkamer systemd[1]: Startup finished in 15.401s (kernel) + 29.858s (userspace) = 45.260s. Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: MYVOLUMIO Environment detected Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Configured plugin music_service/volspotconnect2 cannot be loaded. Removing from configuration Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Plugin folders cleanup Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Scanning into folder /volumio/app/plugins/ Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Scanning category audio_interface Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Scanning category miscellanea Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Scanning category music_service Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Scanning category plugins.json Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Scanning category system_controller Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Scanning category user_interface Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Scanning into folder /data/plugins/ Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Scanning category music_service Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Scanning category system_hardware Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Scanning category user_interface Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Plugin folders cleanup completed Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: ------------------------------------------- Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: ----- Core plugins startup ---- Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: ------------------------------------------- Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Loading plugins from folder /volumio/app/plugins/ Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Adding plugin upnp to MyMusic Plugins Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Adding plugin airplay_emulation to MyMusic Plugins Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Adding plugin upnp_browser to MyMusic Plugins Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Loading plugins from folder /data/plugins/ Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Loading plugin "system"... Sep 14 17:19:23 volumio-woonkamer volumio[865]: info: Loading plugin "appearance"... Sep 14 17:19:24 volumio-woonkamer volumio-remote-updater[535]: [2025-09-14 17:19:24] [connect] Successful connection Sep 14 17:19:26 volumio-woonkamer volumio[865]: info: Loading plugin "network"... Sep 14 17:19:26 volumio-woonkamer volumio[865]: info: Refreshing Cached IP Addresses Sep 14 17:19:26 volumio-woonkamer sudo[920]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 14 17:19:26 volumio-woonkamer sudo[920]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:26 volumio-woonkamer sudo[922]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 14 17:19:26 volumio-woonkamer sudo[920]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:26 volumio-woonkamer sudo[922]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:26 volumio-woonkamer sudo[922]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:26 volumio-woonkamer volumio[865]: info: Loading plugin "services"... Sep 14 17:19:26 volumio-woonkamer volumio[865]: info: Loading plugin "alsa_controller"... Sep 14 17:19:26 volumio-woonkamer sudo[929]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Sep 14 17:19:26 volumio-woonkamer sudo[929]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:26 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 14 17:19:26 volumio-woonkamer volumio[865]: info: Loading plugin "wizard"... Sep 14 17:19:26 volumio-woonkamer volumio[865]: info: Loading plugin "networkfs"... Sep 14 17:19:27 volumio-woonkamer volumio[865]: info: Starting Udev Watcher for removable devices Sep 14 17:19:27 volumio-woonkamer sudo[946]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=rob.vangeloven,password=ShadowsDance4Me,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //nas.vangeloven.net/music /mnt/NAS/DS212 Sep 14 17:19:27 volumio-woonkamer sudo[946]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:27 volumio-woonkamer volumio[865]: info: Ignoring mount for partition: boot Sep 14 17:19:27 volumio-woonkamer volumio[865]: info: Ignoring mount for partition: volumio Sep 14 17:19:27 volumio-woonkamer volumio[865]: info: Ignoring mount for partition: volumio_data Sep 14 17:19:27 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 14 17:19:27 volumio-woonkamer volumio[865]: info: Loading plugin "volumio_command_line_client"... Sep 14 17:19:27 volumio-woonkamer volumio[865]: info: Loading plugin "upnp"... Sep 14 17:19:27 volumio-woonkamer volumio[865]: info: [1757863167220] Starting Upmpd Daemon Sep 14 17:19:27 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 14 17:19:27 volumio-woonkamer volumio[865]: info: Loading plugin "my_music"... Sep 14 17:19:27 volumio-woonkamer volumio[865]: info: Loading plugin "mpd"... Sep 14 17:19:27 volumio-woonkamer kernel: Key type cifs.spnego registered Sep 14 17:19:27 volumio-woonkamer kernel: Key type cifs.idmap registered Sep 14 17:19:27 volumio-woonkamer kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Sep 14 17:19:27 volumio-woonkamer kernel: CIFS: Attempting to mount //nas.vangeloven.net/music Sep 14 17:19:27 volumio-woonkamer sudo[929]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:27 volumio-woonkamer kernel: cryptd: max_cpu_qlen set to 1000 Sep 14 17:19:28 volumio-woonkamer sudo[946]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:28 volumio-woonkamer volumio[865]: info: Loading plugin "upnp_browser"... Sep 14 17:19:29 volumio-woonkamer systemd[1]: systemd-fsckd.service: Succeeded. Sep 14 17:19:29 volumio-woonkamer volumio[865]: info: Loading plugin "alarm-clock"... Sep 14 17:19:29 volumio-woonkamer volumio[865]: info: Loading plugin "airplay_emulation"... Sep 14 17:19:29 volumio-woonkamer volumio[865]: info: Starting Shairport Sync Sep 14 17:19:29 volumio-woonkamer volumio[865]: info: Loading plugin "last_100"... Sep 14 17:19:29 volumio-woonkamer volumio[865]: info: Loading plugin "webradio"... Sep 14 17:19:30 volumio-woonkamer volumio[865]: info: Loading plugin "i2s_dacs"... Sep 14 17:19:30 volumio-woonkamer volumio[865]: info: Loading plugin "volumiodiscovery"... Sep 14 17:19:30 volumio-woonkamer volumio[865]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 14 17:19:30 volumio-woonkamer volumio[865]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 14 17:19:30 volumio-woonkamer node[865]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 14 17:19:30 volumio-woonkamer volumio[865]: *** WARNING *** For more information see Sep 14 17:19:30 volumio-woonkamer volumio[865]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 14 17:19:30 volumio-woonkamer volumio[865]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 14 17:19:30 volumio-woonkamer volumio[865]: *** WARNING *** For more information see Sep 14 17:19:30 volumio-woonkamer node[865]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 14 17:19:30 volumio-woonkamer node[865]: *** WARNING *** For more information see Sep 14 17:19:30 volumio-woonkamer node[865]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 14 17:19:30 volumio-woonkamer node[865]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 14 17:19:30 volumio-woonkamer node[865]: *** WARNING *** For more information see Sep 14 17:19:30 volumio-woonkamer volumio[865]: info: Applying required configuration parameters for plugin volumiodiscovery Sep 14 17:19:30 volumio-woonkamer volumio[865]: info: Discovery: Started advertising with name: Volumio-Woonkamer Sep 14 17:19:30 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 14 17:19:30 volumio-woonkamer volumio[865]: info: Loading plugin "bandcamp"... Sep 14 17:19:30 volumio-woonkamer sh[439]: timed out Sep 14 17:19:30 volumio-woonkamer dhcpcd[483]: timed out Sep 14 17:19:30 volumio-woonkamer sh[439]: dhcpcd exited Sep 14 17:19:30 volumio-woonkamer dhcpcd[483]: dhcpcd exited Sep 14 17:19:30 volumio-woonkamer systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Sep 14 17:19:30 volumio-woonkamer sh[439]: ifup: failed to bring up eth0 Sep 14 17:19:30 volumio-woonkamer systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Sep 14 17:19:31 volumio-woonkamer volumio[865]: info: Loading plugin "spop"... Sep 14 17:19:33 volumio-woonkamer volumio[865]: info: Loading plugin "ytcr"... Sep 14 17:19:37 volumio-woonkamer volumio[865]: info: Loading plugin "now_playing"... Sep 14 17:19:39 volumio-woonkamer volumio-remote-updater[535]: [2025-09-14 17:19:39] [connect] Successful connection Sep 14 17:19:40 volumio-woonkamer volumio[865]: info: Loading plugin "outputs"... Sep 14 17:19:40 volumio-woonkamer volumio[865]: info: Loading plugin "albumart"... Sep 14 17:19:40 volumio-woonkamer volumio[865]: info: Plugin example_plugin is not enabled Sep 14 17:19:40 volumio-woonkamer volumio[865]: info: Loading plugin "inputs"... Sep 14 17:19:40 volumio-woonkamer volumio[865]: info: Loading plugin "updater_comm"... Sep 14 17:19:40 volumio-woonkamer volumio[865]: info: Plugin mpdemulation is not enabled Sep 14 17:19:40 volumio-woonkamer volumio[865]: info: Loading plugin "rest_api"... Sep 14 17:19:40 volumio-woonkamer volumio[865]: info: Loading plugin "websocket"... Sep 14 17:19:40 volumio-woonkamer volumio[865]: info: Starting Socket.io Server version 2.3.0 Sep 14 17:19:40 volumio-woonkamer volumio[865]: info: Loading plugin "music_services_shield"... Sep 14 17:19:40 volumio-woonkamer volumio[865]: Forking 3 albumart workers Sep 14 17:19:41 volumio-woonkamer volumio[865]: info: Applying required configuration parameters for plugin music_services_shield Sep 14 17:19:41 volumio-woonkamer volumio[865]: info: Loading plugin "Systeminfo"... Sep 14 17:19:42 volumio-woonkamer volumio[865]: info: Loading i18n strings for locale en Sep 14 17:19:42 volumio-woonkamer volumio[865]: Updating browse sources language Sep 14 17:19:42 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreCommandRouter::initPlayerControls Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 14 17:19:43 volumio-woonkamer volumio[865]: Express server listening on port 3000 Sep 14 17:19:43 volumio-woonkamer volumio[865]: [Metrics] WebUI: 24s 470.85ms Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreStateMachine::resetVolumioState Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreStateMachine::getcurrentVolume Sep 14 17:19:43 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioRetrievevolume Sep 14 17:19:43 volumio-woonkamer volumio[865]: Starting albumart workers Sep 14 17:19:43 volumio-woonkamer sudo[1045]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 14 17:19:43 volumio-woonkamer sudo[1045]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:43 volumio-woonkamer volumio[865]: Starting albumart workers Sep 14 17:19:44 volumio-woonkamer sudo[1045]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: Volumio Network Manager: Network status updated: 2 Sep 14 17:19:44 volumio-woonkamer sudo[1047]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 14 17:19:44 volumio-woonkamer sudo[1047]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:44 volumio-woonkamer sudo[1047]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:44 volumio-woonkamer volumio[865]: Starting albumart workers Sep 14 17:19:44 volumio-woonkamer volumio-remote-updater[535]: [2025-09-14 17:19:44] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1757863179 101 Sep 14 17:19:44 volumio-woonkamer volumio[865]: 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: 1 Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreStateMachine::pushState Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CorePlayQueue::getTrack 0 Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioPushState Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreStateMachine::updateTrackBlock Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CorePlayQueue::getTrackBlock Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioRetrievevolume Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioGetState Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CorePlayQueue::getTrack 0 Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: Reloading queue from file Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreStateMachine::setRepeat null single undefined Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreStateMachine::pushState Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CorePlayQueue::getTrack 0 Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioPushState Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreStateMachine::setRandom null Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreStateMachine::pushState Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CorePlayQueue::getTrack 0 Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioPushState Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: Setting Device type: Raspberry PI Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: Listing playlists Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: Listing playlists Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: Completed loading Core Plugins Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: Preparing to generate the ALSA configuration file Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreStateMachine::pushState Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CorePlayQueue::getTrack 0 Sep 14 17:19:44 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioPushState Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: Reading ALSA contributions from plugins. Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: Discovery: adding 205c2c0c-d182-4196-940f-741ae188d857 Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: Discovery: Found device Volumio-Woonkamer Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioGetState Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: CorePlayQueue::getTrack 0 Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: Asound.conf file unchanged, so no further update is needed Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: Output device has changed, restarting MPD Sep 14 17:19:45 volumio-woonkamer sudo[1062]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Sep 14 17:19:45 volumio-woonkamer sudo[1062]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: Output device has changed, restarting Shairport Sync Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 14 17:19:45 volumio-woonkamer sudo[1065]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 14 17:19:45 volumio-woonkamer sudo[1065]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:45 volumio-woonkamer systemd[1]: Started UPnP Renderer front-end to MPD. Sep 14 17:19:45 volumio-woonkamer sudo[1065]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:45 volumio-woonkamer sudo[1062]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:45 volumio-woonkamer sudo[1068]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 14 17:19:45 volumio-woonkamer sudo[1068]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:45 volumio-woonkamer systemd[1]: musicservicesshield.service: Succeeded. Sep 14 17:19:45 volumio-woonkamer systemd[1]: Stopped Shield Volumio Music Services in the User CPU Set. Sep 14 17:19:45 volumio-woonkamer systemd[1]: Stopping Shield Volumio Music Services in the User CPU Set... Sep 14 17:19:45 volumio-woonkamer systemd[1]: Stopping Music Player Daemon... Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: ___________ START PLUGINS ___________ Sep 14 17:19:45 volumio-woonkamer systemd[1]: mpd.service: Succeeded. Sep 14 17:19:45 volumio-woonkamer systemd[1]: Stopped Music Player Daemon. Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: ControllerMpd::onStart: Initializing MPD Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: Creating MPD Configuration file Sep 14 17:19:45 volumio-woonkamer systemd[1]: Starting Music Player Daemon... Sep 14 17:19:45 volumio-woonkamer sudo[1076]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 14 17:19:45 volumio-woonkamer sudo[1076]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:45 volumio-woonkamer sudo[1076]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:45 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: [1757863186040] CoreMusicLibrary::Adding element Media Servers Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 14 17:19:46 volumio-woonkamer sudo[1074]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 14 17:19:46 volumio-woonkamer sudo[1085]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 14 17:19:46 volumio-woonkamer sudo[1074]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:46 volumio-woonkamer sudo[1085]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:46 volumio-woonkamer sudo[1074]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 14 17:19:46 volumio-woonkamer systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Sep 14 17:19:46 volumio-woonkamer systemd[1]: mpd.service: Succeeded. Sep 14 17:19:46 volumio-woonkamer systemd[1]: Stopped Music Player Daemon. Sep 14 17:19:46 volumio-woonkamer systemd[1]: Starting Music Player Daemon... Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: [1757863186574] CoreMusicLibrary::Adding element Last_100 Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: [1757863186585] CoreMusicLibrary::Adding element Webradio Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: Initializing BBC Radios Sep 14 17:19:46 volumio-woonkamer sudo[1102]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 14 17:19:46 volumio-woonkamer sudo[1102]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:46 volumio-woonkamer sudo[1102]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: [1757863186778] CoreMusicLibrary::Adding element Bandcamp Discover Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 14 17:19:46 volumio-woonkamer volumio[865]: Cannot find translation for source Bandcamp Discover Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: Creating Spotify config file Sep 14 17:19:46 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: [now-playing-config] Config is up to date. Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: Discovery: Getting this device information Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioGetState Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: CorePlayQueue::getTrack 0 Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: Volumio Calling Home Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: [now-playing-app] App is listening on port 4004. Sep 14 17:19:47 volumio-woonkamer sudo[1167]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/moveallprocesses.sh Sep 14 17:19:47 volumio-woonkamer sudo[1167]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: MPD Permissions set Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: MPD Permissions set Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: Upmpdcli Daemon Started Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioGetState Sep 14 17:19:47 volumio-woonkamer volumio[865]: info: CorePlayQueue::getTrack 0 Sep 14 17:19:48 volumio-woonkamer systemd[1]: systemd-timedated.service: Succeeded. Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: Spotify config file written Sep 14 17:19:48 volumio-woonkamer sudo[1183]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 14 17:19:48 volumio-woonkamer sudo[1183]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:48 volumio-woonkamer volumio[865]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: Volumio called home Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: No need to fix Spotify hosts Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer systemd[1]: Started go-librespot Daemon. Sep 14 17:19:48 volumio-woonkamer go-librespot[1192]: go-librespot daemon starting... Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 14 17:19:48 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 14 17:19:48 volumio-woonkamer sudo[1183]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:49 volumio-woonkamer volumio[865]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Sep 14 17:19:49 volumio-woonkamer volumio[865]: SPOTIFY: BQBvqgUsHSt9-0yWa1mypiqWVk5k1oa8LVInn0B-LIWgfUSi3huPRaQ1YPipDyHtMb7iNt9cf1a1I-Zv4Hk8a_7vla2NoBtZtLzY_fYErkDGt0l9yekMbomr1INUVM_k6dwgmaS1IEPULUfiaVU3cbSd_UcdIleDYgSRylH9AOTv8bMMiej--BlacUMiG6G6wdJ2r77cKPf9FIanqmkOUrcgfS_J-kjCAMHffUCDAZgzWbSXBq03iSRGhgvhQEGepNTyR03o1Ka9PNE7Ta1UdQ Sep 14 17:19:49 volumio-woonkamer volumio[865]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Sep 14 17:19:49 volumio-woonkamer volumio[865]: info: New Spotify access token = BQBvqgUsHSt9-0yWa1mypiqWVk5k1oa8LVInn0B-LIWgfUSi3huPRaQ1YPipDyHtMb7iNt9cf1a1I-Zv4Hk8a_7vla2NoBtZtLzY_fYErkDGt0l9yekMbomr1INUVM_k6dwgmaS1IEPULUfiaVU3cbSd_UcdIleDYgSRylH9AOTv8bMMiej--BlacUMiG6G6wdJ2r77cKPf9FIanqmkOUrcgfS_J-kjCAMHffUCDAZgzWbSXBq03iSRGhgvhQEGepNTyR03o1Ka9PNE7Ta1UdQ Sep 14 17:19:49 volumio-woonkamer volumio[865]: info: Spotify credentials grant success - running version from March 24, 2019 Sep 14 17:19:49 volumio-woonkamer volumio[865]: info: Starting Shairport Sync Sep 14 17:19:49 volumio-woonkamer volumio[865]: info: Starting Shairport Sync Sep 14 17:19:49 volumio-woonkamer volumio[865]: info: Starting Shairport Sync Sep 14 17:19:49 volumio-woonkamer sudo[1207]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 14 17:19:49 volumio-woonkamer sudo[1207]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:49 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:49+02:00" level=info msg="running go-librespot 0.3.2" Sep 14 17:19:49 volumio-woonkamer sudo[1209]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 14 17:19:49 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:49+02:00" level=debug msg="app state loaded" Sep 14 17:19:49 volumio-woonkamer sudo[1209]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:49 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:49+02:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 14 17:19:49 volumio-woonkamer sudo[1211]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 14 17:19:49 volumio-woonkamer sudo[1211]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:49 volumio-woonkamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Sep 14 17:19:49 volumio-woonkamer systemd[1]: shairport-sync.service: Succeeded. Sep 14 17:19:49 volumio-woonkamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Sep 14 17:19:49 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioGetState Sep 14 17:19:49 volumio-woonkamer volumio[865]: info: CorePlayQueue::getTrack 0 Sep 14 17:19:49 volumio-woonkamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Sep 14 17:19:49 volumio-woonkamer sudo[1167]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:49 volumio-woonkamer sudo[1207]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:49 volumio-woonkamer sudo[1209]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:49 volumio-woonkamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Sep 14 17:19:49 volumio-woonkamer systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Sep 14 17:19:49 volumio-woonkamer systemd[1]: shairport-sync.service: Succeeded. Sep 14 17:19:49 volumio-woonkamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Sep 14 17:19:49 volumio-woonkamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Sep 14 17:19:49 volumio-woonkamer sudo[1211]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:49 volumio-woonkamer volumio[865]: info: Shairport-Sync Started Sep 14 17:19:49 volumio-woonkamer volumio[865]: Error adding Membership: Error: addMembership EINVAL Sep 14 17:19:49 volumio-woonkamer volumio[865]: info: Shairport-Sync Started Sep 14 17:19:49 volumio-woonkamer volumio[865]: info: Shairport-Sync Started Sep 14 17:19:50 volumio-woonkamer mpd[1117]: Sep 14 17:19 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Sep 14 17:19:50 volumio-woonkamer volumio[865]: SPOTIFY: User informations: {"country":"NL","display_name":"noldir","email":"rob@vangeloven.net","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/noldir"},"followers":{"href":null,"total":5},"href":"https://api.spotify.com/v1/users/noldir","id":"noldir","images":[],"product":"premium","type":"user","uri":"spotify:user:noldir"} Sep 14 17:19:50 volumio-woonkamer volumio[865]: info: Spotify Successfully logged in Sep 14 17:19:50 volumio-woonkamer systemd[1]: Started Music Player Daemon. Sep 14 17:19:50 volumio-woonkamer sudo[1085]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:50 volumio-woonkamer sudo[1068]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:50 volumio-woonkamer volumio[865]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 14 17:19:50 volumio-woonkamer volumio[865]: info: [1757863190196] CoreMusicLibrary::Adding element Spotify Sep 14 17:19:50 volumio-woonkamer volumio[865]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 14 17:19:50 volumio-woonkamer volumio[865]: Cannot find translation for source Bandcamp Discover Sep 14 17:19:50 volumio-woonkamer volumio[865]: Cannot find translation for source Spotify Sep 14 17:19:50 volumio-woonkamer systemd[1]: Starting Shield Volumio Music Services in the User CPU Set... Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=info msg="zeroconf server listening on port 45167" Sep 14 17:19:50 volumio-woonkamer sudo[1224]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/addservice.sh Sep 14 17:19:50 volumio-woonkamer sudo[1224]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 14 17:19:50 volumio-woonkamer volumio[865]: Upnp client error: Error: This socket has been ended by the other party Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="obtained new client token: AADmyQA/qRgwytR3L424yk7DDa0p9Tnor7E7G3+t1ZawyBpB5C67HOWwQCFNhED9kwvC08JfFQImY7hY0+03zKOXu6IHO2LWpmx/yWdW8EUCplTeAG0Icqmf/j/4ngVTDSm4xKa9BBvbCjhg1+3xOJS3TgNgpOg7JdLVk4ZxSOpF1kjMjlRIDqzv7Thdf2ZpsGG9AmuVVTL2PeJAt/67t7ymIyaMzdEyRHZQDsSr8/l8+AhhafTnL73YMQ==" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="completed keyexchange" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="completed challenge" Sep 14 17:19:50 volumio-woonkamer volumio[865]: [yt-cast-receiver] Listening on port 8098 Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=info msg="authenticated AP" username="no**ir" Sep 14 17:19:50 volumio-woonkamer volumio[865]: info: Completed starting Core Plugins Sep 14 17:19:50 volumio-woonkamer volumio[865]: info: ------------------------------------------- Sep 14 17:19:50 volumio-woonkamer volumio[865]: info: ----- MyVolumio plugins startup ---- Sep 14 17:19:50 volumio-woonkamer volumio[865]: info: ------------------------------------------- Sep 14 17:19:50 volumio-woonkamer volumio[865]: info: [MyVolumio PluginManager] Fetching plans data.... Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=info msg="authenticated Login5" username="no**ir" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="initializing zeroconf session" username="no**ir" Sep 14 17:19:50 volumio-woonkamer volumio[865]: error: MPD error: The expression evaluated to a falsy value: Sep 14 17:19:50 volumio-woonkamer volumio[865]: assert.ok(self.idling) Sep 14 17:19:50 volumio-woonkamer volumio[865]: error: The expression evaluated to a falsy value: Sep 14 17:19:50 volumio-woonkamer volumio[865]: assert.ok(self.idling) Sep 14 17:19:50 volumio-woonkamer volumio[865]: info: MPD running with PID1117 Sep 14 17:19:50 volumio-woonkamer volumio[865]: ,establishing connection Sep 14 17:19:50 volumio-woonkamer volumio[865]: error: updateQueue error: null Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="dealer connection opened" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=trace msg="starting accesspoint recv loop" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=trace msg="received accesspoint ping" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=trace msg="starting dealer recv loop" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=debug msg="received connection id: ZDM1MjUwNWEtYzc3...NjZCOERENUY4NQ==" Sep 14 17:19:50 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:50+02:00" level=trace msg="received accesspoint pong ack" Sep 14 17:19:51 volumio-woonkamer volumio[865]: error: updateQueue error: null Sep 14 17:19:51 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:51+02:00" level=debug msg="put connect state because NEW_DEVICE" Sep 14 17:19:51 volumio-woonkamer volumio[1067]: Generating RSA private key, 4096 bit long modulus (2 primes) Sep 14 17:19:51 volumio-woonkamer volumio[1228]: cset: --> shielding system active with Sep 14 17:19:51 volumio-woonkamer volumio[1228]: cset: "system" cpuset of CPUSPEC(1-3) with 121 tasks running Sep 14 17:19:51 volumio-woonkamer volumio[1228]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Sep 14 17:19:51 volumio-woonkamer systemd[1]: Started Shield Volumio Music Services in the User CPU Set. Sep 14 17:19:51 volumio-woonkamer systemd[1]: Reloading. Sep 14 17:19:51 volumio-woonkamer volumio[865]: info: go-librespot daemon successfully initialized Sep 14 17:19:52 volumio-woonkamer systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Sep 14 17:19:53 volumio-woonkamer systemd[1]: getty@tty1.service: Current command vanished from the unit file, execution of the command list won't be resumed. Sep 14 17:19:53 volumio-woonkamer systemd[1]: serial-getty@ttyAMA0.service: Current command vanished from the unit file, execution of the command list won't be resumed. Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=debug msg="handling transfer player command from b8e4c7f3a30adc31b873cbd8aaa8f321526224e6" Sep 14 17:19:53 volumio-woonkamer sudo[1224]: pam_unix(sudo:session): session closed for user root Sep 14 17:19:53 volumio-woonkamer volumio[865]: info: succeeded Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=debug msg="resolved context of track" uri="spotify:station:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:station:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=warning msg="failed seeking to track in context spotify:station:track:6FprHCXM3mZMEvd1G3JEzz" error="failed fetching tracks for seek: failed moving to next index 50 (page 1): failed fetching next page: invalid status code from page at radio-apollo/v3/tracks/spotify:station:track:6FprHCXM3mZMEvd1G3JEzz?salt=107459&autoplay=false&count=50&isVideo=false&prev_tracks=6FprHCXM3mZMEvd1G3JEzz,4adRxAgzHRDQ3TUJsVQac4,0qoMBdKnbwHfiH7htXFZIi,601YeK6J9i7ttA9rFBoIUf,0PU8le7Cce8gOMBfhlqn3x,27MAqoWBB52gGGtcn5DRTm,3JPnytaQHQ106uCUVHM2bd,7fXY04b7grZYwE87TLIYXQ,5sv9ATwU44XNkprjN3OffC,24qLdtRCOXz9twkB2dsFLm,0tLkpmdRsw5AjcgIy9F8IY,2LmYr2rkQjfNkodi660kkK,2ySSQLJrQPeBEvUDWoNens,60LMeES6FM3GRWgz21Yyt3,4qXp0dzomNdGedffxnPbBP,5sL1AIc2lbOl3CZf7om3mj,6ieM1sOnY3beQzE0u9xaps,0bxcMHuvPutej8x9vMuJxv,2wEc0GjTmoVGoRo2YsPhys,5bmrd7QVE9WiKTrOCkWzBQ,6ov4wjl9zcvS0JXP9P4eZc,1nKZXtsIi9Li4L9lGp4nvD,1c1WCm41CX8Cn7HqldOk6v,7md2TDl3OCU2uaRjhwwhj1,0cZqjNA7WcjDj1Iwh6n69a,426QC3tyWIHwV4VMLtf5GZ,6PZrnEL7MFBl7H6KQv3Jia,0zCkJsVWolDzdV3WxWV279,0PabAatHTS414Kus2acjqA,7nhFRkErobQCZ5dKspNXRj,5hDqohK72gS93shTxD50OA,7cM8Cjclevl8MwHEEtMPuh,3fUgIawiE2x1WvKY8oON5K,4KE4ZbU4eKIDlHhSKzs92S,0OQMGiWzrNJMRnasE5pFOL,1nVSCnP70HDpZbjLHG4Ykv,6fWZBzA9xfZvMWA7Gv7c1O,7vOgvDIAcvAiHMrHPNv6kH,1ma4ZOc6giIVBIxwgrcebE,7mUMCfFiKttp2yAURUotoH,6LepskP1rTalw2JXhyt25x,4oLpT6IBODZV3vx7g6kpV5,73apqK43DIldvrrGxE1VHk,3UlcHAxKgytrvmaouP03Dq,7DZ4onBkmtwtb92z7OU7LD,4DDmJQh8y61klhMNNokbxZ,1NPqsgT7c1pCJCKqVdtlUJ,6nw2pJfjjOoGNg0nVUVaG3,3mxfQ05OtKPIVjwrOZrlth,0OYeWhNZaaM2dhpzf7rraF&minimal=true: 502" uri="spotify:station:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=debug msg="loading track (paused: true, position: 1718ms)" uri="spotify:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=trace msg="emitting websocket event: will_play" Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1338" Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=debug msg="selected format OGG_VORBIS_320 (28bb9be5ba846f4d3216e9ca4499518f8750d6a2)" uri="spotify:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=debug msg="requested aes key for file 28bb9be5ba846f4d3216e9ca4499518f8750d6a2, gid: 6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:53 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:53+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 167" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1120" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="fetched first chunk of 17, total size is 8796036 bytes" uri="spotify:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=trace msg="seek to 1718ms (diff: 203ms, samples: 75763, bytes: 61731)" uri="spotify:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="created new output device" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=info msg="loaded track \"Freeze Man (Megaman 7)\" (paused: true, position: 1718ms, duration: 195800ms, prefetched: false)" uri="spotify:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=trace msg="emitting websocket event: metadata" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=trace msg="emitting websocket event: active" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="sending successful reply for dealer request" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=trace msg="emitting websocket event: paused" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:54 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:54+02:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:54 volumio-woonkamer volumio[865]: info: Initializing connection to go-librespot Websocket Sep 14 17:19:55 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:55+02:00" level=debug msg="new websocket client" Sep 14 17:19:55 volumio-woonkamer volumio[865]: info: Connection to go-librespot Websocket established Sep 14 17:19:55 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:55+02:00" level=debug msg="handling resume player command from b8e4c7f3a30adc31b873cbd8aaa8f321526224e6" Sep 14 17:19:55 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:55+02:00" level=trace msg="seek to 1718ms (diff: 203ms, samples: 75763, bytes: 61731)" uri="spotify:track:6FprHCXM3mZMEvd1G3JEzz" Sep 14 17:19:55 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:55+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" Sep 14 17:19:55 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:55+02:00" level=debug msg="resume track at 1515ms" Sep 14 17:19:55 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:55+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 17:19:55 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:55+02:00" level=trace msg="scheduling prefetch in 164s" Sep 14 17:19:55 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:55+02:00" level=debug msg="sending successful reply for dealer request" Sep 14 17:19:55 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:55+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 14 17:19:55 volumio-woonkamer go-librespot[1192]: time="2025-09-14T17:19:55+02:00" level=trace msg="emitting websocket event: playing" Sep 14 17:19:55 volumio-woonkamer volumio[865]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6FprHCXM3mZMEvd1G3JEzz","resume":true,"play_origin":""}} Sep 14 17:19:55 volumio-woonkamer volumio[865]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 14 17:19:55 volumio-woonkamer volumio[865]: TypeError: Cannot read property 'service' of undefined Sep 14 17:19:55 volumio-woonkamer volumio[865]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at WebSocket.emit (events.js:315:20) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at Receiver.emit (events.js:315:20) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at writeOrBuffer (internal/streams/writable.js:358:12) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at Socket.emit (events.js:315:20) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at addChunk (internal/streams/readable.js:309:12) Sep 14 17:19:55 volumio-woonkamer volumio[865]: at readableAddChunk (internal/streams/readable.js:284:9) Sep 14 17:19:55 volumio-woonkamer volumio[865]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 14 17:19:56 volumio-woonkamer sudo[1287]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-09-14 17:18 Sep 14 17:19:56 volumio-woonkamer sudo[1287]: 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"