-- Logs begin at Sun 2025-03-16 13:06:13 CET, end at Sun 2025-03-16 13:09:33 CET. -- Mar 16 13:08:00 volumio volumio[625]: info: Starting Udev Watcher for removable devices Mar 16 13:08:00 volumio sudo[766]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Markus,password=%Pass4Me$,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.3/Musik /mnt/NAS/Musik Mar 16 13:08:00 volumio sudo[766]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:00 volumio volumio[625]: info: Ignoring mount for partition: boot Mar 16 13:08:00 volumio volumio[625]: info: Ignoring mount for partition: volumio Mar 16 13:08:00 volumio volumio[625]: info: Ignoring mount for partition: volumio_data Mar 16 13:08:00 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 13:08:00 volumio volumio[625]: info: Loading plugin "volumio_command_line_client"... Mar 16 13:08:00 volumio volumio[625]: info: Loading plugin "upnp"... Mar 16 13:08:00 volumio volumio[625]: info: [1742126880536] Starting Upmpd Daemon Mar 16 13:08:00 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 13:08:00 volumio volumio[625]: info: Loading plugin "my_music"... Mar 16 13:08:00 volumio volumio[625]: info: Loading plugin "mpd"... Mar 16 13:08:01 volumio kernel: Key type cifs.spnego registered Mar 16 13:08:01 volumio kernel: Key type cifs.idmap registered Mar 16 13:08:01 volumio 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. Mar 16 13:08:01 volumio kernel: CIFS: Attempting to mount //192.168.0.3/Musik Mar 16 13:08:01 volumio kernel: CIFS: Status code returned 0xc000006d STATUS_LOGON_FAILURE Mar 16 13:08:01 volumio kernel: CIFS: VFS: \\192.168.0.3 Send error in SessSetup = -13 Mar 16 13:08:01 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -13 Mar 16 13:08:01 volumio sudo[766]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:03 volumio volumio[625]: info: Loading plugin "upnp_browser"... Mar 16 13:08:03 volumio volumio-remote-updater[376]: [2025-03-16 13:08:03] [connect] Successful connection Mar 16 13:08:05 volumio volumio[625]: info: Loading plugin "alarm-clock"... Mar 16 13:08:06 volumio volumio[625]: info: Loading plugin "airplay_emulation"... Mar 16 13:08:06 volumio volumio[625]: info: Starting Shairport Sync Mar 16 13:08:06 volumio volumio[625]: info: Loading plugin "last_100"... Mar 16 13:08:06 volumio volumio[625]: info: Loading plugin "webradio"... Mar 16 13:08:07 volumio systemd[1]: systemd-timedated.service: Succeeded. Mar 16 13:08:07 volumio volumio[625]: info: Loading plugin "i2s_dacs"... Mar 16 13:08:07 volumio volumio[625]: info: Loading plugin "volumiodiscovery"... Mar 16 13:08:07 volumio volumio[625]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 16 13:08:07 volumio node[625]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 16 13:08:07 volumio volumio[625]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 13:08:07 volumio node[625]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 13:08:07 volumio volumio[625]: *** WARNING *** For more information see Mar 16 13:08:07 volumio volumio[625]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 16 13:08:07 volumio volumio[625]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 13:08:07 volumio volumio[625]: *** WARNING *** For more information see Mar 16 13:08:07 volumio node[625]: *** WARNING *** For more information see Mar 16 13:08:07 volumio node[625]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 16 13:08:07 volumio node[625]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 13:08:07 volumio node[625]: *** WARNING *** For more information see Mar 16 13:08:07 volumio volumio[625]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 16 13:08:07 volumio volumio[625]: info: Discovery: Started advertising with name: Volumio Mar 16 13:08:07 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 13:08:07 volumio volumio[625]: info: Loading plugin "spop"... Mar 16 13:08:14 volumio volumio[625]: info: Loading plugin "youtube2"... Mar 16 13:08:18 volumio volumio-remote-updater[376]: [2025-03-16 13:08:18] [connect] Successful connection Mar 16 13:08:20 volumio volumio[625]: info: Loading plugin "outputs"... Mar 16 13:08:20 volumio volumio[625]: info: Loading plugin "albumart"... Mar 16 13:08:20 volumio volumio[625]: info: Plugin example_plugin is not enabled Mar 16 13:08:20 volumio volumio[625]: info: Loading plugin "inputs"... Mar 16 13:08:20 volumio volumio[625]: info: Loading plugin "updater_comm"... Mar 16 13:08:21 volumio ntpd[545]: Soliciting pool server 195.186.1.101 Mar 16 13:08:22 volumio volumio[625]: info: Plugin mpdemulation is not enabled Mar 16 13:08:22 volumio volumio[625]: info: Loading plugin "rest_api"... Mar 16 13:08:22 volumio ntpd[545]: Soliciting pool server 80.242.192.230 Mar 16 13:08:22 volumio ntpd[545]: Soliciting pool server 193.134.29.12 Mar 16 13:08:22 volumio ntpd[545]: Soliciting pool server 195.186.4.100 Mar 16 13:08:23 volumio volumio[625]: info: Loading plugin "websocket"... Mar 16 13:08:23 volumio volumio[625]: info: Starting Socket.io Server version 2.3.0 Mar 16 13:08:23 volumio ntpd[545]: Soliciting pool server 185.17.70.106 Mar 16 13:08:23 volumio ntpd[545]: Soliciting pool server 109.233.182.115 Mar 16 13:08:23 volumio ntpd[545]: Soliciting pool server 156.106.214.52 Mar 16 13:08:23 volumio volumio[625]: info: Loading plugin "Systeminfo"... Mar 16 13:08:24 volumio ntpd[545]: Soliciting pool server 62.12.173.12 Mar 16 13:08:24 volumio ntpd[545]: Soliciting pool server 62.220.129.71 Mar 16 13:08:24 volumio ntpd[545]: Soliciting pool server 156.106.214.48 Mar 16 13:08:24 volumio volumio[625]: Forking 1 albumart workers Mar 16 13:08:25 volumio ntpd[545]: Soliciting pool server 2a10:8247:0:1013::12 Mar 16 13:08:25 volumio ntpd[545]: Soliciting pool server 91.235.212.22 Mar 16 13:08:25 volumio ntpd[545]: Soliciting pool server 217.147.223.78 Mar 16 13:08:26 volumio ntpd[545]: Soliciting pool server 83.150.25.25 Mar 16 13:08:27 volumio volumio[625]: info: Loading i18n strings for locale de Mar 16 13:08:27 volumio volumio[625]: Updating browse sources language Mar 16 13:08:27 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 13:08:27 volumio ntpd[545]: Soliciting pool server 46.22.24.205 Mar 16 13:08:28 volumio ntpd[545]: Soliciting pool server 84.16.73.33 Mar 16 13:08:32 volumio ntpd[545]: receive: Unexpected origin timestamp 0xeb813dbc.a02a0c9f does not match aorg 0000000000.00000000 from server@109.233.182.115 xmt 0xeb813dc0.df22a0a0 Mar 16 13:08:32 volumio ntpd[545]: receive: Unexpected origin timestamp 0xeb813dbc.a010861b does not match aorg 0000000000.00000000 from server@91.235.212.22 xmt 0xeb813dc0.df235838 Mar 16 13:08:32 volumio ntpd[545]: receive: Unexpected origin timestamp 0xeb813dbc.a0375999 does not match aorg 0000000000.00000000 from server@80.242.192.230 xmt 0xeb813dc0.df2e563c Mar 16 13:08:32 volumio ntpd[545]: receive: Unexpected origin timestamp 0xeb813dbc.a01d9e4b does not match aorg 0000000000.00000000 from server@185.17.70.106 xmt 0xeb813dc0.deb3d8db Mar 16 13:08:32 volumio ntpd[545]: receive: Unexpected origin timestamp 0xeb813dbc.9ff98f4c does not match aorg 0000000000.00000000 from server@46.22.24.205 xmt 0xeb813dc0.df445088 Mar 16 13:08:33 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 13:08:33 volumio volumio[625]: info: CoreCommandRouter::initPlayerControls Mar 16 13:08:33 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:33 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:33 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:33 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 13:08:33 volumio volumio[625]: Express server listening on port 3000 Mar 16 13:08:33 volumio volumio[625]: [Metrics] WebUI: 44s 634.57ms Mar 16 13:08:34 volumio volumio[625]: info: CoreStateMachine::resetVolumioState Mar 16 13:08:34 volumio volumio[625]: info: CoreStateMachine::getcurrentVolume Mar 16 13:08:34 volumio volumio[625]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 13:08:34 volumio sudo[902]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 16 13:08:34 volumio sudo[902]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:35 volumio sudo[902]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:35 volumio sudo[909]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 16 13:08:35 volumio sudo[909]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:35 volumio sudo[909]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:35 volumio volumio[625]: info: Volumio Network Manager: Network status updated: 1 Mar 16 13:08:35 volumio volumio[625]: info: Cannot mount NAS Musik at system boot, trial number 1 ,retrying in 5 seconds Mar 16 13:08:35 volumio volumio[625]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Mar 16 13:08:35 volumio volumio[625]: wlan0 Interface doesn't support scanning. Mar 16 13:08:35 volumio volumio[625]: info: Cannot use regular scanning, forcing with ap-force Mar 16 13:08:35 volumio sudo[916]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Mar 16 13:08:35 volumio sudo[916]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:35 volumio sudo[916]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:35 volumio volumio[625]: command failed: No such device (-19) Mar 16 13:08:35 volumio volumio[625]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Mar 16 13:08:35 volumio volumio[625]: command failed: No such device (-19) Mar 16 13:08:36 volumio volumio[625]: Starting albumart workers Mar 16 13:08:37 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 13:08:37 volumio volumio[625]: info: CoreStateMachine::setRepeat null single undefined Mar 16 13:08:37 volumio volumio[625]: info: CoreStateMachine::pushState Mar 16 13:08:37 volumio volumio[625]: info: CorePlayQueue::getTrack 0 Mar 16 13:08:37 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 13:08:37 volumio volumio[625]: info: CoreCommandRouter::volumioPushState Mar 16 13:08:37 volumio volumio[625]: info: CoreStateMachine::setRandom true Mar 16 13:08:37 volumio volumio[625]: info: CoreStateMachine::pushState Mar 16 13:08:37 volumio volumio[625]: info: CorePlayQueue::getTrack 0 Mar 16 13:08:37 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 13:08:37 volumio volumio[625]: info: CoreCommandRouter::volumioPushState Mar 16 13:08:37 volumio volumio[625]: info: Setting Device type: Raspberry PI Mar 16 13:08:37 volumio volumio[625]: info: Completed loading Core Plugins Mar 16 13:08:37 volumio volumio[625]: info: Preparing to generate the ALSA configuration file Mar 16 13:08:37 volumio volumio[625]: info: VolumeController:: Volume=62 Mute =false Mar 16 13:08:37 volumio volumio[625]: info: CoreStateMachine::pushState Mar 16 13:08:37 volumio volumio[625]: info: CorePlayQueue::getTrack 0 Mar 16 13:08:37 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 13:08:37 volumio volumio[625]: info: CoreCommandRouter::volumioPushState Mar 16 13:08:37 volumio volumio[625]: info: CoreStateMachine::updateTrackBlock Mar 16 13:08:37 volumio volumio[625]: info: CorePlayQueue::getTrackBlock Mar 16 13:08:37 volumio volumio[625]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 13:08:38 volumio volumio-remote-updater[376]: [2025-03-16 13:08:38] [connect] Successful connection Mar 16 13:08:38 volumio volumio[625]: info: Asound.conf file unchanged, so no further update is needed Mar 16 13:08:38 volumio volumio[625]: info: Output device has changed, restarting MPD Mar 16 13:08:38 volumio sudo[928]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 16 13:08:38 volumio sudo[928]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:38 volumio volumio[625]: info: Output device has changed, restarting Shairport Sync Mar 16 13:08:38 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:38 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 13:08:38 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Mar 16 13:08:38 volumio sudo[928]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:39 volumio sudo[933]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 13:08:39 volumio sudo[930]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 13:08:39 volumio sudo[930]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:39 volumio sudo[933]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:39 volumio sudo[930]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:39 volumio systemd[1]: Stopping Music Player Daemon... Mar 16 13:08:39 volumio systemd[1]: mpd.service: Succeeded. Mar 16 13:08:39 volumio systemd[1]: Stopped Music Player Daemon. Mar 16 13:08:39 volumio volumio[625]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 13:08:39 volumio systemd[1]: Starting Music Player Daemon... Mar 16 13:08:39 volumio volumio[625]: info: ___________ START PLUGINS ___________ Mar 16 13:08:40 volumio volumio[625]: info: ControllerMpd::onStart: Initializing MPD Mar 16 13:08:40 volumio volumio[625]: info: Creating MPD Configuration file Mar 16 13:08:40 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 13:08:40 volumio volumio[625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 13:08:40 volumio volumio[625]: info: [1742126920551] CoreMusicLibrary::Adding element Medienserver Mar 16 13:08:40 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 13:08:40 volumio sudo[943]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 16 13:08:40 volumio sudo[943]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:40 volumio sudo[943]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:40 volumio sudo[945]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 13:08:40 volumio sudo[945]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:40 volumio sudo[945]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:40 volumio sudo[947]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 13:08:40 volumio sudo[947]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:41 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:41 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Mar 16 13:08:41 volumio systemd[1]: mpd.service: Succeeded. Mar 16 13:08:41 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 13:08:41 volumio systemd[1]: Stopped Music Player Daemon. Mar 16 13:08:41 volumio systemd[1]: Starting Music Player Daemon... Mar 16 13:08:41 volumio sudo[952]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 16 13:08:41 volumio sudo[952]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:41 volumio volumio[625]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 13:08:42 volumio sudo[952]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:42 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:42 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 13:08:42 volumio volumio[625]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 13:08:42 volumio volumio[625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 13:08:42 volumio volumio[625]: info: [1742126922752] CoreMusicLibrary::Adding element Last_100 Mar 16 13:08:42 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 13:08:42 volumio volumio[625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 13:08:42 volumio volumio[625]: info: [1742126922839] CoreMusicLibrary::Adding element Webradio Mar 16 13:08:42 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 13:08:42 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 13:08:43 volumio volumio[625]: info: Initializing BBC Radios Mar 16 13:08:43 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 13:08:43 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 13:08:44 volumio volumio[625]: info: Creating Spotify config file Mar 16 13:08:44 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:46 volumio volumio[625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 13:08:46 volumio volumio[625]: info: [1742126926179] CoreMusicLibrary::Adding element YouTube2 Mar 16 13:08:46 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 13:08:46 volumio volumio[625]: Cannot find translation for source YouTube2 Mar 16 13:08:46 volumio volumio[625]: info: Volumio Calling Home Mar 16 13:08:47 volumio volumio[625]: info: Discovery: adding 1d42d3a0-2092-44a1-9392-37992abd0b2a Mar 16 13:08:47 volumio volumio[625]: info: Discovery: Found device Volumio Mar 16 13:08:47 volumio volumio[625]: info: CoreCommandRouter::volumioGetState Mar 16 13:08:47 volumio volumio[625]: info: CorePlayQueue::getTrack 0 Mar 16 13:08:48 volumio sudo[997]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Markus,password=%Pass4Me$,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.3/Musik /mnt/NAS/Musik Mar 16 13:08:48 volumio sudo[997]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:48 volumio kernel: CIFS: Attempting to mount //192.168.0.3/Musik Mar 16 13:08:48 volumio kernel: CIFS: Status code returned 0xc000006d STATUS_LOGON_FAILURE Mar 16 13:08:48 volumio kernel: CIFS: VFS: \\192.168.0.3 Send error in SessSetup = -13 Mar 16 13:08:48 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -13 Mar 16 13:08:48 volumio sudo[997]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:48 volumio volumio[625]: info: MPD Permissions set Mar 16 13:08:48 volumio volumio[625]: info: Upmpdcli Daemon Started Mar 16 13:08:48 volumio volumio[625]: info: CoreCommandRouter::volumioGetState Mar 16 13:08:48 volumio volumio[625]: info: CorePlayQueue::getTrack 0 Mar 16 13:08:49 volumio volumio[625]: info: Cannot mount NAS Musik at system boot, trial number 2 ,retrying in 5 seconds Mar 16 13:08:49 volumio volumio[625]: info: Volumio called home Mar 16 13:08:49 volumio volumio[625]: info: Spotify config file written Mar 16 13:08:49 volumio sudo[1004]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 16 13:08:49 volumio sudo[1004]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:49 volumio volumio[625]: error: error Mar 16 13:08:49 volumio systemd[1]: Started go-librespot Daemon. Mar 16 13:08:49 volumio go-librespot[1008]: Librespot-go daemon starting... Mar 16 13:08:50 volumio sudo[1004]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:50 volumio volumio[625]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 16 13:08:50 volumio volumio[625]: info: VolumeController:: Volume=62 Mute =false Mar 16 13:08:50 volumio volumio[625]: info: CoreStateMachine::pushState Mar 16 13:08:50 volumio volumio[625]: info: CorePlayQueue::getTrack 0 Mar 16 13:08:50 volumio volumio[625]: info: CoreCommandRouter::volumioPushState Mar 16 13:08:50 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:50 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:50 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:50 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 13:08:50 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:50 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:50 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:50 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:50 volumio go-librespot[1008]: time="2025-03-16T13:08:50+01:00" level=info msg="generated new device id: 13afb42695262b53478ea2c7507588d3cf6ec9c5" Mar 16 13:08:50 volumio go-librespot[1008]: time="2025-03-16T13:08:50+01:00" level=debug msg="stored credentials found for 1191146862" Mar 16 13:08:50 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 13:08:50 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 13:08:50 volumio volumio[625]: info: Listing playlists Mar 16 13:08:50 volumio volumio[625]: info: Listing playlists Mar 16 13:08:51 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Mar 16 13:08:51 volumio systemd[1]: mpd.service: Failed with result 'protocol'. Mar 16 13:08:51 volumio systemd[1]: Failed to start Music Player Daemon. Mar 16 13:08:51 volumio sudo[933]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:51 volumio sudo[947]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:52 volumio systemd[1]: Starting Music Player Daemon... Mar 16 13:08:53 volumio sudo[1024]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 16 13:08:53 volumio sudo[1024]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:53 volumio volumio-remote-updater[376]: [2025-03-16 13:08:53] [connect] Successful connection Mar 16 13:08:53 volumio volumio[625]: error: Cannot start MPD on system Start: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service Mar 16 13:08:53 volumio volumio[625]: Job for mpd.service failed because the service did not take the steps required by its unit configuration. Mar 16 13:08:53 volumio volumio[625]: See "systemctl status mpd.service" and "journalctl -xe" for details. Mar 16 13:08:53 volumio volumio[625]: info: Completed starting Core Plugins Mar 16 13:08:53 volumio volumio[625]: info: ------------------------------------------- Mar 16 13:08:53 volumio sudo[1024]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:53 volumio volumio[625]: info: ----- MyVolumio plugins startup ---- Mar 16 13:08:53 volumio volumio[625]: info: ------------------------------------------- Mar 16 13:08:53 volumio volumio[625]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 16 13:08:53 volumio volumio[625]: info: Cannot restart MPD: Error: Command failed: /usr/bin/sudo /bin/systemctl restart mpd.service Mar 16 13:08:53 volumio volumio[625]: Job for mpd.service failed because the service did not take the steps required by its unit configuration. Mar 16 13:08:53 volumio volumio[625]: See "systemctl status mpd.service" and "journalctl -xe" for details. Mar 16 13:08:53 volumio volumio[625]: info: Starting Shairport Sync Mar 16 13:08:53 volumio volumio[625]: info: Starting Shairport Sync Mar 16 13:08:53 volumio volumio[625]: info: Starting Shairport Sync Mar 16 13:08:54 volumio go-librespot[1008]: time="2025-03-16T13:08:54+01:00" level=debug msg="obtained new client token: AACtd62KM0flQMJwwyXaht4BKRWB7SbjWD/x2Z7asGw/5Z1/SBIg+GTW5Ol8dkRZjcBC2BGgZqwksZWIrEV4zai3e6/NrxgbpVAxmMFem/t7qvLpS/JhC7oF01TOQXp88sPZw0Wwmh+fXEubvJP6W6hlLfbIvkvTu3gccYsGmYsy/CEAEYxdQBm878FbEDMTF83kFmc8ZriENSYp1JWVaZO5SX7dvHhejjLhVN8NEfIg3V2lJU3SRFMdyqyPsQ==" Mar 16 13:08:54 volumio sudo[1029]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 16 13:08:54 volumio sudo[1029]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:54 volumio sudo[1031]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 16 13:08:54 volumio go-librespot[1008]: time="2025-03-16T13:08:54+01: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]" Mar 16 13:08:54 volumio sudo[1031]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:54 volumio volumio[625]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 16 13:08:54 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 16 13:08:54 volumio systemd[1]: shairport-sync.service: Succeeded. Mar 16 13:08:54 volumio volumio[625]: SPOTIFY: BQCo0A0ja7ITa33fFm8nNHcuUxgRKt0W88y0uWvC_NpRIL0LRcqghbh2Vc0my_OFSTf0_3ueg7H9K0oDSsxxo6L1bWuPiGsZKVekstzk_Hslx70K7mPbTHC6lfmgUVAUWo72mjxFvsZqIREsbzi2OaSk318-GR7ftXfD9nwJf4yVgRXtAd8X-4yyYArMowV_1IyKG53KeIqek64QCzHO0ynUTeY77zxS3g1QRhyEx0Kv_W1qPpzBPhxccNXs5Tzi-lBXhEsiD-j_6i1fgWk Mar 16 13:08:54 volumio volumio[625]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 16 13:08:54 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 16 13:08:54 volumio volumio[625]: info: New Spotify access token = BQCo0A0ja7ITa33fFm8nNHcuUxgRKt0W88y0uWvC_NpRIL0LRcqghbh2Vc0my_OFSTf0_3ueg7H9K0oDSsxxo6L1bWuPiGsZKVekstzk_Hslx70K7mPbTHC6lfmgUVAUWo72mjxFvsZqIREsbzi2OaSk318-GR7ftXfD9nwJf4yVgRXtAd8X-4yyYArMowV_1IyKG53KeIqek64QCzHO0ynUTeY77zxS3g1QRhyEx0Kv_W1qPpzBPhxccNXs5Tzi-lBXhEsiD-j_6i1fgWk Mar 16 13:08:54 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 16 13:08:54 volumio volumio[625]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 16 13:08:54 volumio go-librespot[1008]: time="2025-03-16T13:08:54+01:00" level=debug msg="completed keyexchange" Mar 16 13:08:55 volumio sudo[1029]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:55 volumio sudo[1034]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 16 13:08:55 volumio sudo[1034]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:55 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 16 13:08:55 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Mar 16 13:08:55 volumio systemd[1]: shairport-sync.service: Succeeded. Mar 16 13:08:55 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 16 13:08:55 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 16 13:08:55 volumio sudo[1031]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:55 volumio go-librespot[1008]: time="2025-03-16T13:08:55+01:00" level=debug msg="completed challenge" Mar 16 13:08:55 volumio go-librespot[1008]: time="2025-03-16T13:08:55+01:00" level=debug msg="authenticated as 1191146862" Mar 16 13:08:55 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 16 13:08:55 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Mar 16 13:08:55 volumio volumio[625]: info: CoreCommandRouter::volumioGetState Mar 16 13:08:55 volumio volumio[625]: info: CorePlayQueue::getTrack 0 Mar 16 13:08:55 volumio systemd[1]: shairport-sync.service: Succeeded. Mar 16 13:08:55 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 16 13:08:55 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 16 13:08:56 volumio sudo[1034]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:56 volumio go-librespot[1008]: time="2025-03-16T13:08:56+01:00" level=debug msg="authenticated as 1191146862" Mar 16 13:08:56 volumio go-librespot[1008]: time="2025-03-16T13:08:56+01: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]" Mar 16 13:08:56 volumio volumio-remote-updater[376]: [2025-03-16 13:08:56] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1742126933 101 Mar 16 13:08:56 volumio go-librespot[1008]: time="2025-03-16T13:08:56+01: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]" Mar 16 13:08:56 volumio volumio[625]: 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: 2 Mar 16 13:08:56 volumio go-librespot[1008]: time="2025-03-16T13:08:56+01:00" level=debug msg="dealer connection opened" Mar 16 13:08:56 volumio go-librespot[1008]: time="2025-03-16T13:08:56+01:00" level=debug msg="received connection id: ODgxZWZjMDUtODI3Mi00ODg1LThmOTYtMThhMTRhOWZlNjc4K2RlYWxlcit0Y3A6Ly8wYWNhNTk5NC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQUVDOEU4NzU4RDA2QTk4RUIyOTY1NjRGRjQ2M0U2NzU4NjNFNUJCNTRFRkI3QTEyMkE4NjYzMEMyNTc2QTc5RQ==" Mar 16 13:08:56 volumio go-librespot[1008]: time="2025-03-16T13:08:56+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 16 13:08:56 volumio go-librespot[1008]: time="2025-03-16T13:08:56+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 16 13:08:57 volumio volumio[625]: info: go-librespot daemon successfully initialized Mar 16 13:08:57 volumio go-librespot[1008]: time="2025-03-16T13:08:57+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 16 13:08:57 volumio go-librespot[1008]: time="2025-03-16T13:08:57+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 16 13:08:57 volumio go-librespot[1008]: time="2025-03-16T13:08:57+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 16 13:08:57 volumio go-librespot[1008]: time="2025-03-16T13:08:57+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 16 13:08:57 volumio sudo[1057]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Markus,password=%Pass4Me$,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.3/Musik /mnt/NAS/Musik Mar 16 13:08:57 volumio sudo[1057]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:08:57 volumio kernel: CIFS: Attempting to mount //192.168.0.3/Musik Mar 16 13:08:57 volumio volumio[625]: info: Shairport-Sync Started Mar 16 13:08:57 volumio volumio[625]: Error adding Membership: Error: addMembership EINVAL Mar 16 13:08:57 volumio volumio[625]: info: Shairport-Sync Started Mar 16 13:08:57 volumio volumio[625]: info: Shairport-Sync Started Mar 16 13:08:57 volumio volumio[625]: info: CoreCommandRouter::volumioGetState Mar 16 13:08:57 volumio volumio[625]: info: CorePlayQueue::getTrack 0 Mar 16 13:08:57 volumio kernel: CIFS: Status code returned 0xc000006d STATUS_LOGON_FAILURE Mar 16 13:08:57 volumio kernel: CIFS: VFS: \\192.168.0.3 Send error in SessSetup = -13 Mar 16 13:08:57 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -13 Mar 16 13:08:57 volumio sudo[1057]: pam_unix(sudo:session): session closed for user root Mar 16 13:08:57 volumio volumio[625]: info: Cannot mount NAS Musik at system boot, trial number 3 ,retrying in 5 seconds Mar 16 13:08:58 volumio volumio[625]: SPOTIFY: User informations: {"country":"CH","display_name":"Markus Hediger","email":"randirvithren@gmx.ch","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/1191146862"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/1191146862","id":"1191146862","images":[{"height":300,"url":"https://scontent-arn2-1.xx.fbcdn.net/v/t1.6435-1/68835626_10219495630045726_5533727793646403584_n.jpg?stp=dst-jpg_s320x320_tt6&_nc_cat=101&ccb=1-7&_nc_sid=79bf43&_nc_ohc=PH_FMO2cQ7IQ7kNvgHCDJzw&_nc_oc=AdjIkOva0bfpENZuqa_NLPXwJ_PkCp8Pyf5L-QEPDvhG2Lw1oEujtEL14-x__vayDyf-XQpdjvhE_wEoV_hU8-XZ&_nc_zt=24&_nc_ht=scontent-arn2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=hBXJW3J9tqbBrLqn4Swpew&oh=00_AYH3_ohibu06T5a3vE8JkW1XzayRRyMrKO8xkQEs1eUr0Q&oe=67FE1166","width":300},{"height":64,"url":"https://scontent-arn2-1.xx.fbcdn.net/v/t1.6435-1/68835626_10219495630045726_5533727793646403584_n.jpg?stp=cp0_dst-jpg_s50x50_tt6&_nc_cat=101&ccb=1-7&_nc_sid=fe756c&_nc_ohc=PH_FMO2cQ7IQ7kNvgHCDJzw&_nc_oc=AdjIkOva0bfpENZuqa_NLPXwJ_PkCp8Pyf5L-QEPDvhG2Lw1oEujtEL14-x__vayDyf-XQpdjvhE_wEoV_hU8-XZ&_nc_zt=24&_nc_ht=scontent-arn2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=hBXJW3J9tqbBrLqn4Swpew&oh=00_AYFlTLyWvBT38IrlH4ht1KKQLp2A0Q2GKzfu5BRLFyJnqQ&oe=67FE1166","width":64}],"product":"premium","type":"user","uri":"spotify:user:1191146862"} Mar 16 13:08:58 volumio volumio[625]: info: Spotify Successfully logged in Mar 16 13:08:58 volumio volumio[625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 13:08:58 volumio volumio[625]: info: [1742126938303] CoreMusicLibrary::Adding element Spotify Mar 16 13:08:58 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 13:08:58 volumio volumio[625]: Cannot find translation for source YouTube2 Mar 16 13:08:58 volumio volumio[625]: Cannot find translation for source Spotify Mar 16 13:09:00 volumio volumio[625]: info: Initializing connection to go-librespot Websocket Mar 16 13:09:00 volumio go-librespot[1008]: time="2025-03-16T13:09:00+01:00" level=debug msg="new websocket client" Mar 16 13:09:00 volumio volumio[625]: info: Connection to go-librespot Websocket established Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Mar 16 13:09:02 volumio volumio[625]: info: Adding plugin bluetooth to MyMusic Plugins Mar 16 13:09:02 volumio volumio[625]: info: Adding plugin multiroom to MyMusic Plugins Mar 16 13:09:02 volumio volumio[625]: info: Adding plugin metavolumio to MyMusic Plugins Mar 16 13:09:02 volumio volumio[625]: info: Adding plugin cd_controller to MyMusic Plugins Mar 16 13:09:02 volumio volumio[625]: info: Adding plugin smart_inputs to MyMusic Plugins Mar 16 13:09:02 volumio volumio[625]: info: Adding plugin tidalconnect to MyMusic Plugins Mar 16 13:09:02 volumio volumio[625]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Mar 16 13:09:04 volumio go-librespot[1008]: time="2025-03-16T13:09:04+01:00" level=debug msg="handling transfer player command from ffbd9c8d7f95f553c903c4811bf4c88fdaa70cd5" Mar 16 13:09:04 volumio go-librespot[1008]: time="2025-03-16T13:09:04+01:00" level=trace msg="fetched new page 0 with 47 items (list: 47)" Mar 16 13:09:04 volumio go-librespot[1008]: time="2025-03-16T13:09:04+01:00" level=debug msg="loading track spotify:track:0dqlfHKr9Xdq5GmPuMpfTP (paused: true, position: 42332ms)" Mar 16 13:09:04 volumio go-librespot[1008]: time="2025-03-16T13:09:04+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 16 13:09:04 volumio go-librespot[1008]: time="2025-03-16T13:09:04+01:00" level=trace msg="emitting websocket event: will_play" Mar 16 13:09:04 volumio go-librespot[1008]: time="2025-03-16T13:09:04+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Mar 16 13:09:04 volumio go-librespot[1008]: time="2025-03-16T13:09:04+01:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:0dqlfHKr9Xdq5GmPuMpfTP" Mar 16 13:09:04 volumio go-librespot[1008]: time="2025-03-16T13:09:04+01:00" level=debug msg="requested aes key for file e4bd6369f3eb2a12aedf7a2ffb6e0554f24c75d9, gid: 0dqlfHKr9Xdq5GmPuMpfTP" Mar 16 13:09:05 volumio go-librespot[1008]: time="2025-03-16T13:09:05+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3176" Mar 16 13:09:05 volumio go-librespot[1008]: time="2025-03-16T13:09:05+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2032" Mar 16 13:09:06 volumio go-librespot[1008]: time="2025-03-16T13:09:06+01:00" level=debug msg="fetched first chunk of 12, total size is 6099312 bytes" Mar 16 13:09:08 volumio mpd[1027]: Mar 16 13:09 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 16 13:09:09 volumio systemd[1]: Started Music Player Daemon. Mar 16 13:09:09 volumio mpd_monitor.sh[352]: MPD restarted due to no mpc output. Mar 16 13:09:10 volumio go-librespot[1008]: time="2025-03-16T13:09:10+01:00" level=debug msg="fetched chunk 3/11, size: 524288" Mar 16 13:09:11 volumio go-librespot[1008]: time="2025-03-16T13:09:11+01:00" level=trace msg="seek to 42332ms (diff: 184ms, samples: 1866841, bytes: 1897871)" Mar 16 13:09:11 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Mar 16 13:09:11 volumio go-librespot[1008]: time="2025-03-16T13:09:11+01:00" level=info msg="loaded track \"Darf ich mitspielen?\" (uri: spotify:track:0dqlfHKr9Xdq5GmPuMpfTP, paused: true, position: 42332ms, duration: 134739ms)" Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=debug msg="fetched chunk 5/11, size: 524288" Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=debug msg="fetched chunk 2/11, size: 524288" Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=trace msg="emitting websocket event: metadata" Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=trace msg="emitting websocket event: active" Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=debug msg="sending successful reply for delaer request" Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=debug msg="fetched chunk 6/11, size: 524288" Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=debug msg="fetched chunk 1/11, size: 524288" Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=trace msg="emitting websocket event: paused" Mar 16 13:09:12 volumio go-librespot[1008]: time="2025-03-16T13:09:12+01:00" level=debug msg="fetched chunk 4/11, size: 524288" Mar 16 13:09:14 volumio volumio[625]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Mar 16 13:09:14 volumio volumio[625]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Mar 16 13:09:14 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 13:09:14 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 13:09:14 volumio volumio[625]: info: Starting MyVolumio Remote Streaming Endpoints Mar 16 13:09:15 volumio volumio[625]: info: MyVolumio login type: Token Mar 16 13:09:15 volumio volumio[625]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Mar 16 13:09:15 volumio volumio[625]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Mar 16 13:09:20 volumio volumio[625]: info: Starting Streaming Service Transparent Proxy Mar 16 13:09:20 volumio volumio[625]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Mar 16 13:09:20 volumio volumio[625]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Mar 16 13:09:20 volumio volumio[625]: info: Streaming services startup Mar 16 13:09:20 volumio volumio[625]: info: Starting Streaming Daemon Mar 16 13:09:20 volumio sudo[1142]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 16 13:09:20 volumio sudo[1142]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:09:20 volumio volumio[625]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Mar 16 13:09:21 volumio sudo[1142]: pam_unix(sudo:session): session closed for user root Mar 16 13:09:21 volumio sudo[1150]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Markus,password=%Pass4Me$,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.3/Musik /mnt/NAS/Musik Mar 16 13:09:21 volumio sudo[1150]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:09:21 volumio volumio[625]: info: Getting Spotify volume Mar 16 13:09:21 volumio kernel: CIFS: Attempting to mount //192.168.0.3/Musik Mar 16 13:09:21 volumio kernel: CIFS: Status code returned 0xc000006d STATUS_LOGON_FAILURE Mar 16 13:09:21 volumio kernel: CIFS: VFS: \\192.168.0.3 Send error in SessSetup = -13 Mar 16 13:09:21 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -13 Mar 16 13:09:21 volumio sudo[1150]: pam_unix(sudo:session): session closed for user root Mar 16 13:09:22 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 13:09:22 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 13:09:22 volumio volumio[625]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 16 13:09:22 volumio volumio[625]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0dqlfHKr9Xdq5GmPuMpfTP","play_origin":"com.spotify.service.carplayv2"}} Mar 16 13:09:22 volumio volumio[625]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0dqlfHKr9Xdq5GmPuMpfTP","name":"Darf ich mitspielen?","artist_names":["Hurra Kinderlieder"],"album_name":"Darf ich mitspielen?","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a12d5299437fc2d96687e15f","position":42332,"duration":134739,"release_date":"year:2021 month:4 day:9","track_number":1,"disc_number":1}} Mar 16 13:09:22 volumio volumio[625]: SPOTIFY: received: {"type":"active","data":null} Mar 16 13:09:22 volumio volumio[625]: info: Aligning Spotify Volume to Volumio Volume Mar 16 13:09:22 volumio volumio[625]: info: CoreCommandRouter::volumioGetState Mar 16 13:09:22 volumio volumio[625]: info: CorePlayQueue::getTrack 0 Mar 16 13:09:22 volumio volumio[625]: info: Setting Spotify Volume from Volumio: 62 Mar 16 13:09:22 volumio volumio[625]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0dqlfHKr9Xdq5GmPuMpfTP","play_origin":"com.spotify.service.carplayv2"}} Mar 16 13:09:22 volumio volumio[625]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 13:09:22 volumio volumio[625]: TypeError: Cannot read property 'service' of undefined Mar 16 13:09:22 volumio volumio[625]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Mar 16 13:09:22 volumio volumio[625]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Mar 16 13:09:22 volumio volumio[625]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Mar 16 13:09:22 volumio volumio[625]: at WebSocket.emit (events.js:315:20) Mar 16 13:09:22 volumio volumio[625]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Mar 16 13:09:22 volumio volumio[625]: at Receiver.emit (events.js:315:20) Mar 16 13:09:22 volumio volumio[625]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Mar 16 13:09:22 volumio volumio[625]: at internal/process/task_queues.js:149:7 Mar 16 13:09:22 volumio volumio[625]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Mar 16 13:09:22 volumio volumio[625]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Mar 16 13:09:22 volumio volumio[625]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Mar 16 13:09:22 volumio volumio[625]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 13:09:24 volumio go-librespot[1008]: time="2025-03-16T13:09:24+01:00" level=debug msg="handling resume player command from ffbd9c8d7f95f553c903c4811bf4c88fdaa70cd5" Mar 16 13:09:24 volumio go-librespot[1008]: time="2025-03-16T13:09:24+01:00" level=trace msg="seek to 42332ms (diff: 184ms, samples: 1866841, bytes: 1897871)" Mar 16 13:09:24 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Mar 16 13:09:24 volumio go-librespot[1008]: time="2025-03-16T13:09:24+01:00" level=debug msg="resume track at 42148ms" Mar 16 13:09:25 volumio go-librespot[1008]: time="2025-03-16T13:09:25+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 16 13:09:25 volumio go-librespot[1008]: time="2025-03-16T13:09:25+01:00" level=debug msg="sending successful reply for delaer request" Mar 16 13:09:25 volumio go-librespot[1008]: time="2025-03-16T13:09:25+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 16 13:09:25 volumio go-librespot[1008]: time="2025-03-16T13:09:25+01:00" level=trace msg="emitting websocket event: playing" Mar 16 13:09:26 volumio volumio-remote-updater[376]: [2025-03-16 13:09:26] [disconnect] Disconnect close local:[1008,Pong timeout] remote:[1006] Mar 16 13:09:27 volumio shairport-sync[1041]: % Total % Received % Xferd Average Speed Time Time Time Current Mar 16 13:09:27 volumio shairport-sync[1041]: Dload Upload Total Spent Left Speed Mar 16 13:09:29 volumio go-librespot[1008]: time="2025-03-16T13:09:29+01:00" level=debug msg="update volume to 63002/65535" Mar 16 13:09:29 volumio go-librespot[1008]: time="2025-03-16T13:09:29+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 16 13:09:29 volumio go-librespot[1008]: time="2025-03-16T13:09:29+01:00" level=trace msg="emitting websocket event: volume" Mar 16 13:09:29 volumio go-librespot[1008]: time="2025-03-16T13:09:29+01:00" level=debug msg="update volume to 32122/65535" Mar 16 13:09:29 volumio go-librespot[1008]: time="2025-03-16T13:09:29+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 16 13:09:29 volumio go-librespot[1008]: time="2025-03-16T13:09:29+01:00" level=trace msg="emitting websocket event: volume" Mar 16 13:09:29 volumio go-librespot[1008]: time="2025-03-16T13:09:29+01:00" level=debug msg="update volume to 24972/65535" Mar 16 13:09:30 volumio go-librespot[1008]: time="2025-03-16T13:09:30+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 16 13:09:30 volumio go-librespot[1008]: time="2025-03-16T13:09:30+01:00" level=trace msg="emitting websocket event: volume" Mar 16 13:09:30 volumio go-librespot[1008]: time="2025-03-16T13:09:30+01:00" level=debug msg="fetched chunk 7/11, size: 524288" Mar 16 13:09:31 volumio volumio-remote-updater[376]: [2025-03-16 13:09:31] [connect] Successful connection Mar 16 13:09:31 volumio go-librespot[1008]: time="2025-03-16T13:09:31+01:00" level=debug msg="update volume to 25072/65535" Mar 16 13:09:31 volumio go-librespot[1008]: time="2025-03-16T13:09:31+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 16 13:09:31 volumio go-librespot[1008]: time="2025-03-16T13:09:31+01:00" level=trace msg="emitting websocket event: volume" Mar 16 13:09:31 volumio go-librespot[1008]: time="2025-03-16T13:09:31+01:00" level=debug msg="update volume to 35299/65535" Mar 16 13:09:32 volumio go-librespot[1008]: time="2025-03-16T13:09:32+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 16 13:09:32 volumio go-librespot[1008]: time="2025-03-16T13:09:32+01:00" level=trace msg="emitting websocket event: volume" Mar 16 13:09:32 volumio go-librespot[1008]: time="2025-03-16T13:09:32+01:00" level=debug msg="update volume to 35398/65535" Mar 16 13:09:32 volumio go-librespot[1008]: time="2025-03-16T13:09:32+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 16 13:09:32 volumio go-librespot[1008]: time="2025-03-16T13:09:32+01:00" level=trace msg="emitting websocket event: volume" Mar 16 13:09:32 volumio go-librespot[1008]: time="2025-03-16T13:09:32+01:00" level=debug msg="update volume to 35796/65535" Mar 16 13:09:32 volumio go-librespot[1008]: time="2025-03-16T13:09:32+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 16 13:09:32 volumio go-librespot[1008]: time="2025-03-16T13:09:32+01:00" level=trace msg="emitting websocket event: volume" Mar 16 13:09:32 volumio go-librespot[1008]: time="2025-03-16T13:09:32+01:00" level=debug msg="update volume to 41753/65535" Mar 16 13:09:32 volumio sudo[1192]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-16 13:08 Mar 16 13:09:32 volumio sudo[1192]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 13:09:32 volumio go-librespot[1008]: time="2025-03-16T13:09:32+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 16 13:09:32 volumio go-librespot[1008]: time="2025-03-16T13:09:32+01:00" level=trace msg="emitting websocket event: volume" Mar 16 13:09:32 volumio go-librespot[1008]: time="2025-03-16T13:09:32+01:00" level=debug msg="update volume to 42150/65535" Mar 16 13:09:33 volumio go-librespot[1008]: time="2025-03-16T13:09:33+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 16 13:09:33 volumio go-librespot[1008]: time="2025-03-16T13:09:33+01:00" level=trace msg="emitting websocket event: volume" PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"