-- Logs begin at Wed 2024-11-20 18:17:27 UTC, end at Sat 2024-11-30 08:20:37 UTC. -- Nov 30 08:20:08 musecume systemd-timedated[898]: Changed local time to Sat Nov 30 08:20:08 2024 Nov 30 08:20:08 musecume sudo[896]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:08 musecume volumio-time-update[507]: volumio-time-update-util: System time updated successfully. Nov 30 08:20:08 musecume systemd[1]: Starting Daily apt download activities... Nov 30 08:20:08 musecume systemd[1]: Started Volumio Time Update Utility. Nov 30 08:20:08 musecume systemd[1]: Reached target Multi-User System. Nov 30 08:20:08 musecume systemd[1]: Reached target Graphical Interface. Nov 30 08:20:08 musecume systemd[1]: Starting Update UTMP about System Runlevel Changes... Nov 30 08:20:08 musecume systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Nov 30 08:20:08 musecume systemd[1]: Started Update UTMP about System Runlevel Changes. Nov 30 08:20:09 musecume volumio-remote-updater[492]: [2024-11-30 08:20:09] [connect] Successful connection Nov 30 08:20:10 musecume volumio[792]: info: MYVOLUMIO Environment detected Nov 30 08:20:10 musecume volumio[792]: info: Plugin folders cleanup Nov 30 08:20:10 musecume volumio[792]: info: Scanning into folder /volumio/app/plugins/ Nov 30 08:20:10 musecume volumio[792]: info: Scanning category audio_interface Nov 30 08:20:10 musecume volumio[792]: info: Scanning category miscellanea Nov 30 08:20:10 musecume volumio[792]: info: Scanning category music_service Nov 30 08:20:10 musecume volumio[792]: info: Scanning category plugins.json Nov 30 08:20:10 musecume volumio[792]: info: Scanning category system_controller Nov 30 08:20:10 musecume volumio[792]: info: Scanning category user_interface Nov 30 08:20:10 musecume volumio[792]: info: Scanning into folder /data/plugins/ Nov 30 08:20:10 musecume volumio[792]: info: Scanning category audio_interface Nov 30 08:20:10 musecume volumio[792]: info: Scanning category music_service Nov 30 08:20:10 musecume volumio[792]: info: Plugin folders cleanup completed Nov 30 08:20:10 musecume volumio[792]: info: ------------------------------------------- Nov 30 08:20:10 musecume volumio[792]: info: ----- Core plugins startup ---- Nov 30 08:20:10 musecume volumio[792]: info: ------------------------------------------- Nov 30 08:20:10 musecume volumio[792]: info: Loading plugins from folder /volumio/app/plugins/ Nov 30 08:20:10 musecume volumio[792]: info: Adding plugin upnp to MyMusic Plugins Nov 30 08:20:10 musecume volumio[792]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 30 08:20:10 musecume volumio[792]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 30 08:20:10 musecume volumio[792]: info: Loading plugins from folder /data/plugins/ Nov 30 08:20:10 musecume volumio[792]: info: Loading plugin "system"... Nov 30 08:20:10 musecume volumio[792]: info: Loading plugin "appearance"... Nov 30 08:20:13 musecume systemd[1]: apt-daily.service: Succeeded. Nov 30 08:20:13 musecume systemd[1]: Started Daily apt download activities. Nov 30 08:20:13 musecume systemd[1]: Starting Daily apt upgrade and clean activities... Nov 30 08:20:13 musecume volumio[792]: info: Loading plugin "network"... Nov 30 08:20:13 musecume volumio[792]: info: Refreshing Cached IP Addresses Nov 30 08:20:13 musecume sudo[970]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 30 08:20:13 musecume sudo[970]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:13 musecume sudo[973]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 30 08:20:13 musecume volumio[792]: info: Loading plugin "services"... Nov 30 08:20:13 musecume sudo[970]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:13 musecume sudo[973]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:13 musecume volumio[792]: info: Loading plugin "alsa_controller"... Nov 30 08:20:13 musecume sudo[973]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:13 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 30 08:20:13 musecume volumio[792]: info: Loading plugin "wizard"... Nov 30 08:20:13 musecume volumio[792]: info: Loading plugin "networkfs"... Nov 30 08:20:14 musecume volumio[792]: info: Starting Udev Watcher for removable devices Nov 30 08:20:14 musecume sudo[1000]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.254/Elements /mnt/NAS/Elements Nov 30 08:20:14 musecume sudo[1000]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:14 musecume volumio[792]: info: Ignoring mount for partition: boot Nov 30 08:20:14 musecume volumio[792]: info: Ignoring mount for partition: volumio Nov 30 08:20:14 musecume volumio[792]: info: Ignoring mount for partition: volumio_data Nov 30 08:20:14 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 30 08:20:14 musecume volumio[792]: info: Loading plugin "volumio_command_line_client"... Nov 30 08:20:14 musecume volumio[792]: info: Loading plugin "upnp"... Nov 30 08:20:14 musecume volumio[792]: info: [1732954814122] Starting Upmpd Daemon Nov 30 08:20:14 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 30 08:20:14 musecume volumio[792]: info: Loading plugin "my_music"... Nov 30 08:20:14 musecume volumio[792]: info: Loading plugin "mpd"... Nov 30 08:20:14 musecume kernel: Key type cifs.spnego registered Nov 30 08:20:14 musecume kernel: Key type cifs.idmap registered Nov 30 08:20:14 musecume 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. Nov 30 08:20:14 musecume kernel: CIFS: Attempting to mount //192.168.0.254/Elements Nov 30 08:20:14 musecume kernel: CIFS: VFS: BAD_NETWORK_NAME: \\192.168.0.254\Elements Nov 30 08:20:14 musecume kernel: CIFS: VFS: cifs_mount failed w/return code = -2 Nov 30 08:20:14 musecume sudo[1000]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:15 musecume volumio[792]: info: Loading plugin "upnp_browser"... Nov 30 08:20:15 musecume volumio[792]: info: Loading plugin "alarm-clock"... Nov 30 08:20:16 musecume volumio[792]: info: Loading plugin "airplay_emulation"... Nov 30 08:20:16 musecume volumio[792]: info: Starting Shairport Sync Nov 30 08:20:16 musecume volumio[792]: info: Loading plugin "last_100"... Nov 30 08:20:16 musecume volumio[792]: info: Loading plugin "webradio"... Nov 30 08:20:16 musecume systemd[1]: apt-daily-upgrade.service: Succeeded. Nov 30 08:20:16 musecume systemd[1]: Started Daily apt upgrade and clean activities. Nov 30 08:20:16 musecume systemd[1]: Startup finished in 15.758s (kernel) + 29.094s (userspace) = 44.853s. Nov 30 08:20:16 musecume volumio[792]: info: Loading plugin "i2s_dacs"... Nov 30 08:20:16 musecume volumio[792]: info: I2S DAC not set, start Auto-detection Nov 30 08:20:16 musecume volumio[792]: info: Loading plugin "volumiodiscovery"... Nov 30 08:20:16 musecume volumio[792]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 30 08:20:16 musecume volumio[792]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 30 08:20:16 musecume volumio[792]: *** WARNING *** For more information see Nov 30 08:20:16 musecume volumio[792]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 30 08:20:16 musecume node[792]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 30 08:20:16 musecume volumio[792]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 30 08:20:16 musecume volumio[792]: *** WARNING *** For more information see Nov 30 08:20:16 musecume node[792]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 30 08:20:16 musecume node[792]: *** WARNING *** For more information see Nov 30 08:20:16 musecume node[792]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 30 08:20:16 musecume node[792]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 30 08:20:16 musecume node[792]: *** WARNING *** For more information see Nov 30 08:20:16 musecume volumio[792]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 30 08:20:16 musecume volumio[792]: info: Discovery: Started advertising with name: Musecume Nov 30 08:20:17 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 30 08:20:17 musecume volumio[792]: info: Plugin soundcloud is not enabled Nov 30 08:20:17 musecume volumio[792]: info: Loading plugin "spop"... Nov 30 08:20:19 musecume volumio[792]: info: Loading plugin "ytcr"... Nov 30 08:20:22 musecume systemd[1]: systemd-fsckd.service: Succeeded. Nov 30 08:20:23 musecume volumio[792]: info: Loading plugin "outputs"... Nov 30 08:20:23 musecume volumio[792]: info: Loading plugin "albumart"... Nov 30 08:20:23 musecume volumio[792]: info: Plugin example_plugin is not enabled Nov 30 08:20:23 musecume volumio[792]: info: Loading plugin "inputs"... Nov 30 08:20:23 musecume volumio[792]: info: Loading plugin "updater_comm"... Nov 30 08:20:23 musecume volumio[792]: info: Plugin mpdemulation is not enabled Nov 30 08:20:23 musecume volumio[792]: info: Loading plugin "rest_api"... Nov 30 08:20:23 musecume volumio[792]: info: Loading plugin "websocket"... Nov 30 08:20:23 musecume volumio[792]: info: Starting Socket.io Server version 2.3.0 Nov 30 08:20:23 musecume volumio[792]: info: Plugin fusiondsp is not enabled Nov 30 08:20:23 musecume volumio[792]: info: Loading i18n strings for locale fr Nov 30 08:20:23 musecume volumio[792]: Updating browse sources language Nov 30 08:20:23 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 30 08:20:24 musecume volumio[792]: Forking 3 albumart workers Nov 30 08:20:24 musecume volumio-remote-updater[492]: [2024-11-30 08:20:24] [connect] Successful connection Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::initPlayerControls Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 30 08:20:24 musecume volumio[792]: Express server listening on port 3000 Nov 30 08:20:24 musecume volumio[792]: [Metrics] WebUI: 18s 883.21ms Nov 30 08:20:24 musecume volumio[792]: info: CoreStateMachine::resetVolumioState Nov 30 08:20:24 musecume volumio[792]: info: CoreStateMachine::getcurrentVolume Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::volumioRetrievevolume Nov 30 08:20:24 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 30 08:20:24 musecume sudo[1112]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 30 08:20:24 musecume sudo[1112]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:24 musecume sudo[1112]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:24 musecume sudo[1114]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 30 08:20:24 musecume sudo[1114]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:24 musecume sudo[1114]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:24 musecume volumio[792]: info: Volumio Network Manager: Network status updated: 1 Nov 30 08:20:24 musecume volumio[792]: info: Cannot mount NAS Elements at system boot, trial number 1 ,retrying in 5 seconds Nov 30 08:20:25 musecume volumio-remote-updater[492]: [2024-11-30 08:20:25] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1732954824 101 Nov 30 08:20:25 musecume volumio[792]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Nov 30 08:20:25 musecume volumio[792]: info: CoreStateMachine::pushState Nov 30 08:20:25 musecume volumio[792]: info: CorePlayQueue::getTrack 0 Nov 30 08:20:25 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 30 08:20:25 musecume volumio[792]: info: CoreCommandRouter::volumioPushState Nov 30 08:20:25 musecume volumio[792]: info: CoreStateMachine::updateTrackBlock Nov 30 08:20:25 musecume volumio[792]: info: CorePlayQueue::getTrackBlock Nov 30 08:20:25 musecume volumio[792]: info: CoreCommandRouter::volumioRetrievevolume Nov 30 08:20:25 musecume volumio[792]: info: Reloading queue from file Nov 30 08:20:25 musecume volumio[792]: info: CoreStateMachine::setRepeat false single undefined Nov 30 08:20:25 musecume volumio[792]: info: CoreStateMachine::pushState Nov 30 08:20:25 musecume volumio[792]: info: CorePlayQueue::getTrack 0 Nov 30 08:20:25 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 30 08:20:25 musecume volumio[792]: info: CoreCommandRouter::volumioPushState Nov 30 08:20:25 musecume volumio[792]: info: CoreStateMachine::setRandom false Nov 30 08:20:25 musecume volumio[792]: info: CoreStateMachine::pushState Nov 30 08:20:25 musecume volumio[792]: info: CorePlayQueue::getTrack 0 Nov 30 08:20:25 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 30 08:20:25 musecume volumio[792]: info: CoreCommandRouter::volumioPushState Nov 30 08:20:25 musecume volumio[792]: info: Setting Device type: Raspberry PI Nov 30 08:20:25 musecume volumio[792]: info: CoreStateMachine::pushState Nov 30 08:20:25 musecume volumio[792]: info: CorePlayQueue::getTrack 0 Nov 30 08:20:25 musecume volumio[792]: info: CoreCommandRouter::volumioPushState Nov 30 08:20:25 musecume volumio[792]: info: Completed loading Core Plugins Nov 30 08:20:25 musecume volumio[792]: info: Preparing to generate the ALSA configuration file Nov 30 08:20:25 musecume volumio[792]: info: Discovery: adding 7d680830-6200-467f-bdf4-95dc6763e13e Nov 30 08:20:25 musecume volumio[792]: info: Discovery: Found device Musecume Nov 30 08:20:25 musecume sudo[1132]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 30 08:20:25 musecume volumio[792]: info: CoreCommandRouter::volumioGetState Nov 30 08:20:25 musecume volumio[792]: info: CorePlayQueue::getTrack 0 Nov 30 08:20:25 musecume sudo[1132]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:25 musecume volumio[792]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Nov 30 08:20:25 musecume volumio[792]: info: Reading ALSA contributions from plugins. Nov 30 08:20:25 musecume volumio[792]: info: Asound.conf file unchanged, so no further update is needed Nov 30 08:20:25 musecume volumio[792]: info: Output device has changed, restarting MPD Nov 30 08:20:25 musecume volumio[792]: info: Output device has changed, restarting Shairport Sync Nov 30 08:20:25 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:25 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 30 08:20:25 musecume sudo[1136]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 30 08:20:25 musecume sudo[1136]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:25 musecume sudo[1136]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:25 musecume systemd[1]: Started UPnP Renderer front-end to MPD. Nov 30 08:20:25 musecume sudo[1138]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 30 08:20:25 musecume sudo[1138]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:25 musecume sudo[1132]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:25 musecume systemd[1]: Stopping Music Player Daemon... Nov 30 08:20:25 musecume volumio[792]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 30 08:20:25 musecume volumio[792]: info: ___________ START PLUGINS ___________ Nov 30 08:20:25 musecume volumio[792]: info: ControllerMpd::onStart: Initializing MPD Nov 30 08:20:25 musecume volumio[792]: info: Creating MPD Configuration file Nov 30 08:20:25 musecume volumio[792]: Starting albumart workers Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 30 08:20:26 musecume volumio[792]: info: [1732954826034] CoreMusicLibrary::Adding element Serveurs Média Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 30 08:20:26 musecume systemd[1]: mpd.service: Succeeded. Nov 30 08:20:26 musecume systemd[1]: Stopped Music Player Daemon. Nov 30 08:20:26 musecume sudo[1145]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 30 08:20:26 musecume sudo[1147]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 30 08:20:26 musecume sudo[1145]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 30 08:20:26 musecume systemd[1]: Starting Music Player Daemon... Nov 30 08:20:26 musecume sudo[1147]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:26 musecume sudo[1145]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:26 musecume systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Nov 30 08:20:26 musecume systemd[1]: mpd.service: Succeeded. Nov 30 08:20:26 musecume systemd[1]: Stopped Music Player Daemon. Nov 30 08:20:26 musecume systemd[1]: Starting Music Player Daemon... Nov 30 08:20:26 musecume volumio[792]: Starting albumart workers Nov 30 08:20:26 musecume volumio[792]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 30 08:20:26 musecume volumio[792]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 30 08:20:26 musecume volumio[792]: Starting albumart workers Nov 30 08:20:26 musecume volumio[792]: info: [1732954826378] CoreMusicLibrary::Adding element Last_100 Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 30 08:20:26 musecume volumio[792]: info: [1732954826385] CoreMusicLibrary::Adding element Webradio Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 30 08:20:26 musecume volumio[792]: info: Initializing BBC Radios Nov 30 08:20:26 musecume sudo[1154]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 30 08:20:26 musecume sudo[1154]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:26 musecume sudo[1154]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 30 08:20:26 musecume volumio[792]: info: Creating Spotify config file Nov 30 08:20:26 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:27 musecume volumio[792]: info: Volumio Calling Home Nov 30 08:20:27 musecume volumio[792]: info: MPD Permissions set Nov 30 08:20:27 musecume volumio[792]: info: MPD Permissions set Nov 30 08:20:27 musecume volumio[792]: info: Upmpdcli Daemon Started Nov 30 08:20:27 musecume volumio[792]: info: Volumio called home Nov 30 08:20:27 musecume volumio[792]: info: Spotify config file written Nov 30 08:20:27 musecume sudo[1174]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 30 08:20:27 musecume sudo[1174]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:27 musecume volumio[792]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Nov 30 08:20:27 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:27 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:27 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:27 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:27 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:27 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:27 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 30 08:20:27 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:27 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:27 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:27 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:27 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:28 musecume systemd[1]: Started go-librespot Daemon. Nov 30 08:20:28 musecume go-librespot[1188]: Librespot-go daemon starting... Nov 30 08:20:28 musecume sudo[1174]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:28 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 30 08:20:28 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 08:20:28 musecume volumio[792]: info: Starting Shairport Sync Nov 30 08:20:28 musecume volumio[792]: info: Starting Shairport Sync Nov 30 08:20:28 musecume sudo[1216]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 30 08:20:28 musecume sudo[1216]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:28 musecume volumio[792]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 30 08:20:28 musecume volumio[792]: SPOTIFY: BQCB4djIKDmF5v-wNoGtGqIDFQLl9pVxPcewrdR94_YsoQCkDuE-0kcs89oTaAYrlBI9TKSQaoMH4c8vU1hYlSgCJpX2Fx5nlXYgTMh0rFnaPceSvpCEE-6NtHnU4Z-oqSDj9PbkOp6VAc-rcWuZGrczw4pw7i97Tl2oM0HR3eFmU2fwnznVOb0i_Jy5SB8wOx54fKL88uTg6JIgANOe3NZ0yr7x4sj0KcfMbQTKnMW5Fqzxa61hXLClup4HuiuEkZu16kDgmlIlmdw Nov 30 08:20:28 musecume volumio[792]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 30 08:20:28 musecume volumio[792]: info: New Spotify access token = BQCB4djIKDmF5v-wNoGtGqIDFQLl9pVxPcewrdR94_YsoQCkDuE-0kcs89oTaAYrlBI9TKSQaoMH4c8vU1hYlSgCJpX2Fx5nlXYgTMh0rFnaPceSvpCEE-6NtHnU4Z-oqSDj9PbkOp6VAc-rcWuZGrczw4pw7i97Tl2oM0HR3eFmU2fwnznVOb0i_Jy5SB8wOx54fKL88uTg6JIgANOe3NZ0yr7x4sj0KcfMbQTKnMW5Fqzxa61hXLClup4HuiuEkZu16kDgmlIlmdw Nov 30 08:20:28 musecume volumio[792]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 30 08:20:28 musecume sudo[1218]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 30 08:20:28 musecume sudo[1218]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:28 musecume systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 30 08:20:28 musecume go-librespot[1188]: time="2024-11-30T08:20:28Z" level=info msg="generated new device id: 4543322e0907179636927d56d9741a16d9fcbe9b" Nov 30 08:20:28 musecume systemd[1]: shairport-sync.service: Succeeded. Nov 30 08:20:28 musecume go-librespot[1188]: time="2024-11-30T08:20:28Z" level=debug msg="stored credentials found for y4gmjllgu0tz8xz35gpt0ey4i" Nov 30 08:20:28 musecume systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 30 08:20:28 musecume volumio[792]: info: CoreCommandRouter::volumioGetState Nov 30 08:20:28 musecume volumio[792]: info: CorePlayQueue::getTrack 0 Nov 30 08:20:28 musecume volumio[792]: info: Starting Shairport Sync Nov 30 08:20:28 musecume systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 30 08:20:28 musecume sudo[1216]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:28 musecume systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 30 08:20:28 musecume systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Nov 30 08:20:28 musecume systemd[1]: shairport-sync.service: Succeeded. Nov 30 08:20:28 musecume systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 30 08:20:28 musecume sudo[1223]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 30 08:20:28 musecume sudo[1223]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:28 musecume systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 30 08:20:28 musecume sudo[1218]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:28 musecume systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 30 08:20:28 musecume systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Nov 30 08:20:28 musecume systemd[1]: shairport-sync.service: Succeeded. Nov 30 08:20:28 musecume systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 30 08:20:28 musecume systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 30 08:20:28 musecume sudo[1223]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:28 musecume volumio[792]: info: Shairport-Sync Started Nov 30 08:20:29 musecume volumio[792]: Error adding Membership: Error: addMembership EINVAL Nov 30 08:20:29 musecume volumio[792]: info: Shairport-Sync Started Nov 30 08:20:29 musecume volumio[792]: info: Shairport-Sync Started Nov 30 08:20:29 musecume volumio[792]: SPOTIFY: User informations: {"country":"FR","display_name":"SpotiFlav","email":"flavalf@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/y4gmjllgu0tz8xz35gpt0ey4i"},"followers":{"href":null,"total":3},"href":"https://api.spotify.com/v1/users/y4gmjllgu0tz8xz35gpt0ey4i","id":"y4gmjllgu0tz8xz35gpt0ey4i","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85df9e94aa02b4b836dc28f3c4","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82df9e94aa02b4b836dc28f3c4","width":64}],"product":"premium","type":"user","uri":"spotify:user:y4gmjllgu0tz8xz35gpt0ey4i"} Nov 30 08:20:29 musecume volumio[792]: info: Spotify Successfully logged in Nov 30 08:20:29 musecume volumio[792]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 30 08:20:29 musecume systemd[1]: systemd-hostnamed.service: Succeeded. Nov 30 08:20:29 musecume volumio[792]: info: [1732954829166] CoreMusicLibrary::Adding element Spotify Nov 30 08:20:29 musecume volumio[792]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 30 08:20:29 musecume volumio[792]: Cannot find translation for source Spotify Nov 30 08:20:29 musecume go-librespot[1188]: time="2024-11-30T08:20:29Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Nov 30 08:20:29 musecume go-librespot[1188]: time="2024-11-30T08:20:29Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 30 08:20:29 musecume go-librespot[1188]: time="2024-11-30T08:20:29Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 30 08:20:29 musecume go-librespot[1188]: time="2024-11-30T08:20:29Z" level=debug msg="zeroconf server listening on port 39589" Nov 30 08:20:29 musecume go-librespot[1188]: time="2024-11-30T08:20:29Z" level=debug msg="obtained new client token: AABUwv6spYCul2LxQr4EK+NmMtBqVFXbQ/BXdK/kk6FkOHal9WghTXt2QaG2yFGZgJjUnDleRn/Phhl11khwiz3fn3NS5vkBnH5yP9DXde0krGq2Ppm2KCFBEIFB7xJbyN8EeddmtNmrRy3JUrRESZ80y7KjXiQGo//i9N6q55Hc6wE1XDOKsVkMSJLDI5OyOXNBMWmE3FkEFEMd97Uq/ZTn4bNswhoLMx2cBLaHtS6DcSerf211u4kNOA==" Nov 30 08:20:29 musecume go-librespot[1188]: time="2024-11-30T08:20:29Z" level=debug msg="completed keyexchange" Nov 30 08:20:30 musecume sudo[1237]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.254/Elements /mnt/NAS/Elements Nov 30 08:20:30 musecume sudo[1237]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:30 musecume kernel: CIFS: Attempting to mount //192.168.0.254/Elements Nov 30 08:20:30 musecume sudo[1237]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:30 musecume kernel: CIFS: VFS: BAD_NETWORK_NAME: \\192.168.0.254\Elements Nov 30 08:20:30 musecume kernel: CIFS: VFS: cifs_mount failed w/return code = -2 Nov 30 08:20:30 musecume volumio[792]: info: Cannot mount NAS Elements at system boot, trial number 2 ,retrying in 5 seconds Nov 30 08:20:30 musecume mpd[1165]: Nov 30 08:20 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 30 08:20:30 musecume systemd[1]: Started Music Player Daemon. Nov 30 08:20:30 musecume sudo[1147]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:30 musecume volumio[792]: Upnp client error: Error: This socket has been ended by the other party Nov 30 08:20:30 musecume sudo[1138]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="completed challenge" Nov 30 08:20:30 musecume volumio[792]: error: MPD error: The expression evaluated to a falsy value: Nov 30 08:20:30 musecume volumio[792]: assert.ok(self.idling) Nov 30 08:20:30 musecume volumio[792]: error: The expression evaluated to a falsy value: Nov 30 08:20:30 musecume volumio[792]: assert.ok(self.idling) Nov 30 08:20:30 musecume volumio[792]: info: MPD running with PID1165 Nov 30 08:20:30 musecume volumio[792]: ,establishing connection Nov 30 08:20:30 musecume volumio[792]: error: updateQueue error: null Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="authenticated as y4gmjllgu0tz8xz35gpt0ey4i" Nov 30 08:20:30 musecume volumio[792]: [yt-cast-receiver] Listening on port 8098 Nov 30 08:20:30 musecume volumio[792]: info: Completed starting Core Plugins Nov 30 08:20:30 musecume volumio[792]: info: ------------------------------------------- Nov 30 08:20:30 musecume volumio[792]: info: ----- MyVolumio plugins startup ---- Nov 30 08:20:30 musecume volumio[792]: info: ------------------------------------------- Nov 30 08:20:30 musecume volumio[792]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 30 08:20:30 musecume volumio[792]: error: updateQueue error: null Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="authenticated as y4gmjllgu0tz8xz35gpt0ey4i" Nov 30 08:20:30 musecume volumio[1135]: Generating RSA private key, 4096 bit long modulus (2 primes) Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="dealer connection opened" Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="initializing zeroconf session, username: y4gmjllgu0tz8xz35gpt0ey4i" Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="received connection id: MmM5ZmVlZjMtMjQ4OS00NGUzLWExMzAtYTU3YWU2NTIzOTcwK2RlYWxlcit0Y3A6Ly8wYWNhNDA5My5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArRDdDQTAzODhDNUM4OTk5MDM3MERDODU4QURBMzQ3NEU3RkZCRDEyQjU2MzQ0MTlBRkRDM0RCNDYzRjA5OTYyNw==" Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="put connect state because NEW_DEVICE" Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 30 08:20:30 musecume go-librespot[1188]: time="2024-11-30T08:20:30Z" level=debug msg="autoplay enabled: false" Nov 30 08:20:31 musecume volumio[792]: info: go-librespot daemon successfully initialized Nov 30 08:20:34 musecume volumio[792]: info: Initializing connection to go-librespot Websocket Nov 30 08:20:34 musecume go-librespot[1188]: time="2024-11-30T08:20:34Z" level=debug msg="new websocket client" Nov 30 08:20:34 musecume volumio[792]: info: Connection to go-librespot Websocket established Nov 30 08:20:35 musecume sudo[1280]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.254/Elements /mnt/NAS/Elements Nov 30 08:20:35 musecume sudo[1280]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:35 musecume kernel: CIFS: Attempting to mount //192.168.0.254/Elements Nov 30 08:20:35 musecume kernel: CIFS: VFS: BAD_NETWORK_NAME: \\192.168.0.254\Elements Nov 30 08:20:35 musecume kernel: CIFS: VFS: cifs_mount failed w/return code = -2 Nov 30 08:20:35 musecume sudo[1280]: pam_unix(sudo:session): session closed for user root Nov 30 08:20:35 musecume volumio[792]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 30 08:20:35 musecume volumio[792]: info: Cannot mount NAS Elements at system boot, trial number 3 ,retrying in 5 seconds Nov 30 08:20:35 musecume go-librespot[1188]: time="2024-11-30T08:20:35Z" level=debug msg="handling transfer player command from 11f1927289672702c02e0b3ca1fdf25301fc46ce" Nov 30 08:20:35 musecume go-librespot[1188]: time="2024-11-30T08:20:35Z" level=debug msg="resolved context of track" uri="spotify:playlist:3cDLM9pLOEjYQyY4jrRuKJ" Nov 30 08:20:35 musecume go-librespot[1188]: time="2024-11-30T08:20:35Z" level=trace msg="fetched new page 0 with 12 items (list: 12)" uri="spotify:playlist:3cDLM9pLOEjYQyY4jrRuKJ" Nov 30 08:20:35 musecume go-librespot[1188]: time="2024-11-30T08:20:35Z" level=debug msg="shuffled context with seed 1476663658912584905 (len: 12, keep: 3)" Nov 30 08:20:35 musecume go-librespot[1188]: time="2024-11-30T08:20:35Z" level=debug msg="loading track (paused: true, position: 4930ms)" uri="spotify:track:4oklGriqYjaIZ346oE0pps" Nov 30 08:20:35 musecume go-librespot[1188]: time="2024-11-30T08:20:35Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 30 08:20:35 musecume go-librespot[1188]: time="2024-11-30T08:20:35Z" level=trace msg="emitting websocket event: will_play" Nov 30 08:20:35 musecume volumio[792]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4oklGriqYjaIZ346oE0pps","play_origin":"playlist"}} Nov 30 08:20:35 musecume go-librespot[1188]: time="2024-11-30T08:20:35Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 30 08:20:35 musecume go-librespot[1188]: time="2024-11-30T08:20:35Z" level=debug msg="selected format OGG_VORBIS_320 (bcf636635773bcd4452816a01b0b6eb6ae46af52)" uri="spotify:track:4oklGriqYjaIZ346oE0pps" Nov 30 08:20:35 musecume go-librespot[1188]: time="2024-11-30T08:20:35Z" level=debug msg="requested aes key for file bcf636635773bcd4452816a01b0b6eb6ae46af52, gid: 4oklGriqYjaIZ346oE0pps" Nov 30 08:20:35 musecume go-librespot[1188]: time="2024-11-30T08:20:35Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1697" Nov 30 08:20:35 musecume go-librespot[1188]: time="2024-11-30T08:20:35Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1293" Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=debug msg="fetched first chunk of 16, total size is 7998444 bytes" uri="spotify:track:4oklGriqYjaIZ346oE0pps" Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=trace msg="seek to 4930ms (diff: 127ms, samples: 217413, bytes: 157931)" uri="spotify:track:4oklGriqYjaIZ346oE0pps" Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 10068 us, period size = 444 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 49 frames" Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=debug msg="created new output device" Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=info msg="loaded track \"Bling-bling\" (paused: true, position: 4930ms, duration: 186626ms, prefetched: false)" uri="spotify:track:4oklGriqYjaIZ346oE0pps" Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=trace msg="emitting websocket event: metadata" Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=trace msg="emitting websocket event: active" Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=debug msg="sending successful reply for dealer request" Nov 30 08:20:36 musecume volumio[792]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4oklGriqYjaIZ346oE0pps","name":"Bling-bling","artist_names":["Adrien Antoine"],"album_name":"Vaiana - La Légende du Bout du Monde (Bande Originale Française du Film)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02460fc9b0c79ed8ce87b5bcd6","position":4930,"duration":186626,"release_date":"year:2016 month:11 day:18","track_number":8,"disc_number":1}} Nov 30 08:20:36 musecume volumio[792]: SPOTIFY: received: {"type":"active","data":null} Nov 30 08:20:36 musecume volumio[792]: info: Aligning Spotify Volume to Volumio Volume Nov 30 08:20:36 musecume volumio[792]: info: CoreCommandRouter::volumioGetState Nov 30 08:20:36 musecume volumio[792]: info: CorePlayQueue::getTrack 0 Nov 30 08:20:36 musecume volumio[792]: info: Setting Spotify Volume from Volumio: 87 Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 30 08:20:36 musecume go-librespot[1188]: time="2024-11-30T08:20:36Z" level=trace msg="emitting websocket event: paused" Nov 30 08:20:36 musecume volumio[792]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4oklGriqYjaIZ346oE0pps","play_origin":"playlist"}} Nov 30 08:20:36 musecume volumio[792]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 30 08:20:36 musecume volumio[792]: TypeError: Cannot read property 'service' of undefined Nov 30 08:20:36 musecume volumio[792]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Nov 30 08:20:36 musecume volumio[792]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Nov 30 08:20:36 musecume volumio[792]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Nov 30 08:20:36 musecume volumio[792]: at WebSocket.emit (events.js:315:20) Nov 30 08:20:36 musecume volumio[792]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Nov 30 08:20:36 musecume volumio[792]: at Receiver.emit (events.js:315:20) Nov 30 08:20:36 musecume volumio[792]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Nov 30 08:20:36 musecume volumio[792]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Nov 30 08:20:36 musecume volumio[792]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Nov 30 08:20:36 musecume volumio[792]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Nov 30 08:20:36 musecume volumio[792]: at writeOrBuffer (internal/streams/writable.js:358:12) Nov 30 08:20:36 musecume volumio[792]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Nov 30 08:20:36 musecume volumio[792]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Nov 30 08:20:36 musecume volumio[792]: at Socket.emit (events.js:315:20) Nov 30 08:20:36 musecume volumio[792]: at addChunk (internal/streams/readable.js:309:12) Nov 30 08:20:36 musecume volumio[792]: at readableAddChunk (internal/streams/readable.js:284:9) Nov 30 08:20:36 musecume volumio[792]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 30 08:20:37 musecume go-librespot[1188]: time="2024-11-30T08:20:37Z" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:4oklGriqYjaIZ346oE0pps" Nov 30 08:20:37 musecume go-librespot[1188]: time="2024-11-30T08:20:37Z" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:4oklGriqYjaIZ346oE0pps" Nov 30 08:20:37 musecume go-librespot[1188]: time="2024-11-30T08:20:37Z" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:4oklGriqYjaIZ346oE0pps" Nov 30 08:20:37 musecume sudo[1295]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-30 08:19 Nov 30 08:20:37 musecume sudo[1295]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 08:20:38 musecume systemd[1]: systemd-timedated.service: Succeeded. 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="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"