-- Logs begin at Mon 2024-11-18 14:58:47 CET, end at Sun 2024-12-01 17:00:55 CET. -- Dec 01 17:00:36 raspoty systemd-timedated[889]: Changed local time to Sun Dec 1 17:00:36 2024 Dec 01 17:00:36 raspoty sudo[887]: pam_unix(sudo:session): session closed for user root Dec 01 17:00:36 raspoty volumio-time-update[563]: volumio-time-update-util: System time updated successfully. Dec 01 17:00:36 raspoty systemd[1]: Starting Daily apt download activities... Dec 01 17:00:36 raspoty systemd[1]: Started Volumio Time Update Utility. Dec 01 17:00:36 raspoty ntpd[851]: Soliciting pool server 129.250.35.250 Dec 01 17:00:36 raspoty ntpd[851]: Soliciting pool server 162.159.200.123 Dec 01 17:00:37 raspoty systemd[1]: apt-daily.service: Succeeded. Dec 01 17:00:37 raspoty systemd[1]: Started Daily apt download activities. Dec 01 17:00:37 raspoty systemd[1]: Starting Daily apt upgrade and clean activities... Dec 01 17:00:37 raspoty volumio[793]: info: ------------------------------------------- Dec 01 17:00:37 raspoty volumio[793]: info: ----- Volumio3 ---- Dec 01 17:00:37 raspoty ntpd[851]: Soliciting pool server 51.68.44.27 Dec 01 17:00:37 raspoty volumio[793]: info: ------------------------------------------- Dec 01 17:00:37 raspoty volumio[793]: info: ----- System startup ---- Dec 01 17:00:37 raspoty volumio[793]: info: ------------------------------------------- Dec 01 17:00:37 raspoty ntpd[851]: Soliciting pool server 82.64.45.50 Dec 01 17:00:37 raspoty ntpd[851]: Soliciting pool server 79.143.250.33 Dec 01 17:00:37 raspoty nmbd[709]: [2024/12/01 17:00:37.715321, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 01 17:00:37 raspoty systemd[1]: Started Samba NMB Daemon. Dec 01 17:00:37 raspoty nmbd[709]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Dec 01 17:00:37 raspoty systemd[1]: Starting Samba Winbind Daemon... Dec 01 17:00:37 raspoty systemd[1]: apt-daily-upgrade.service: Succeeded. Dec 01 17:00:37 raspoty systemd[1]: Started Daily apt upgrade and clean activities. Dec 01 17:00:38 raspoty winbindd[987]: [2024/12/01 17:00:38.137196, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Dec 01 17:00:38 raspoty winbindd[987]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Dec 01 17:00:38 raspoty winbindd[987]: [2024/12/01 17:00:38.169183, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 01 17:00:38 raspoty systemd[1]: Started Samba Winbind Daemon. Dec 01 17:00:38 raspoty winbindd[987]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Dec 01 17:00:38 raspoty systemd[1]: Starting Samba SMB Daemon... Dec 01 17:00:38 raspoty ntpd[851]: Soliciting pool server 51.195.104.188 Dec 01 17:00:38 raspoty ntpd[851]: Soliciting pool server 82.65.248.56 Dec 01 17:00:38 raspoty ntpd[851]: Soliciting pool server 51.178.79.86 Dec 01 17:00:38 raspoty ntpd[851]: Soliciting pool server 162.159.200.1 Dec 01 17:00:38 raspoty smbd[1000]: [2024/12/01 17:00:38.772466, 0] ../lib/util/become_daemon.c:138(daemon_ready) Dec 01 17:00:38 raspoty systemd[1]: Started Samba SMB Daemon. Dec 01 17:00:38 raspoty smbd[1000]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Dec 01 17:00:38 raspoty systemd[1]: Reached target Multi-User System. Dec 01 17:00:38 raspoty systemd[1]: Reached target Graphical Interface. Dec 01 17:00:38 raspoty systemd[1]: Starting Update UTMP about System Runlevel Changes... Dec 01 17:00:38 raspoty systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Dec 01 17:00:38 raspoty systemd[1]: Started Update UTMP about System Runlevel Changes. Dec 01 17:00:38 raspoty systemd[1]: Startup finished in 16.245s (kernel) + 18.338s (userspace) = 34.584s. Dec 01 17:00:39 raspoty volumio[793]: info: MYVOLUMIO Environment detected Dec 01 17:00:39 raspoty volumio[793]: info: Plugin folders cleanup Dec 01 17:00:39 raspoty volumio[793]: info: Scanning into folder /volumio/app/plugins/ Dec 01 17:00:39 raspoty volumio[793]: info: Scanning category audio_interface Dec 01 17:00:39 raspoty volumio[793]: info: Scanning category miscellanea Dec 01 17:00:39 raspoty volumio[793]: info: Scanning category music_service Dec 01 17:00:39 raspoty volumio[793]: info: Scanning category plugins.json Dec 01 17:00:39 raspoty volumio[793]: info: Scanning category system_controller Dec 01 17:00:39 raspoty volumio[793]: info: Scanning category user_interface Dec 01 17:00:39 raspoty volumio[793]: info: Scanning into folder /data/plugins/ Dec 01 17:00:39 raspoty volumio[793]: info: Scanning category music_service Dec 01 17:00:39 raspoty volumio[793]: info: Scanning category user_interface Dec 01 17:00:39 raspoty volumio[793]: info: Plugin folders cleanup completed Dec 01 17:00:39 raspoty volumio[793]: info: ------------------------------------------- Dec 01 17:00:39 raspoty volumio[793]: info: ----- Core plugins startup ---- Dec 01 17:00:39 raspoty volumio[793]: info: ------------------------------------------- Dec 01 17:00:39 raspoty volumio[793]: info: Loading plugins from folder /volumio/app/plugins/ Dec 01 17:00:39 raspoty volumio[793]: info: Adding plugin upnp to MyMusic Plugins Dec 01 17:00:39 raspoty volumio[793]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 01 17:00:39 raspoty volumio[793]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 01 17:00:39 raspoty volumio[793]: info: Loading plugins from folder /data/plugins/ Dec 01 17:00:39 raspoty volumio[793]: info: Loading plugin "system"... Dec 01 17:00:39 raspoty volumio[793]: info: Loading plugin "appearance"... Dec 01 17:00:39 raspoty ntpd[851]: Soliciting pool server 91.224.149.41 Dec 01 17:00:39 raspoty ntpd[851]: Soliciting pool server 91.194.60.128 Dec 01 17:00:39 raspoty ntpd[851]: Soliciting pool server 82.64.247.11 Dec 01 17:00:40 raspoty ntpd[851]: Soliciting pool server 45.13.105.44 Dec 01 17:00:40 raspoty ntpd[851]: Soliciting pool server 82.64.81.218 Dec 01 17:00:40 raspoty volumio[793]: info: Loading plugin "network"... Dec 01 17:00:40 raspoty volumio[793]: info: Refreshing Cached IP Addresses Dec 01 17:00:40 raspoty sudo[1015]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 01 17:00:40 raspoty sudo[1015]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 17:00:40 raspoty sudo[1015]: pam_unix(sudo:session): session closed for user root Dec 01 17:00:40 raspoty volumio[793]: info: Loading plugin "services"... Dec 01 17:00:40 raspoty sudo[1017]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 01 17:00:40 raspoty sudo[1017]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 17:00:40 raspoty volumio[793]: info: Loading plugin "alsa_controller"... Dec 01 17:00:40 raspoty sudo[1017]: pam_unix(sudo:session): session closed for user root Dec 01 17:00:40 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 01 17:00:40 raspoty volumio[793]: info: Loading plugin "wizard"... Dec 01 17:00:40 raspoty volumio[793]: info: Loading plugin "networkfs"... Dec 01 17:00:41 raspoty volumio[793]: info: Starting Udev Watcher for removable devices Dec 01 17:00:41 raspoty sudo[1040]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=rasputy,password=XR-900nr,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.33/Musique /mnt/NAS/Playlist Dec 01 17:00:41 raspoty sudo[1040]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 17:00:41 raspoty volumio[793]: info: Ignoring mount for partition: boot Dec 01 17:00:41 raspoty volumio[793]: info: Ignoring mount for partition: volumio Dec 01 17:00:41 raspoty volumio[793]: info: Ignoring mount for partition: volumio_data Dec 01 17:00:41 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 01 17:00:41 raspoty volumio[793]: info: Loading plugin "volumio_command_line_client"... Dec 01 17:00:41 raspoty volumio[793]: info: Plugin upnp is not enabled Dec 01 17:00:41 raspoty volumio[793]: info: Loading plugin "my_music"... Dec 01 17:00:41 raspoty volumio[793]: info: Loading plugin "mpd"... Dec 01 17:00:41 raspoty kernel: Key type cifs.spnego registered Dec 01 17:00:41 raspoty kernel: Key type cifs.idmap registered Dec 01 17:00:41 raspoty 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. Dec 01 17:00:41 raspoty kernel: CIFS: Attempting to mount //192.168.0.33/Musique Dec 01 17:00:41 raspoty ntpd[851]: Soliciting pool server 5.39.80.51 Dec 01 17:00:41 raspoty ntpd[851]: Soliciting pool server 2001:41d0:a:268f::123 Dec 01 17:00:41 raspoty volumio[793]: info: Plugin upnp_browser is not enabled Dec 01 17:00:41 raspoty volumio[793]: info: Loading plugin "alarm-clock"... Dec 01 17:00:41 raspoty volumio[793]: info: Plugin airplay_emulation is not enabled Dec 01 17:00:41 raspoty volumio[793]: info: Loading plugin "last_100"... Dec 01 17:00:41 raspoty volumio[793]: info: Loading plugin "webradio"... Dec 01 17:00:42 raspoty volumio[793]: info: Loading plugin "i2s_dacs"... Dec 01 17:00:42 raspoty volumio[793]: info: I2S DAC not set, start Auto-detection Dec 01 17:00:42 raspoty volumio[793]: info: Loading plugin "volumiodiscovery"... Dec 01 17:00:42 raspoty sudo[1040]: pam_unix(sudo:session): session closed for user root Dec 01 17:00:42 raspoty kernel: CIFS: VFS: \\192.168.0.33 Dialect not supported by server. Consider specifying vers=1.0 or vers=2.0 on mount for accessing older servers Dec 01 17:00:42 raspoty kernel: CIFS: VFS: cifs_mount failed w/return code = -95 Dec 01 17:00:42 raspoty volumio[793]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 01 17:00:42 raspoty volumio[793]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 01 17:00:42 raspoty volumio[793]: *** WARNING *** For more information see Dec 01 17:00:42 raspoty volumio[793]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 01 17:00:42 raspoty node[793]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 01 17:00:42 raspoty volumio[793]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 01 17:00:42 raspoty volumio[793]: *** WARNING *** For more information see Dec 01 17:00:42 raspoty node[793]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 01 17:00:42 raspoty node[793]: *** WARNING *** For more information see Dec 01 17:00:42 raspoty node[793]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 01 17:00:42 raspoty node[793]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 01 17:00:42 raspoty node[793]: *** WARNING *** For more information see Dec 01 17:00:42 raspoty volumio[793]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 01 17:00:42 raspoty volumio[793]: info: Discovery: Started advertising with name: Raspoty Dec 01 17:00:42 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 01 17:00:42 raspoty volumio[793]: info: Loading plugin "spop"... Dec 01 17:00:42 raspoty volumio-remote-updater[561]: [2024-12-01 17:00:42] [connect] Successful connection Dec 01 17:00:44 raspoty volumio[793]: info: Loading plugin "outputs"... Dec 01 17:00:44 raspoty volumio[793]: info: Loading plugin "albumart"... Dec 01 17:00:44 raspoty volumio[793]: info: Plugin example_plugin is not enabled Dec 01 17:00:44 raspoty volumio[793]: info: Loading plugin "inputs"... Dec 01 17:00:44 raspoty volumio[793]: info: Loading plugin "updater_comm"... Dec 01 17:00:44 raspoty volumio[793]: info: Plugin mpdemulation is not enabled Dec 01 17:00:44 raspoty volumio[793]: info: Loading plugin "rest_api"... Dec 01 17:00:44 raspoty volumio[793]: info: Loading plugin "websocket"... Dec 01 17:00:44 raspoty volumio[793]: info: Starting Socket.io Server version 2.3.0 Dec 01 17:00:44 raspoty volumio[793]: info: Loading plugin "randomizer"... Dec 01 17:00:44 raspoty volumio[793]: Forking 3 albumart workers Dec 01 17:00:46 raspoty ntpd[851]: receive: Unexpected origin timestamp 0xeaf706ac.a402ae49 does not match aorg 0000000000.00000000 from server@91.224.149.41 xmt 0xeaf706ae.0156b747 Dec 01 17:00:46 raspoty ntpd[851]: receive: Unexpected origin timestamp 0xeaf706ac.a3ff5c33 does not match aorg 0000000000.00000000 from server@82.64.81.218 xmt 0xeaf706ad.ffa8a064 Dec 01 17:00:46 raspoty volumio[793]: info: Applying required configuration parameters for plugin randomizer Dec 01 17:00:46 raspoty volumio[793]: info: Loading i18n strings for locale fr Dec 01 17:00:46 raspoty volumio[793]: Updating browse sources language Dec 01 17:00:46 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 01 17:00:46 raspoty volumio[793]: Starting albumart workers Dec 01 17:00:46 raspoty volumio[793]: Starting albumart workers Dec 01 17:00:46 raspoty volumio[793]: Starting albumart workers Dec 01 17:00:46 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 01 17:00:46 raspoty volumio[793]: info: CoreCommandRouter::initPlayerControls Dec 01 17:00:46 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:46 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:46 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:46 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:46 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:46 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:46 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:46 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:46 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 01 17:00:46 raspoty volumio[793]: Express server listening on port 3000 Dec 01 17:00:46 raspoty volumio[793]: [Metrics] WebUI: 9s 1.47ms Dec 01 17:00:46 raspoty volumio[793]: info: CoreStateMachine::resetVolumioState Dec 01 17:00:46 raspoty volumio[793]: info: CoreStateMachine::getcurrentVolume Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::volumioRetrievevolume Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 01 17:00:47 raspoty volumio[793]: info: Volumio Network Manager: Network status updated: 1 Dec 01 17:00:47 raspoty volumio[793]: info: Cannot mount NAS Playlist at system boot, trial number 1 ,retrying in 5 seconds Dec 01 17:00:47 raspoty volumio-remote-updater[561]: [2024-12-01 17:00:47] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1733068842 101 Dec 01 17:00:47 raspoty volumio[793]: 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 Dec 01 17:00:47 raspoty volumio[793]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control 'HDMI',0 Dec 01 17:00:47 raspoty volumio[793]: info: Reloading queue from file Dec 01 17:00:47 raspoty volumio[793]: info: Setting Device type: Raspberry PI Dec 01 17:00:47 raspoty volumio[793]: info: CoreStateMachine::setRepeat false single undefined Dec 01 17:00:47 raspoty volumio[793]: info: CoreStateMachine::pushState Dec 01 17:00:47 raspoty volumio[793]: info: CorePlayQueue::getTrack 0 Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::volumioPushState Dec 01 17:00:47 raspoty volumio[793]: info: CoreStateMachine::setRandom true Dec 01 17:00:47 raspoty volumio[793]: info: CoreStateMachine::pushState Dec 01 17:00:47 raspoty volumio[793]: info: CorePlayQueue::getTrack 0 Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::volumioPushState Dec 01 17:00:47 raspoty volumio[793]: info: VolumeController:: Volume=undefined Mute =false Dec 01 17:00:47 raspoty volumio[793]: info: CoreStateMachine::pushState Dec 01 17:00:47 raspoty volumio[793]: info: CorePlayQueue::getTrack 0 Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::volumioPushState Dec 01 17:00:47 raspoty volumio[793]: info: CoreStateMachine::updateTrackBlock Dec 01 17:00:47 raspoty volumio[793]: info: CorePlayQueue::getTrackBlock Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::volumioRetrievevolume Dec 01 17:00:47 raspoty volumio[793]: info: Completed loading Core Plugins Dec 01 17:00:47 raspoty volumio[793]: info: Preparing to generate the ALSA configuration file Dec 01 17:00:47 raspoty volumio[793]: info: Discovery: adding e10fb0a0-ba5c-43b5-99d7-bb3f6ca9a23c Dec 01 17:00:47 raspoty volumio[793]: info: Discovery: Found device Raspoty Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::volumioGetState Dec 01 17:00:47 raspoty volumio[793]: info: CorePlayQueue::getTrack 0 Dec 01 17:00:47 raspoty volumio[793]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control 'HDMI',0 Dec 01 17:00:47 raspoty volumio[793]: info: Asound.conf file unchanged, so no further update is needed Dec 01 17:00:47 raspoty volumio[793]: info: Output device has changed, restarting MPD Dec 01 17:00:47 raspoty sudo[1130]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 01 17:00:47 raspoty sudo[1130]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 17:00:47 raspoty volumio[793]: info: ___________ START PLUGINS ___________ Dec 01 17:00:47 raspoty sudo[1130]: pam_unix(sudo:session): session closed for user root Dec 01 17:00:47 raspoty volumio[793]: info: ControllerMpd::onStart: Initializing MPD Dec 01 17:00:47 raspoty volumio[793]: info: Creating MPD Configuration file Dec 01 17:00:47 raspoty sudo[1133]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 01 17:00:47 raspoty sudo[1133]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 17:00:47 raspoty sudo[1136]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 01 17:00:47 raspoty volumio[793]: info: [1733068847755] CoreMusicLibrary::Adding element Last_100 Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 01 17:00:47 raspoty sudo[1136]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 17:00:47 raspoty systemd[1]: Stopping Music Player Daemon... Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 01 17:00:47 raspoty volumio[793]: info: [1733068847764] CoreMusicLibrary::Adding element Webradio Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 01 17:00:47 raspoty sudo[1136]: pam_unix(sudo:session): session closed for user root Dec 01 17:00:47 raspoty sudo[1138]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 01 17:00:47 raspoty sudo[1138]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 17:00:47 raspoty volumio[793]: info: Initializing BBC Radios Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 01 17:00:47 raspoty volumio[793]: info: Creating Spotify config file Dec 01 17:00:47 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:47 raspoty systemd[1]: mpd.service: Succeeded. Dec 01 17:00:47 raspoty systemd[1]: Stopped Music Player Daemon. Dec 01 17:00:47 raspoty systemd[1]: Starting Music Player Daemon... Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 01 17:00:48 raspoty volumio[793]: info: [1733068848019] CoreMusicLibrary::Adding element Randomizer Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 01 17:00:48 raspoty volumio[793]: Cannot find translation for source Randomizer Dec 01 17:00:48 raspoty volumio[793]: info: Volumio Calling Home Dec 01 17:00:48 raspoty sudo[1151]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 01 17:00:48 raspoty sudo[1151]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 17:00:48 raspoty sudo[1151]: pam_unix(sudo:session): session closed for user root Dec 01 17:00:48 raspoty volumio[793]: info: MPD Permissions set Dec 01 17:00:48 raspoty volumio[793]: info: VolumeController:: Volume=undefined Mute =false Dec 01 17:00:48 raspoty volumio[793]: info: CoreStateMachine::pushState Dec 01 17:00:48 raspoty volumio[793]: info: CorePlayQueue::getTrack 0 Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::volumioPushState Dec 01 17:00:48 raspoty volumio[793]: info: Spotify config file written Dec 01 17:00:48 raspoty sudo[1160]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 01 17:00:48 raspoty sudo[1160]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 17:00:48 raspoty volumio[793]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 01 17:00:48 raspoty volumio[793]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 01 17:00:48 raspoty volumio[793]: info: Volumio called home Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty systemd[1]: Started go-librespot Daemon. Dec 01 17:00:48 raspoty sudo[1160]: pam_unix(sudo:session): session closed for user root Dec 01 17:00:48 raspoty go-librespot[1162]: Librespot-go daemon starting... Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: No need to fix Spotify hosts Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 01 17:00:48 raspoty volumio[793]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 01 17:00:48 raspoty volumio[793]: SPOTIFY: BQD87KNSeYNqFIdLCAQwkwVV5RHM31ai_HS8KS4To9aA8HOCCJP8SF6P1yIoSQS5WNKv1VozieknKagYWIV7JyVjF3t-NrrmLdACH-JEd1O1STdjgVOIoDzaVa2oHcTmKat6uU8cv28Gj72t2oAd-pZe_PgagdVFFSYb5xnn_UQJP3XP4kIodzcJ4PlhQRjDgo9648L468cQimyFQUosSz5IE9Oo4LWnMOYMAS9JpLZY8m5UgA2hLoreuJ3b_kUn0ahGiOEH3JFCals Dec 01 17:00:48 raspoty volumio[793]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 01 17:00:48 raspoty volumio[793]: info: New Spotify access token = BQD87KNSeYNqFIdLCAQwkwVV5RHM31ai_HS8KS4To9aA8HOCCJP8SF6P1yIoSQS5WNKv1VozieknKagYWIV7JyVjF3t-NrrmLdACH-JEd1O1STdjgVOIoDzaVa2oHcTmKat6uU8cv28Gj72t2oAd-pZe_PgagdVFFSYb5xnn_UQJP3XP4kIodzcJ4PlhQRjDgo9648L468cQimyFQUosSz5IE9Oo4LWnMOYMAS9JpLZY8m5UgA2hLoreuJ3b_kUn0ahGiOEH3JFCals Dec 01 17:00:48 raspoty volumio[793]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::volumioGetState Dec 01 17:00:48 raspoty volumio[793]: info: CorePlayQueue::getTrack 0 Dec 01 17:00:48 raspoty go-librespot[1162]: time="2024-12-01T17:00:48+01:00" level=info msg="generated new device id: 004a75e16af37f1186fb56ecfbd7a4961ac8c3d7" Dec 01 17:00:48 raspoty go-librespot[1162]: time="2024-12-01T17:00:48+01:00" level=debug msg="stored credentials found for xwbwcha2azo5cepmlnbddvg9a" Dec 01 17:00:48 raspoty volumio[793]: SPOTIFY: User informations: {"country":"FR","display_name":"Alone","email":"chamalono@outlook.fr","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/xwbwcha2azo5cepmlnbddvg9a"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/xwbwcha2azo5cepmlnbddvg9a","id":"xwbwcha2azo5cepmlnbddvg9a","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85a8d1554eaa0c24469575fdac","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82a8d1554eaa0c24469575fdac","width":64}],"product":"premium","type":"user","uri":"spotify:user:xwbwcha2azo5cepmlnbddvg9a"} Dec 01 17:00:48 raspoty volumio[793]: info: Spotify Successfully logged in Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 01 17:00:48 raspoty volumio[793]: info: [1733068848907] CoreMusicLibrary::Adding element Spotify Dec 01 17:00:48 raspoty volumio[793]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 01 17:00:48 raspoty volumio[793]: Cannot find translation for source Randomizer Dec 01 17:00:48 raspoty volumio[793]: Cannot find translation for source Spotify Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" 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]" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" 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]" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" 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]" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="zeroconf server listening on port 45315" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="obtained new client token: AACH/ajFPuQ1RxiSMq+Rd/3PTch6+a+JctaMC5+DEqVVr0xp+Hda7xBMlYtxRRKUYDmtzDZ0YVGuu2XSEiBCqLPimYEvwe1qxAZqe7hJ05ahv0k4Lw61MYZxhBWv2SgDuJsRDonxHCdFfF03hN4buf3lCinYU8pv/G+J0QRXs/l0wdEHHDB9tQl7wzFBKqIdwlwO2Qdlu8Z9fP37EmxC6Ie87Ze7NRMpDn5y7Ppc0yIvhPoPwzte6RnHE80=" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=info msg="connected to ap-gew1.spotify.com:4070" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="completed keyexchange" Dec 01 17:00:49 raspoty mpd[1158]: Dec 01 17:00 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 01 17:00:49 raspoty systemd[1]: Started Music Player Daemon. Dec 01 17:00:49 raspoty sudo[1133]: pam_unix(sudo:session): session closed for user root Dec 01 17:00:49 raspoty sudo[1138]: pam_unix(sudo:session): session closed for user root Dec 01 17:00:49 raspoty volumio[793]: info: Completed starting Core Plugins Dec 01 17:00:49 raspoty volumio[793]: info: ------------------------------------------- Dec 01 17:00:49 raspoty volumio[793]: info: ----- MyVolumio plugins startup ---- Dec 01 17:00:49 raspoty volumio[793]: info: ------------------------------------------- Dec 01 17:00:49 raspoty volumio[793]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 01 17:00:49 raspoty volumio[793]: error: MPD error: The expression evaluated to a falsy value: Dec 01 17:00:49 raspoty volumio[793]: assert.ok(self.idling) Dec 01 17:00:49 raspoty volumio[793]: error: The expression evaluated to a falsy value: Dec 01 17:00:49 raspoty volumio[793]: assert.ok(self.idling) Dec 01 17:00:49 raspoty volumio[793]: info: MPD running with PID1158 Dec 01 17:00:49 raspoty volumio[793]: ,establishing connection Dec 01 17:00:49 raspoty volumio[793]: error: updateQueue error: null Dec 01 17:00:49 raspoty volumio[793]: error: updateQueue error: null Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="completed challenge" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="authenticated as xwbwcha2azo5cepmlnbddvg9a" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="authenticated as xwbwcha2azo5cepmlnbddvg9a" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="dealer connection opened" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="initializing zeroconf session, username: xwbwcha2azo5cepmlnbddvg9a" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="autoplay enabled: false" Dec 01 17:00:49 raspoty go-librespot[1162]: time="2024-12-01T17:00:49+01:00" level=debug msg="received connection id: MDQ4MjljY2YtZDA1Yy00YWVkLTkxMWItMTZkYjQ3NDdlZWNhK2RlYWxlcit0Y3A6Ly8wYWNhNDBmYy5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArNTk2OTNDRDExRjc0NkVCRDI3OEQwMTNEMTg2RUVGNDU0OUNGM0FDMjJCMEExOUVDQ0E3OTM2QTM5MEM2RTdBRg==" Dec 01 17:00:50 raspoty go-librespot[1162]: time="2024-12-01T17:00:50+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 01 17:00:51 raspoty volumio[793]: info: go-librespot daemon successfully initialized Dec 01 17:00:52 raspoty sudo[1184]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=rasputy,password=XR-900nr,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.33/Musique /mnt/NAS/Playlist Dec 01 17:00:52 raspoty sudo[1184]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 01 17:00:52 raspoty kernel: CIFS: Attempting to mount //192.168.0.33/Musique Dec 01 17:00:52 raspoty sudo[1184]: pam_unix(sudo:session): session closed for user root Dec 01 17:00:52 raspoty kernel: CIFS: VFS: \\192.168.0.33 Dialect not supported by server. Consider specifying vers=1.0 or vers=2.0 on mount for accessing older servers Dec 01 17:00:52 raspoty kernel: CIFS: VFS: cifs_mount failed w/return code = -95 Dec 01 17:00:52 raspoty volumio[793]: info: Cannot mount NAS Playlist at system boot, trial number 2 ,retrying in 5 seconds Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="handling transfer player command from bfc3d5019f48115d3edabeb833e01ab974674daa" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="resolved context of track" uri="spotify:user:xwbwcha2azo5cepmlnbddvg9a:collection" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=trace msg="fetched new page 0 with 1389 items (list: 1389)" uri="spotify:user:xwbwcha2azo5cepmlnbddvg9a:collection" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="shuffled context with seed 1992008363012218361 (len: 1389, keep: 999)" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="loading track (paused: false, position: 23573ms)" uri="spotify:track:7xMokLfGPxWjZJi0bZQkQ8" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=trace msg="emitting websocket event: will_play" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="selected format OGG_VORBIS_320 (03fa15a94e021c816a355b4328941275a4e69c28)" uri="spotify:track:7xMokLfGPxWjZJi0bZQkQ8" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="requested aes key for file 03fa15a94e021c816a355b4328941275a4e69c28, gid: 7xMokLfGPxWjZJi0bZQkQ8" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1688" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="fetched first chunk of 18, total size is 9197808 bytes" uri="spotify:track:7xMokLfGPxWjZJi0bZQkQ8" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:7xMokLfGPxWjZJi0bZQkQ8" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:7xMokLfGPxWjZJi0bZQkQ8" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=trace msg="seek to 23573ms (diff: 121ms, samples: 1039569, bytes: 855694)" uri="spotify:track:7xMokLfGPxWjZJi0bZQkQ8" Dec 01 17:00:54 raspoty volumio[793]: info: Initializing connection to go-librespot Websocket Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 10068 us, period size = 444 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 49 frames" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="created new output device" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=info msg="loaded track \"Lily of the Valley\" (paused: false, position: 23573ms, duration: 247710ms, prefetched: false)" uri="spotify:track:7xMokLfGPxWjZJi0bZQkQ8" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="new websocket client" Dec 01 17:00:54 raspoty volumio[793]: info: Connection to go-librespot Websocket established Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:7xMokLfGPxWjZJi0bZQkQ8" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1288" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=trace msg="scheduling prefetch in 194s" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=trace msg="emitting websocket event: metadata" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=trace msg="emitting websocket event: active" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="sending successful reply for dealer request" Dec 01 17:00:54 raspoty volumio[793]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7xMokLfGPxWjZJi0bZQkQ8","name":"Lily of the Valley","artist_names":["Robin Appelqvist"],"album_name":"Lily of the Valley","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02aabeea59c0c66e208b930784","position":23573,"duration":247710,"release_date":"year:2022 month:4 day:1","track_number":1,"disc_number":1}} Dec 01 17:00:54 raspoty volumio[793]: SPOTIFY: received: {"type":"active","data":null} Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 01 17:00:54 raspoty volumio[793]: info: Aligning Spotify Volume to Volumio Volume Dec 01 17:00:54 raspoty volumio[793]: info: CoreCommandRouter::volumioGetState Dec 01 17:00:54 raspoty volumio[793]: info: CorePlayQueue::getTrack 0 Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="fetched chunk 4/17, size: 524288" uri="spotify:track:7xMokLfGPxWjZJi0bZQkQ8" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 01 17:00:54 raspoty go-librespot[1162]: time="2024-12-01T17:00:54+01:00" level=trace msg="emitting websocket event: playing" Dec 01 17:00:54 raspoty volumio[793]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:7xMokLfGPxWjZJi0bZQkQ8","play_origin":"collection-songs"}} Dec 01 17:00:54 raspoty volumio[793]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 01 17:00:54 raspoty volumio[793]: TypeError: Cannot read property 'service' of undefined Dec 01 17:00:54 raspoty volumio[793]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Dec 01 17:00:54 raspoty volumio[793]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Dec 01 17:00:54 raspoty volumio[793]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Dec 01 17:00:54 raspoty volumio[793]: at WebSocket.emit (events.js:315:20) Dec 01 17:00:54 raspoty volumio[793]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Dec 01 17:00:54 raspoty volumio[793]: at Receiver.emit (events.js:315:20) Dec 01 17:00:54 raspoty volumio[793]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Dec 01 17:00:54 raspoty volumio[793]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Dec 01 17:00:54 raspoty volumio[793]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Dec 01 17:00:54 raspoty volumio[793]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Dec 01 17:00:54 raspoty volumio[793]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 01 17:00:55 raspoty sudo[1214]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-12-01 16:59 Dec 01 17:00:55 raspoty sudo[1214]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="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"