-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sun 2025-05-11 09:24:39 CEST. -- May 11 09:24:05 patrick systemd-timedated[872]: Changed local time to Sun May 11 09:24:05 2025 May 11 09:24:05 patrick sudo[870]: pam_unix(sudo:session): session closed for user root May 11 09:24:05 patrick volumio-time-update[496]: volumio-time-update-util: System time updated successfully. May 11 09:24:05 patrick systemd[1]: Started Volumio Time Update Utility. May 11 09:24:05 patrick systemd[1]: Reached target Multi-User System. May 11 09:24:05 patrick systemd[1]: Reached target Graphical Interface. May 11 09:24:05 patrick systemd[1]: Starting Update UTMP about System Runlevel Changes... May 11 09:24:05 patrick systemd[1]: Starting Daily apt download activities... May 11 09:24:05 patrick systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 11 09:24:05 patrick systemd[1]: Started Update UTMP about System Runlevel Changes. May 11 09:24:05 patrick volumio[835]: info: ------------------------------------------- May 11 09:24:05 patrick volumio[835]: info: ----- Volumio3 ---- May 11 09:24:05 patrick volumio[835]: info: ------------------------------------------- May 11 09:24:05 patrick volumio[835]: info: ----- System startup ---- May 11 09:24:05 patrick volumio[835]: info: ------------------------------------------- May 11 09:24:06 patrick systemd[1]: apt-daily.service: Succeeded. May 11 09:24:06 patrick systemd[1]: Started Daily apt download activities. May 11 09:24:07 patrick systemd[1]: Starting Daily apt upgrade and clean activities... May 11 09:24:07 patrick volumio[835]: info: MYVOLUMIO Environment detected May 11 09:24:07 patrick volumio[835]: info: Plugin folders cleanup May 11 09:24:07 patrick volumio[835]: info: Scanning into folder /volumio/app/plugins/ May 11 09:24:07 patrick volumio[835]: info: Scanning category audio_interface May 11 09:24:07 patrick volumio[835]: info: Scanning category miscellanea May 11 09:24:07 patrick volumio[835]: info: Scanning category music_service May 11 09:24:07 patrick volumio[835]: info: Scanning category plugins.json May 11 09:24:07 patrick volumio[835]: info: Scanning category system_controller May 11 09:24:07 patrick volumio[835]: info: Scanning category user_interface May 11 09:24:07 patrick volumio[835]: info: Scanning into folder /data/plugins/ May 11 09:24:07 patrick volumio[835]: info: Scanning category music_service May 11 09:24:07 patrick volumio[835]: info: Plugin folders cleanup completed May 11 09:24:07 patrick volumio[835]: info: ------------------------------------------- May 11 09:24:07 patrick volumio[835]: info: ----- Core plugins startup ---- May 11 09:24:07 patrick volumio[835]: info: ------------------------------------------- May 11 09:24:07 patrick volumio[835]: info: Loading plugins from folder /volumio/app/plugins/ May 11 09:24:07 patrick volumio[835]: info: Adding plugin upnp to MyMusic Plugins May 11 09:24:07 patrick volumio[835]: info: Adding plugin airplay_emulation to MyMusic Plugins May 11 09:24:07 patrick volumio[835]: info: Adding plugin upnp_browser to MyMusic Plugins May 11 09:24:07 patrick volumio[835]: info: Loading plugins from folder /data/plugins/ May 11 09:24:07 patrick volumio[835]: info: Loading plugin "system"... May 11 09:24:07 patrick volumio[835]: info: Loading plugin "appearance"... May 11 09:24:08 patrick systemd[1]: apt-daily-upgrade.service: Succeeded. May 11 09:24:08 patrick systemd[1]: Started Daily apt upgrade and clean activities. May 11 09:24:08 patrick systemd[1]: Startup finished in 13.613s (kernel) + 25.473s (userspace) = 39.086s. May 11 09:24:09 patrick volumio[835]: info: Loading plugin "network"... May 11 09:24:09 patrick volumio[835]: info: Refreshing Cached IP Addresses May 11 09:24:09 patrick volumio[835]: info: Loading plugin "services"... May 11 09:24:09 patrick volumio[835]: info: Loading plugin "alsa_controller"... May 11 09:24:09 patrick sudo[988]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 11 09:24:09 patrick sudo[990]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 11 09:24:09 patrick sudo[990]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:09 patrick sudo[993]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 11 09:24:09 patrick sudo[988]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:09 patrick sudo[993]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:09 patrick sudo[990]: pam_unix(sudo:session): session closed for user root May 11 09:24:09 patrick sudo[988]: pam_unix(sudo:session): session closed for user root May 11 09:24:09 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 11 09:24:09 patrick volumio[835]: info: Loading plugin "wizard"... May 11 09:24:09 patrick volumio[835]: info: Loading plugin "networkfs"... May 11 09:24:09 patrick volumio[835]: info: Starting Udev Watcher for removable devices May 11 09:24:09 patrick sudo[1016]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=media,password=PW-unterhaltung24,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.178.75/music /mnt/NAS/NAS_Music May 11 09:24:09 patrick sudo[1016]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:09 patrick volumio[835]: info: Ignoring mount for partition: boot May 11 09:24:09 patrick volumio[835]: info: Ignoring mount for partition: volumio May 11 09:24:09 patrick volumio[835]: info: Ignoring mount for partition: volumio_data May 11 09:24:09 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 11 09:24:09 patrick volumio[835]: info: Loading plugin "volumio_command_line_client"... May 11 09:24:10 patrick volumio[835]: info: Loading plugin "upnp"... May 11 09:24:10 patrick volumio[835]: info: [1746948250039] Starting Upmpd Daemon May 11 09:24:10 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 11 09:24:10 patrick volumio[835]: info: Loading plugin "my_music"... May 11 09:24:10 patrick volumio[835]: info: Loading plugin "mpd"... May 11 09:24:10 patrick kernel: Key type cifs.spnego registered May 11 09:24:10 patrick kernel: Key type cifs.idmap registered May 11 09:24:10 patrick 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. May 11 09:24:10 patrick kernel: CIFS: Attempting to mount //192.168.178.75/music May 11 09:24:10 patrick kernel: cryptd: max_cpu_qlen set to 1000 May 11 09:24:10 patrick sudo[993]: pam_unix(sudo:session): session closed for user root May 11 09:24:10 patrick sudo[1016]: pam_unix(sudo:session): session closed for user root May 11 09:24:10 patrick volumio[835]: info: Loading plugin "upnp_browser"... May 11 09:24:11 patrick volumio[835]: info: Loading plugin "alarm-clock"... May 11 09:24:11 patrick volumio-remote-updater[513]: [2025-05-11 09:24:11] [connect] Successful connection May 11 09:24:11 patrick volumio[835]: info: Loading plugin "airplay_emulation"... May 11 09:24:11 patrick volumio[835]: info: Starting Shairport Sync May 11 09:24:11 patrick volumio[835]: info: Loading plugin "last_100"... May 11 09:24:11 patrick volumio[835]: info: Loading plugin "webradio"... May 11 09:24:12 patrick volumio[835]: info: Loading plugin "i2s_dacs"... May 11 09:24:12 patrick volumio[835]: info: Loading plugin "volumiodiscovery"... May 11 09:24:12 patrick volumio[835]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 11 09:24:12 patrick volumio[835]: *** WARNING *** Please fix your application to use the native API of Avahi! May 11 09:24:12 patrick volumio[835]: *** WARNING *** For more information see May 11 09:24:12 patrick volumio[835]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 11 09:24:12 patrick node[835]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 11 09:24:12 patrick volumio[835]: *** WARNING *** Please fix your application to use the native API of Avahi! May 11 09:24:12 patrick volumio[835]: *** WARNING *** For more information see May 11 09:24:12 patrick node[835]: *** WARNING *** Please fix your application to use the native API of Avahi! May 11 09:24:12 patrick node[835]: *** WARNING *** For more information see May 11 09:24:12 patrick node[835]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 11 09:24:12 patrick node[835]: *** WARNING *** Please fix your application to use the native API of Avahi! May 11 09:24:12 patrick node[835]: *** WARNING *** For more information see May 11 09:24:12 patrick volumio[835]: info: Applying required configuration parameters for plugin volumiodiscovery May 11 09:24:12 patrick volumio[835]: info: Discovery: Started advertising with name: Patrick May 11 09:24:12 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 11 09:24:12 patrick volumio[835]: info: Loading plugin "spop"... May 11 09:24:14 patrick volumio[835]: info: Loading plugin "youtube2"... May 11 09:24:16 patrick systemd[1]: systemd-fsckd.service: Succeeded. May 11 09:24:16 patrick volumio[835]: info: Loading plugin "ytcr"... May 11 09:24:20 patrick volumio[835]: info: Loading plugin "ytmusic"... May 11 09:24:20 patrick systemd[1]: systemd-hostnamed.service: Succeeded. May 11 09:24:22 patrick volumio[835]: info: Loading plugin "outputs"... May 11 09:24:22 patrick volumio[835]: info: Loading plugin "albumart"... May 11 09:24:22 patrick volumio[835]: info: Plugin example_plugin is not enabled May 11 09:24:22 patrick volumio[835]: info: Loading plugin "inputs"... May 11 09:24:22 patrick volumio[835]: info: Loading plugin "updater_comm"... May 11 09:24:22 patrick volumio[835]: info: Plugin mpdemulation is not enabled May 11 09:24:22 patrick volumio[835]: info: Loading plugin "rest_api"... May 11 09:24:22 patrick volumio[835]: info: Loading plugin "websocket"... May 11 09:24:22 patrick volumio[835]: info: Starting Socket.io Server version 2.3.0 May 11 09:24:22 patrick volumio[835]: info: Loading i18n strings for locale de May 11 09:24:22 patrick volumio[835]: Updating browse sources language May 11 09:24:22 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 09:24:22 patrick volumio[835]: Forking 3 albumart workers May 11 09:24:22 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 09:24:22 patrick volumio[835]: info: CoreCommandRouter::initPlayerControls May 11 09:24:22 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:22 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:22 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:22 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:22 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:22 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:22 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:22 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:22 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 09:24:22 patrick volumio[835]: Express server listening on port 3000 May 11 09:24:22 patrick volumio[835]: [Metrics] WebUI: 18s 943.24ms May 11 09:24:23 patrick volumio[835]: info: CoreStateMachine::resetVolumioState May 11 09:24:23 patrick volumio[835]: info: CoreStateMachine::getcurrentVolume May 11 09:24:23 patrick volumio[835]: info: CoreCommandRouter::volumioRetrievevolume May 11 09:24:23 patrick volumio[835]: info: Volumio Network Manager: Network status updated: 2 May 11 09:24:23 patrick volumio[835]: verbose: New Socket.io Connection to 192.168.178.72:3000 from 192.168.178.85 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 May 11 09:24:23 patrick volumio[835]: verbose: New Socket.io Connection to 192.168.178.72:3000 from 192.168.178.85 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 May 11 09:24:23 patrick volumio[835]: info: CoreStateMachine::pushState May 11 09:24:23 patrick volumio[835]: info: CorePlayQueue::getTrack 0 May 11 09:24:23 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 09:24:23 patrick volumio[835]: info: CoreCommandRouter::volumioPushState May 11 09:24:23 patrick volumio[835]: info: CoreStateMachine::updateTrackBlock May 11 09:24:23 patrick volumio[835]: info: CorePlayQueue::getTrackBlock May 11 09:24:23 patrick volumio[835]: info: CoreCommandRouter::volumioRetrievevolume May 11 09:24:23 patrick sudo[1114]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 11 09:24:23 patrick sudo[1114]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:23 patrick sudo[1116]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 11 09:24:23 patrick sudo[1116]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:23 patrick sudo[1116]: pam_unix(sudo:session): session closed for user root May 11 09:24:23 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 09:24:23 patrick volumio[835]: info: Reloading queue from file May 11 09:24:23 patrick sudo[1114]: pam_unix(sudo:session): session closed for user root May 11 09:24:23 patrick volumio[835]: info: CoreStateMachine::setRepeat null single undefined May 11 09:24:23 patrick volumio[835]: info: CoreStateMachine::pushState May 11 09:24:23 patrick volumio[835]: info: CorePlayQueue::getTrack 0 May 11 09:24:23 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 09:24:23 patrick volumio[835]: info: CoreCommandRouter::volumioPushState May 11 09:24:23 patrick volumio[835]: info: CoreStateMachine::setRandom null May 11 09:24:23 patrick volumio[835]: info: CoreStateMachine::pushState May 11 09:24:23 patrick volumio[835]: info: CorePlayQueue::getTrack 0 May 11 09:24:23 patrick volumio[835]: info: CoreCommandRouter::volumioPushState May 11 09:24:23 patrick volumio[835]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb May 11 09:24:23 patrick volumio[835]: info: USB Boot Capable - System SBC Revision found in cpuinfo: 902120 May 11 09:24:23 patrick volumio[835]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI May 11 09:24:23 patrick volumio[835]: info: Setting Device type: Raspberry PI May 11 09:24:23 patrick volumio[835]: info: Completed loading Core Plugins May 11 09:24:23 patrick volumio[835]: info: Preparing to generate the ALSA configuration file May 11 09:24:23 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket May 11 09:24:23 patrick volumio[835]: info: CoreStateMachine::pushState May 11 09:24:23 patrick volumio[835]: info: CorePlayQueue::getTrack 0 May 11 09:24:23 patrick volumio[835]: info: CoreCommandRouter::volumioPushState May 11 09:24:23 patrick volumio[835]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf May 11 09:24:23 patrick volumio[835]: info: Reading ALSA contributions from plugins. May 11 09:24:24 patrick sudo[1134]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 11 09:24:24 patrick sudo[1134]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:24 patrick volumio[835]: info: CoreCommandRouter::volumioGetState May 11 09:24:24 patrick volumio[835]: info: CorePlayQueue::getTrack 0 May 11 09:24:24 patrick systemd[1]: Started UPnP Renderer front-end to MPD. May 11 09:24:24 patrick sudo[1134]: pam_unix(sudo:session): session closed for user root May 11 09:24:24 patrick volumio[835]: Starting albumart workers May 11 09:24:24 patrick volumio[835]: Starting albumart workers May 11 09:24:24 patrick volumio[835]: Starting albumart workers May 11 09:24:24 patrick volumio[835]: info: Discovery: adding 03a7b5e7-93f3-4385-963f-9fd0fd72de37 May 11 09:24:24 patrick volumio[835]: info: Discovery: Found device Patrick May 11 09:24:24 patrick volumio[835]: info: CoreCommandRouter::volumioGetState May 11 09:24:24 patrick volumio[835]: info: CorePlayQueue::getTrack 0 May 11 09:24:24 patrick volumio[835]: info: Discovery: adding 4ae95fed-fa4a-4919-8ebf-63d156dd3078 May 11 09:24:24 patrick volumio[835]: info: Discovery: Found device Raspi_Station May 11 09:24:24 patrick volumio[835]: info: Discovery: Connecting to remote: 192.168.178.85 May 11 09:24:24 patrick volumio[835]: info: Upmpdcli Daemon Started May 11 09:24:24 patrick volumio[835]: info: Asound.conf file unchanged, so no further update is needed May 11 09:24:24 patrick volumio[835]: info: Output device has changed, restarting MPD May 11 09:24:24 patrick volumio[835]: info: Output device has changed, restarting Shairport Sync May 11 09:24:24 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:24 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 09:24:24 patrick sudo[1139]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 11 09:24:24 patrick sudo[1141]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 11 09:24:24 patrick sudo[1139]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:24 patrick sudo[1141]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:24 patrick sudo[1139]: pam_unix(sudo:session): session closed for user root May 11 09:24:24 patrick systemd[1]: Stopping Music Player Daemon... May 11 09:24:24 patrick volumio[835]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 11 09:24:24 patrick volumio[835]: info: ___________ START PLUGINS ___________ May 11 09:24:25 patrick volumio[835]: info: ControllerMpd::onStart: Initializing MPD May 11 09:24:25 patrick volumio[835]: info: Creating MPD Configuration file May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 09:24:25 patrick sudo[1148]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 11 09:24:25 patrick sudo[1148]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 09:24:25 patrick volumio[835]: info: [1746948265111] CoreMusicLibrary::Adding element Medienserver May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 09:24:25 patrick sudo[1148]: pam_unix(sudo:session): session closed for user root May 11 09:24:25 patrick sudo[1150]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 11 09:24:25 patrick sudo[1150]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 09:24:25 patrick systemd[1]: mpd.service: Succeeded. May 11 09:24:25 patrick systemd[1]: Stopped Music Player Daemon. May 11 09:24:25 patrick volumio[835]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 09:24:25 patrick systemd[1]: Starting Music Player Daemon... May 11 09:24:25 patrick volumio[835]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 09:24:25 patrick volumio[835]: info: [1746948265458] CoreMusicLibrary::Adding element Last_100 May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 09:24:25 patrick volumio[835]: info: [1746948265464] CoreMusicLibrary::Adding element Webradio May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 11 09:24:25 patrick volumio[835]: info: Initializing BBC Radios May 11 09:24:25 patrick volumio[835]: /usr/bin/md5sum: /sys/class/net/eth0/address: No such file or directory May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 09:24:25 patrick sudo[1156]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 11 09:24:25 patrick sudo[1156]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:25 patrick sudo[1156]: pam_unix(sudo:session): session closed for user root May 11 09:24:25 patrick volumio[835]: info: Creating Spotify config file May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 09:24:25 patrick volumio[835]: info: [1746948265938] CoreMusicLibrary::Adding element YouTube2 May 11 09:24:25 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 09:24:25 patrick volumio[835]: Cannot find translation for source YouTube2 May 11 09:24:26 patrick volumio[835]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 09:24:26 patrick volumio[835]: info: [1746948266029] CoreMusicLibrary::Adding element YouTube Music May 11 09:24:26 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 09:24:26 patrick volumio[835]: Cannot find translation for source YouTube2 May 11 09:24:26 patrick volumio[835]: Cannot find translation for source YouTube Music May 11 09:24:26 patrick volumio[835]: info: Volumio Calling Home May 11 09:24:26 patrick volumio-remote-updater[513]: [2025-05-11 09:24:26] [connect] Successful connection May 11 09:24:27 patrick volumio[835]: info: Discovery: Connected to remote: 192.168.178.85 May 11 09:24:27 patrick volumio[835]: error: Upnp client error: Error: This socket has been ended by the other party May 11 09:24:27 patrick volumio[835]: info: MPD Permissions set May 11 09:24:28 patrick volumio[835]: info: MPD Permissions set May 11 09:24:29 patrick volumio-remote-updater[513]: [2025-05-11 09:24:29] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1746948266 101 May 11 09:24:29 patrick volumio[835]: 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: 3 May 11 09:24:29 patrick volumio[835]: info: Volumio called home May 11 09:24:29 patrick volumio[835]: info: Spotify config file written May 11 09:24:29 patrick volumio[835]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 May 11 09:24:29 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:29 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:29 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:29 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:29 patrick sudo[1200]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 11 09:24:29 patrick sudo[1200]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:29 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:29 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 09:24:29 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:29 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:29 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:29 patrick systemd[1]: Started go-librespot Daemon. May 11 09:24:29 patrick go-librespot[1210]: Librespot-go daemon starting... May 11 09:24:29 patrick sudo[1200]: pam_unix(sudo:session): session closed for user root May 11 09:24:29 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 09:24:29 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 09:24:29 patrick volumio[835]: info: No need to fix Spotify hosts May 11 09:24:30 patrick go-librespot[1210]: time="2025-05-11T09:24:30+02:00" level=info msg="generated new device id: 953e72e30d3fd1f3ba342ac4516758ad3c14bcb5" May 11 09:24:30 patrick go-librespot[1210]: time="2025-05-11T09:24:30+02:00" level=debug msg="stored credentials found for 5ka1idsxg34hpl7qi69kbkxmr" May 11 09:24:30 patrick volumio[835]: info: Starting Shairport Sync May 11 09:24:30 patrick volumio[835]: info: Starting Shairport Sync May 11 09:24:30 patrick volumio[835]: info: Starting Shairport Sync May 11 09:24:30 patrick sudo[1232]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 11 09:24:30 patrick sudo[1232]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:30 patrick sudo[1234]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 11 09:24:30 patrick sudo[1234]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:30 patrick sudo[1238]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 11 09:24:30 patrick sudo[1238]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 09:24:30 patrick volumio[835]: info: CoreCommandRouter::volumioGetState May 11 09:24:30 patrick volumio[835]: info: CorePlayQueue::getTrack 0 May 11 09:24:30 patrick volumio[835]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 11 09:24:30 patrick volumio[835]: SPOTIFY: BQBv-4UNee7IXfDHQ1d4LN3LPzXQLeXJgZrGcsbf8plVJCO83JF6WrueHxH4kaU3uWoD9HlDx0UXN3bU7QMAth--t8ObFSyKe94kpBOiSFthqszCvNlVOrcIvOXfAkgGypyBJPML1JB98ec4lQC2hUdGyT-V1UkQttkpJ_a7JmUwJ4s7biLI1dNPC9fNnbCYSPwsFCsGIvdDG8F2kPJaWRlpJI36IOuh5inRc1Nz1bPnl87046k902P4UiAnL74xSxhv-yDvsN3zPJGSkPytO7L2wClT1aSePYMGEJ_15AOjhcc May 11 09:24:30 patrick volumio[835]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 11 09:24:30 patrick volumio[835]: info: New Spotify access token = BQBv-4UNee7IXfDHQ1d4LN3LPzXQLeXJgZrGcsbf8plVJCO83JF6WrueHxH4kaU3uWoD9HlDx0UXN3bU7QMAth--t8ObFSyKe94kpBOiSFthqszCvNlVOrcIvOXfAkgGypyBJPML1JB98ec4lQC2hUdGyT-V1UkQttkpJ_a7JmUwJ4s7biLI1dNPC9fNnbCYSPwsFCsGIvdDG8F2kPJaWRlpJI36IOuh5inRc1Nz1bPnl87046k902P4UiAnL74xSxhv-yDvsN3zPJGSkPytO7L2wClT1aSePYMGEJ_15AOjhcc May 11 09:24:30 patrick volumio[835]: info: Spotify credentials grant success - running version from March 24, 2019 May 11 09:24:30 patrick systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 11 09:24:30 patrick systemd[1]: shairport-sync.service: Succeeded. May 11 09:24:30 patrick systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 11 09:24:30 patrick systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 11 09:24:30 patrick sudo[1232]: pam_unix(sudo:session): session closed for user root May 11 09:24:30 patrick sudo[1234]: pam_unix(sudo:session): session closed for user root May 11 09:24:30 patrick sudo[1238]: pam_unix(sudo:session): session closed for user root May 11 09:24:30 patrick volumio[835]: info: Shairport-Sync Started May 11 09:24:30 patrick volumio[835]: Error adding Membership: Error: addMembership EINVAL May 11 09:24:30 patrick volumio[835]: info: Shairport-Sync Started May 11 09:24:31 patrick go-librespot[1210]: time="2025-05-11T09:24:31+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 11 09:24:31 patrick go-librespot[1210]: time="2025-05-11T09:24:31+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 11 09:24:31 patrick go-librespot[1210]: time="2025-05-11T09:24:31+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 11 09:24:31 patrick go-librespot[1210]: time="2025-05-11T09:24:31+02:00" level=debug msg="zeroconf server listening on port 45565" May 11 09:24:31 patrick volumio[835]: SPOTIFY: User informations: {"country":"DE","display_name":"Roland","email":"roland.joerger@gmx.de","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/5ka1idsxg34hpl7qi69kbkxmr"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/5ka1idsxg34hpl7qi69kbkxmr","id":"5ka1idsxg34hpl7qi69kbkxmr","images":[],"product":"premium","type":"user","uri":"spotify:user:5ka1idsxg34hpl7qi69kbkxmr"} May 11 09:24:31 patrick volumio[835]: info: Spotify Successfully logged in May 11 09:24:31 patrick volumio[835]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 09:24:31 patrick volumio[835]: info: [1746948271136] CoreMusicLibrary::Adding element Spotify May 11 09:24:31 patrick volumio[835]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 09:24:31 patrick volumio[835]: Cannot find translation for source YouTube2 May 11 09:24:31 patrick volumio[835]: Cannot find translation for source YouTube Music May 11 09:24:31 patrick volumio[835]: Cannot find translation for source Spotify May 11 09:24:31 patrick go-librespot[1210]: time="2025-05-11T09:24:31+02:00" level=debug msg="obtained new client token: AAAul3yVYFn/PIpCcrtWuQx19RnLSeLxjcXZjwUGUUlkLuD4nOmnJicUsyvHHeEuYrxq+2IKQpP/59ns9HYxX9iMLahqwcjN3g/xMpnPzr20ixorwonMyP1SrknOu+n5nXLFLWuNaBClNGt75XIT9TY3WE0WQZan9mRR2ISSK69CWh/Tydd/MjQc5UZIlfJQfq/zH+44+iWWbD8X0FwlmAwjfXokekRrLKXLSV7YxEZul4TTRAfdMrE5tpf5" May 11 09:24:31 patrick go-librespot[1210]: time="2025-05-11T09:24:31+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" May 11 09:24:31 patrick go-librespot[1210]: time="2025-05-11T09:24:31+02:00" level=debug msg="completed keyexchange" May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="completed challenge" May 11 09:24:32 patrick volumio[835]: info: [yt-cast-receiver] DIAL server listening on port 8098 May 11 09:24:32 patrick volumio[835]: info: CoreCommandRouter::volumioRetrievevolume May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="authenticated as 5ka1idsxg34hpl7qi69kbkxmr" May 11 09:24:32 patrick volumio[835]: info: CoreCommandRouter::volumioGetState May 11 09:24:32 patrick volumio[835]: info: CorePlayQueue::getTrack 0 May 11 09:24:32 patrick volumio[835]: info: CoreStateMachine::pushState May 11 09:24:32 patrick volumio[835]: info: CorePlayQueue::getTrack 0 May 11 09:24:32 patrick volumio[835]: info: CoreCommandRouter::volumioPushState May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="authenticated as 5ka1idsxg34hpl7qi69kbkxmr" May 11 09:24:32 patrick mpd[1171]: May 11 09:24 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="dealer connection opened" May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="initializing zeroconf session, username: 5ka1idsxg34hpl7qi69kbkxmr" May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="autoplay enabled: false" May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="received connection id: MzljZmNmNWYtMTg4MC00YmU3LWJkZjYtZWZiZDE3ZTMxMWU4K2RlYWxlcit0Y3A6Ly8wYWNhNTljNi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRDgzOTMxQTc4RkQwNUQ1NEMxRkRGMENGOEJDM0IxMEUyMkMwMkJCNTAzMDkyODc5RjM3ODg0QjM3RDkyQzYyNQ==" May 11 09:24:32 patrick systemd[1]: Started Music Player Daemon. May 11 09:24:32 patrick sudo[1141]: pam_unix(sudo:session): session closed for user root May 11 09:24:32 patrick sudo[1150]: pam_unix(sudo:session): session closed for user root May 11 09:24:32 patrick volumio[835]: Upnp client error: Error: This socket has been ended by the other party May 11 09:24:32 patrick volumio[835]: info: Completed starting Core Plugins May 11 09:24:32 patrick volumio[835]: info: ------------------------------------------- May 11 09:24:32 patrick volumio[835]: info: ----- MyVolumio plugins startup ---- May 11 09:24:32 patrick volumio[835]: info: ------------------------------------------- May 11 09:24:32 patrick volumio[835]: info: [MyVolumio PluginManager] Fetching plans data.... May 11 09:24:32 patrick volumio[835]: error: MPD error: The expression evaluated to a falsy value: May 11 09:24:32 patrick volumio[835]: assert.ok(self.idling) May 11 09:24:32 patrick volumio[835]: error: The expression evaluated to a falsy value: May 11 09:24:32 patrick volumio[835]: assert.ok(self.idling) May 11 09:24:32 patrick volumio[835]: info: MPD running with PID1171 May 11 09:24:32 patrick volumio[835]: ,establishing connection May 11 09:24:32 patrick volumio[835]: error: updateQueue error: null May 11 09:24:32 patrick volumio[835]: error: updateQueue error: null May 11 09:24:32 patrick go-librespot[1210]: time="2025-05-11T09:24:32+02:00" level=debug msg="put connect state because NEW_DEVICE" May 11 09:24:33 patrick volumio[835]: info: go-librespot daemon successfully initialized May 11 09:24:33 patrick go-librespot[1210]: time="2025-05-11T09:24:33+02:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusGoingAway and reason = \"\"" May 11 09:24:33 patrick go-librespot[1210]: time="2025-05-11T09:24:33+02:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.178.72:53884->34.158.1.133:4070: use of closed network connection" May 11 09:24:33 patrick go-librespot[1210]: time="2025-05-11T09:24:33+02:00" level=debug msg="obtained new client token: AAB/712rualYxfZSMH8M9hm983PVwL5PcALzQtsFvQVibDwbgy1MlyFd3Bsa4KNI0wUg2fESyMh/THqmodeGU8xTOcGxp/gnQTNPY2i1AEAb+qdU0T3ccO0T+z0rzoUjMnFUoJ3I16I5EJqtf0galDl3eTBiMNT2EmPW9tVqUYrDDiPSJa8JzeGHWJ16ELwJolKOBVHSZOhiShkGYOZ6/PNHIMyzOoWk3JnNi6xqRShBxbeBwe+1wp6aokKkKzA=" May 11 09:24:33 patrick go-librespot[1210]: time="2025-05-11T09:24:33+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" May 11 09:24:33 patrick go-librespot[1210]: time="2025-05-11T09:24:33+02:00" level=debug msg="completed keyexchange" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="completed challenge" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="authenticated as q65woppi4aiylsx5cx9d4xpi6" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="authenticated as q65woppi4aiylsx5cx9d4xpi6" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="dealer connection opened" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=info msg="accepted zeroconf user q65woppi4aiylsx5cx9d4xpi6 from A54 von Patrick" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="received connection id: YjQ5MmIzMTktNjc1Zi00ODIwLTkwOWMtNzc5NzFmMzAxNTdjK2RlYWxlcit0Y3A6Ly8wYWNhNTkxYi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQTVGOEVEOUQyOEJFRUNCMDIwQjlBRTI0MUM5MjNCNTdDQkU4ODE5OThERTUzQjZGNkU5MzZEMzFFQjMwQTlDMg==" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="put connect state because NEW_DEVICE" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="autoplay enabled: false" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="handling transfer player command from e49f9b7e8ad8c20e1966699f4cd47f68a1a455e0" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="resolved context of track" uri="spotify:album:7HaPTdLL3KcYuQkMcVQfRx" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=trace msg="fetched new page 0 with 18 items (list: 18)" uri="spotify:album:7HaPTdLL3KcYuQkMcVQfRx" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=warning msg="failed seeking to track in context spotify:album:7HaPTdLL3KcYuQkMcVQfRx" error="could not find track" May 11 09:24:34 patrick go-librespot[1210]: time="2025-05-11T09:24:34+02:00" level=debug msg="loading track (paused: false, position: 153197ms)" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:35 patrick systemd[1]: systemd-timedated.service: Succeeded. May 11 09:24:35 patrick go-librespot[1210]: time="2025-05-11T09:24:35+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 09:24:35 patrick go-librespot[1210]: time="2025-05-11T09:24:35+02:00" level=trace msg="emitting websocket event: will_play" May 11 09:24:35 patrick go-librespot[1210]: time="2025-05-11T09:24:35+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 11 09:24:35 patrick go-librespot[1210]: time="2025-05-11T09:24:35+02:00" level=debug msg="selected format OGG_VORBIS_320 (08679d1bc0d37b2ae2699087739e37b06f7785ed)" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:35 patrick go-librespot[1210]: time="2025-05-11T09:24:35+02:00" level=debug msg="requested aes key for file 08679d1bc0d37b2ae2699087739e37b06f7785ed, gid: 22NYziqwaRESvIdBnRHPZu" May 11 09:24:35 patrick go-librespot[1210]: time="2025-05-11T09:24:35+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1354" May 11 09:24:35 patrick go-librespot[1210]: time="2025-05-11T09:24:35+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1121" May 11 09:24:35 patrick go-librespot[1210]: time="2025-05-11T09:24:35+02:00" level=debug msg="fetched first chunk of 21, total size is 10597201 bytes" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:36 patrick go-librespot[1210]: time="2025-05-11T09:24:36+02:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:36 patrick volumio[835]: info: Initializing connection to go-librespot Websocket May 11 09:24:36 patrick go-librespot[1210]: time="2025-05-11T09:24:36+02:00" level=debug msg="new websocket client" May 11 09:24:36 patrick volumio[835]: info: Connection to go-librespot Websocket established May 11 09:24:37 patrick go-librespot[1210]: time="2025-05-11T09:24:37+02:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:37 patrick go-librespot[1210]: time="2025-05-11T09:24:37+02:00" level=debug msg="fetched chunk 16/20, size: 524288" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:37 patrick go-librespot[1210]: time="2025-05-11T09:24:37+02:00" level=debug msg="fetched chunk 14/20, size: 524288" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:37 patrick go-librespot[1210]: time="2025-05-11T09:24:37+02:00" level=trace msg="seek to 153197ms (diff: 223ms, samples: 6755987, bytes: 7840569)" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:37 patrick go-librespot[1210]: time="2025-05-11T09:24:37+02:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:37 patrick go-librespot[1210]: time="2025-05-11T09:24:37+02:00" level=debug msg="fetched chunk 17/20, size: 524288" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:37 patrick go-librespot[1210]: time="2025-05-11T09:24:37+02:00" level=debug msg="fetched chunk 15/20, size: 524288" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:38 patrick go-librespot[1210]: time="2025-05-11T09:24:38+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" May 11 09:24:38 patrick go-librespot[1210]: time="2025-05-11T09:24:38+02:00" level=debug msg="created new output device" May 11 09:24:38 patrick go-librespot[1210]: time="2025-05-11T09:24:38+02:00" level=info msg="loaded track \"Coi Leray (Feat. Jeriq)\" (paused: false, position: 153197ms, duration: 208820ms, prefetched: false)" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:38 patrick go-librespot[1210]: time="2025-05-11T09:24:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 09:24:38 patrick go-librespot[1210]: time="2025-05-11T09:24:38+02:00" level=trace msg="scheduling prefetch in 26s" May 11 09:24:38 patrick go-librespot[1210]: time="2025-05-11T09:24:38+02:00" level=trace msg="emitting websocket event: metadata" May 11 09:24:38 patrick go-librespot[1210]: time="2025-05-11T09:24:38+02:00" level=trace msg="emitting websocket event: active" May 11 09:24:38 patrick go-librespot[1210]: time="2025-05-11T09:24:38+02:00" level=debug msg="sending successful reply for dealer request" May 11 09:24:38 patrick go-librespot[1210]: time="2025-05-11T09:24:38+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 11 09:24:38 patrick go-librespot[1210]: time="2025-05-11T09:24:38+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 11 09:24:38 patrick volumio[835]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:22NYziqwaRESvIdBnRHPZu","name":"Coi Leray (Feat. Jeriq)","artist_names":["NSG","Jeriq"],"album_name":"The Big 6","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0235a013059def082619b2377d","position":153197,"duration":208820,"release_date":"year:2025 month:2 day:28","track_number":11,"disc_number":1}} May 11 09:24:38 patrick volumio[835]: SPOTIFY: received: {"type":"active","data":null} May 11 09:24:38 patrick volumio[835]: info: Aligning Spotify Volume to Volumio Volume May 11 09:24:38 patrick volumio[835]: info: CoreCommandRouter::volumioGetState May 11 09:24:38 patrick volumio[835]: info: CorePlayQueue::getTrack 0 May 11 09:24:38 patrick volumio[835]: info: Setting Spotify Volume from Volumio: 89 May 11 09:24:38 patrick volumio[835]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 11 09:24:38 patrick go-librespot[1210]: time="2025-05-11T09:24:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 09:24:38 patrick go-librespot[1210]: time="2025-05-11T09:24:38+02:00" level=trace msg="emitting websocket event: playing" May 11 09:24:38 patrick volumio[835]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:22NYziqwaRESvIdBnRHPZu","play_origin":"playlist"}} May 11 09:24:38 patrick volumio[835]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 11 09:24:38 patrick volumio[835]: TypeError: Cannot read property 'service' of undefined May 11 09:24:38 patrick volumio[835]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) May 11 09:24:38 patrick volumio[835]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) May 11 09:24:38 patrick volumio[835]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) May 11 09:24:38 patrick volumio[835]: at WebSocket.emit (events.js:315:20) May 11 09:24:38 patrick volumio[835]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 11 09:24:38 patrick volumio[835]: at Receiver.emit (events.js:315:20) May 11 09:24:38 patrick volumio[835]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 11 09:24:38 patrick volumio[835]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 11 09:24:38 patrick volumio[835]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 11 09:24:38 patrick volumio[835]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 11 09:24:38 patrick volumio[835]: at writeOrBuffer (internal/streams/writable.js:358:12) May 11 09:24:38 patrick volumio[835]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 11 09:24:38 patrick volumio[835]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 11 09:24:38 patrick volumio[835]: at Socket.emit (events.js:315:20) May 11 09:24:38 patrick volumio[835]: at addChunk (internal/streams/readable.js:309:12) May 11 09:24:38 patrick volumio[835]: at readableAddChunk (internal/streams/readable.js:284:9) May 11 09:24:38 patrick volumio[835]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 11 09:24:39 patrick go-librespot[1210]: time="2025-05-11T09:24:39+02:00" level=debug msg="fetched chunk 18/20, size: 524288" uri="spotify:track:22NYziqwaRESvIdBnRHPZu" May 11 09:24:39 patrick sudo[1270]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-11 09:23 May 11 09:24:39 patrick sudo[1270]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"