-- Logs begin at Thu 2019-02-14 11:12:00 CET, end at Sun 2024-11-24 09:57:39 CET. -- Nov 24 09:57:20 raspoty systemd-timedated[895]: Changed local time to Sun Nov 24 09:57:20 2024 Nov 24 09:57:20 raspoty sudo[890]: pam_unix(sudo:session): session closed for user root Nov 24 09:57:20 raspoty volumio-time-update[569]: volumio-time-update-util: System time updated successfully. Nov 24 09:57:20 raspoty systemd[1]: Starting Daily apt download activities... Nov 24 09:57:20 raspoty systemd[1]: Started Volumio Time Update Utility. Nov 24 09:57:20 raspoty ntpd[851]: Soliciting pool server 79.143.250.33 Nov 24 09:57:20 raspoty ntpd[851]: Soliciting pool server 193.200.43.105 Nov 24 09:57:21 raspoty systemd[1]: apt-daily.service: Succeeded. Nov 24 09:57:21 raspoty systemd[1]: Started Daily apt download activities. Nov 24 09:57:21 raspoty systemd[1]: Starting Daily apt upgrade and clean activities... Nov 24 09:57:21 raspoty nmbd[712]: [2024/11/24 09:57:21.715562, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 24 09:57:21 raspoty nmbd[712]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Nov 24 09:57:21 raspoty systemd[1]: Started Samba NMB Daemon. Nov 24 09:57:21 raspoty ntpd[851]: Soliciting pool server 162.159.200.123 Nov 24 09:57:21 raspoty ntpd[851]: Soliciting pool server 82.64.42.185 Nov 24 09:57:21 raspoty systemd[1]: Starting Samba Winbind Daemon... Nov 24 09:57:21 raspoty volumio[798]: info: ------------------------------------------- Nov 24 09:57:21 raspoty ntpd[851]: Soliciting pool server 194.177.34.116 Nov 24 09:57:21 raspoty volumio[798]: info: ----- Volumio3 ---- Nov 24 09:57:21 raspoty volumio[798]: info: ------------------------------------------- Nov 24 09:57:21 raspoty volumio[798]: info: ----- System startup ---- Nov 24 09:57:21 raspoty volumio[798]: info: ------------------------------------------- Nov 24 09:57:22 raspoty systemd[1]: apt-daily-upgrade.service: Succeeded. Nov 24 09:57:22 raspoty systemd[1]: Started Daily apt upgrade and clean activities. Nov 24 09:57:22 raspoty winbindd[985]: [2024/11/24 09:57:22.100741, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Nov 24 09:57:22 raspoty winbindd[985]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Nov 24 09:57:22 raspoty winbindd[985]: [2024/11/24 09:57:22.126335, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 24 09:57:22 raspoty systemd[1]: Started Samba Winbind Daemon. Nov 24 09:57:22 raspoty winbindd[985]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Nov 24 09:57:22 raspoty systemd[1]: Starting Samba SMB Daemon... Nov 24 09:57:22 raspoty ntpd[851]: Soliciting pool server 185.254.101.25 Nov 24 09:57:22 raspoty ntpd[851]: Soliciting pool server 37.59.63.125 Nov 24 09:57:22 raspoty ntpd[851]: Soliciting pool server 51.195.104.188 Nov 24 09:57:22 raspoty systemd[1]: Started Samba SMB Daemon. Nov 24 09:57:22 raspoty systemd[1]: Reached target Multi-User System. Nov 24 09:57:22 raspoty systemd[1]: Reached target Graphical Interface. Nov 24 09:57:22 raspoty smbd[1006]: [2024/11/24 09:57:22.750089, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 24 09:57:22 raspoty smbd[1006]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Nov 24 09:57:22 raspoty ntpd[851]: Soliciting pool server 82.67.41.119 Nov 24 09:57:22 raspoty systemd[1]: Starting Update UTMP about System Runlevel Changes... Nov 24 09:57:22 raspoty systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Nov 24 09:57:22 raspoty systemd[1]: Started Update UTMP about System Runlevel Changes. Nov 24 09:57:22 raspoty systemd[1]: Startup finished in 16.309s (kernel) + 18.446s (userspace) = 34.755s. Nov 24 09:57:23 raspoty volumio[798]: info: MYVOLUMIO Environment detected Nov 24 09:57:23 raspoty volumio[798]: info: Plugin folders cleanup Nov 24 09:57:23 raspoty volumio[798]: info: Scanning into folder /volumio/app/plugins/ Nov 24 09:57:23 raspoty volumio[798]: info: Scanning category audio_interface Nov 24 09:57:23 raspoty volumio[798]: info: Scanning category miscellanea Nov 24 09:57:23 raspoty volumio[798]: info: Scanning category music_service Nov 24 09:57:23 raspoty volumio[798]: info: Scanning category plugins.json Nov 24 09:57:23 raspoty volumio[798]: info: Scanning category system_controller Nov 24 09:57:23 raspoty volumio[798]: info: Scanning category user_interface Nov 24 09:57:23 raspoty volumio[798]: info: Scanning into folder /data/plugins/ Nov 24 09:57:23 raspoty volumio[798]: info: Scanning category music_service Nov 24 09:57:23 raspoty volumio[798]: info: Scanning category user_interface Nov 24 09:57:23 raspoty volumio[798]: info: Plugin folders cleanup completed Nov 24 09:57:23 raspoty volumio[798]: info: ------------------------------------------- Nov 24 09:57:23 raspoty volumio[798]: info: ----- Core plugins startup ---- Nov 24 09:57:23 raspoty volumio[798]: info: ------------------------------------------- Nov 24 09:57:23 raspoty volumio[798]: info: Loading plugins from folder /volumio/app/plugins/ Nov 24 09:57:23 raspoty volumio[798]: info: Adding plugin upnp to MyMusic Plugins Nov 24 09:57:23 raspoty volumio[798]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 24 09:57:23 raspoty volumio[798]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 24 09:57:23 raspoty volumio[798]: info: Loading plugins from folder /data/plugins/ Nov 24 09:57:23 raspoty volumio[798]: info: Loading plugin "system"... Nov 24 09:57:23 raspoty volumio[798]: info: Loading plugin "appearance"... Nov 24 09:57:23 raspoty ntpd[851]: Soliciting pool server 51.68.44.27 Nov 24 09:57:23 raspoty ntpd[851]: Soliciting pool server 5.196.160.139 Nov 24 09:57:23 raspoty ntpd[851]: Soliciting pool server 51.255.141.76 Nov 24 09:57:24 raspoty ntpd[851]: Soliciting pool server 82.64.230.205 Nov 24 09:57:24 raspoty ntpd[851]: Soliciting pool server 94.23.45.103 Nov 24 09:57:24 raspoty volumio[798]: info: Loading plugin "network"... Nov 24 09:57:24 raspoty volumio[798]: info: Refreshing Cached IP Addresses Nov 24 09:57:24 raspoty sudo[1021]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 24 09:57:24 raspoty sudo[1021]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 09:57:24 raspoty volumio[798]: info: Loading plugin "services"... Nov 24 09:57:24 raspoty sudo[1023]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 24 09:57:24 raspoty sudo[1023]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 09:57:24 raspoty sudo[1021]: pam_unix(sudo:session): session closed for user root Nov 24 09:57:24 raspoty volumio[798]: info: Loading plugin "alsa_controller"... Nov 24 09:57:24 raspoty sudo[1023]: pam_unix(sudo:session): session closed for user root Nov 24 09:57:25 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 24 09:57:25 raspoty volumio[798]: info: Loading plugin "wizard"... Nov 24 09:57:25 raspoty volumio[798]: info: Loading plugin "networkfs"... Nov 24 09:57:25 raspoty volumio[798]: info: Starting Udev Watcher for removable devices Nov 24 09:57:25 raspoty sudo[1046]: 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 Nov 24 09:57:25 raspoty sudo[1046]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 09:57:25 raspoty volumio[798]: info: Ignoring mount for partition: boot Nov 24 09:57:25 raspoty volumio[798]: info: Ignoring mount for partition: volumio Nov 24 09:57:25 raspoty volumio[798]: info: Ignoring mount for partition: volumio_data Nov 24 09:57:25 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 24 09:57:25 raspoty volumio[798]: info: Loading plugin "volumio_command_line_client"... Nov 24 09:57:25 raspoty volumio[798]: info: Plugin upnp is not enabled Nov 24 09:57:25 raspoty volumio[798]: info: Loading plugin "my_music"... Nov 24 09:57:25 raspoty volumio[798]: info: Loading plugin "mpd"... Nov 24 09:57:25 raspoty kernel: Key type cifs.spnego registered Nov 24 09:57:25 raspoty kernel: Key type cifs.idmap registered Nov 24 09:57:25 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. Nov 24 09:57:25 raspoty kernel: CIFS: Attempting to mount //192.168.0.33/Musique Nov 24 09:57:25 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 Nov 24 09:57:25 raspoty kernel: CIFS: VFS: cifs_mount failed w/return code = -95 Nov 24 09:57:25 raspoty sudo[1046]: pam_unix(sudo:session): session closed for user root Nov 24 09:57:25 raspoty ntpd[851]: Soliciting pool server 2606:4700:f1::1 Nov 24 09:57:25 raspoty volumio[798]: info: Plugin upnp_browser is not enabled Nov 24 09:57:25 raspoty volumio[798]: info: Loading plugin "alarm-clock"... Nov 24 09:57:26 raspoty volumio[798]: info: Plugin airplay_emulation is not enabled Nov 24 09:57:26 raspoty volumio[798]: info: Loading plugin "last_100"... Nov 24 09:57:26 raspoty volumio[798]: info: Loading plugin "webradio"... Nov 24 09:57:26 raspoty volumio[798]: info: Loading plugin "i2s_dacs"... Nov 24 09:57:26 raspoty volumio[798]: info: I2S DAC not set, start Auto-detection Nov 24 09:57:26 raspoty volumio[798]: info: Loading plugin "volumiodiscovery"... Nov 24 09:57:26 raspoty volumio[798]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 24 09:57:26 raspoty volumio[798]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 24 09:57:26 raspoty volumio[798]: *** WARNING *** For more information see Nov 24 09:57:26 raspoty node[798]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 24 09:57:26 raspoty volumio[798]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 24 09:57:26 raspoty volumio[798]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 24 09:57:26 raspoty volumio[798]: *** WARNING *** For more information see Nov 24 09:57:26 raspoty node[798]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 24 09:57:26 raspoty node[798]: *** WARNING *** For more information see Nov 24 09:57:26 raspoty node[798]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 24 09:57:26 raspoty node[798]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 24 09:57:26 raspoty node[798]: *** WARNING *** For more information see Nov 24 09:57:26 raspoty volumio[798]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 24 09:57:26 raspoty volumio[798]: info: Discovery: Started advertising with name: Raspoty Nov 24 09:57:26 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 24 09:57:26 raspoty volumio[798]: info: Loading plugin "spop"... Nov 24 09:57:26 raspoty volumio-remote-updater[537]: [2024-11-24 09:57:26] [connect] Successful connection Nov 24 09:57:28 raspoty volumio[798]: info: Loading plugin "outputs"... Nov 24 09:57:28 raspoty volumio[798]: info: Loading plugin "albumart"... Nov 24 09:57:28 raspoty volumio[798]: info: Plugin example_plugin is not enabled Nov 24 09:57:28 raspoty volumio[798]: info: Loading plugin "inputs"... Nov 24 09:57:28 raspoty volumio[798]: info: Loading plugin "updater_comm"... Nov 24 09:57:28 raspoty volumio[798]: info: Plugin mpdemulation is not enabled Nov 24 09:57:28 raspoty volumio[798]: info: Loading plugin "rest_api"... Nov 24 09:57:28 raspoty volumio[798]: info: Loading plugin "websocket"... Nov 24 09:57:28 raspoty volumio[798]: info: Starting Socket.io Server version 2.3.0 Nov 24 09:57:28 raspoty volumio[798]: info: Loading plugin "randomizer"... Nov 24 09:57:28 raspoty volumio[798]: Forking 3 albumart workers Nov 24 09:57:29 raspoty ntpd[851]: receive: Unexpected origin timestamp 0xeaed68f8.be3b9bb4 does not match aorg 0000000000.00000000 from server@82.64.42.185 xmt 0xeaed68f9.ba8f8890 Nov 24 09:57:29 raspoty ntpd[851]: receive: Unexpected origin timestamp 0xeaed68f8.be392838 does not match aorg 0000000000.00000000 from server@51.68.44.27 xmt 0xeaed68f9.bafbf0d4 Nov 24 09:57:29 raspoty ntpd[851]: receive: Unexpected origin timestamp 0xeaed68f8.be1adb45 does not match aorg 0000000000.00000000 from server@51.255.141.76 xmt 0xeaed68f9.baf6206b Nov 24 09:57:29 raspoty ntpd[851]: receive: Unexpected origin timestamp 0xeaed68f8.be3e46a2 does not match aorg 0000000000.00000000 from server@5.39.80.51 xmt 0xeaed68f9.bc6f66bb Nov 24 09:57:29 raspoty ntpd[851]: receive: Unexpected origin timestamp 0xeaed68f8.be32de60 does not match aorg 0000000000.00000000 from server@5.196.160.139 xmt 0xeaed68f9.bdd6c16a Nov 24 09:57:30 raspoty volumio[798]: info: Applying required configuration parameters for plugin randomizer Nov 24 09:57:30 raspoty volumio[798]: info: Loading i18n strings for locale fr Nov 24 09:57:30 raspoty volumio[798]: Updating browse sources language Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 24 09:57:30 raspoty volumio[798]: Starting albumart workers Nov 24 09:57:30 raspoty volumio[798]: Starting albumart workers Nov 24 09:57:30 raspoty volumio[798]: Starting albumart workers Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::initPlayerControls Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 24 09:57:30 raspoty volumio[798]: Express server listening on port 3000 Nov 24 09:57:30 raspoty volumio[798]: [Metrics] WebUI: 9s 38.26ms Nov 24 09:57:30 raspoty volumio[798]: info: CoreStateMachine::resetVolumioState Nov 24 09:57:30 raspoty volumio[798]: info: CoreStateMachine::getcurrentVolume Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::volumioRetrievevolume Nov 24 09:57:30 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 09:57:30 raspoty volumio[798]: info: Volumio Network Manager: Network status updated: 1 Nov 24 09:57:30 raspoty volumio[798]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control 'HDMI',0 Nov 24 09:57:30 raspoty volumio[798]: info: Cannot mount NAS Playlist at system boot, trial number 1 ,retrying in 5 seconds Nov 24 09:57:31 raspoty volumio-remote-updater[537]: [2024-11-24 09:57:31] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1732438646 101 Nov 24 09:57:31 raspoty volumio[798]: 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 24 09:57:31 raspoty volumio[798]: info: VolumeController:: Volume=undefined Mute =false Nov 24 09:57:31 raspoty volumio[798]: info: CoreStateMachine::pushState Nov 24 09:57:31 raspoty volumio[798]: info: CorePlayQueue::getTrack 0 Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::volumioPushState Nov 24 09:57:31 raspoty volumio[798]: info: CoreStateMachine::updateTrackBlock Nov 24 09:57:31 raspoty volumio[798]: info: CorePlayQueue::getTrackBlock Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::volumioRetrievevolume Nov 24 09:57:31 raspoty volumio[798]: info: Reloading queue from file Nov 24 09:57:31 raspoty volumio[798]: info: CoreStateMachine::setRepeat false single undefined Nov 24 09:57:31 raspoty volumio[798]: info: CoreStateMachine::pushState Nov 24 09:57:31 raspoty volumio[798]: info: CorePlayQueue::getTrack 0 Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::volumioPushState Nov 24 09:57:31 raspoty volumio[798]: info: CoreStateMachine::setRandom true Nov 24 09:57:31 raspoty volumio[798]: info: CoreStateMachine::pushState Nov 24 09:57:31 raspoty volumio[798]: info: CorePlayQueue::getTrack 0 Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::volumioPushState Nov 24 09:57:31 raspoty volumio[798]: info: Setting Device type: Raspberry PI Nov 24 09:57:31 raspoty volumio[798]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control 'HDMI',0 Nov 24 09:57:31 raspoty volumio[798]: info: Completed loading Core Plugins Nov 24 09:57:31 raspoty volumio[798]: info: Preparing to generate the ALSA configuration file Nov 24 09:57:31 raspoty volumio[798]: info: Discovery: adding e10fb0a0-ba5c-43b5-99d7-bb3f6ca9a23c Nov 24 09:57:31 raspoty volumio[798]: info: Discovery: Found device Raspoty Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::volumioGetState Nov 24 09:57:31 raspoty volumio[798]: info: CorePlayQueue::getTrack 0 Nov 24 09:57:31 raspoty volumio[798]: info: VolumeController:: Volume=undefined Mute =false Nov 24 09:57:31 raspoty volumio[798]: info: CoreStateMachine::pushState Nov 24 09:57:31 raspoty volumio[798]: info: CorePlayQueue::getTrack 0 Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::volumioPushState Nov 24 09:57:31 raspoty volumio[798]: info: Asound.conf file unchanged, so no further update is needed Nov 24 09:57:31 raspoty volumio[798]: info: Output device has changed, restarting MPD Nov 24 09:57:31 raspoty volumio[798]: info: ___________ START PLUGINS ___________ Nov 24 09:57:31 raspoty sudo[1137]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 24 09:57:31 raspoty sudo[1137]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 09:57:31 raspoty sudo[1137]: pam_unix(sudo:session): session closed for user root Nov 24 09:57:31 raspoty volumio[798]: info: ControllerMpd::onStart: Initializing MPD Nov 24 09:57:31 raspoty sudo[1139]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 24 09:57:31 raspoty sudo[1139]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 09:57:31 raspoty volumio[798]: info: Creating MPD Configuration file Nov 24 09:57:31 raspoty systemd[1]: Stopping Music Player Daemon... Nov 24 09:57:31 raspoty sudo[1143]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 24 09:57:31 raspoty sudo[1143]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 24 09:57:31 raspoty volumio[798]: info: [1732438651591] CoreMusicLibrary::Adding element Last_100 Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 24 09:57:31 raspoty sudo[1143]: pam_unix(sudo:session): session closed for user root Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 24 09:57:31 raspoty volumio[798]: info: [1732438651599] CoreMusicLibrary::Adding element Webradio Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 24 09:57:31 raspoty sudo[1145]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 24 09:57:31 raspoty sudo[1145]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 09:57:31 raspoty volumio[798]: info: Initializing BBC Radios Nov 24 09:57:31 raspoty systemd[1]: mpd.service: Succeeded. Nov 24 09:57:31 raspoty systemd[1]: Stopped Music Player Daemon. Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 09:57:31 raspoty volumio[798]: info: Creating Spotify config file Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:31 raspoty systemd[1]: Starting Music Player Daemon... Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 24 09:57:31 raspoty volumio[798]: info: [1732438651902] CoreMusicLibrary::Adding element Randomizer Nov 24 09:57:31 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 24 09:57:31 raspoty volumio[798]: Cannot find translation for source Randomizer Nov 24 09:57:31 raspoty sudo[1158]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 24 09:57:31 raspoty sudo[1158]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 09:57:31 raspoty volumio[798]: info: Volumio Calling Home Nov 24 09:57:31 raspoty sudo[1158]: pam_unix(sudo:session): session closed for user root Nov 24 09:57:32 raspoty volumio[798]: info: MPD Permissions set Nov 24 09:57:32 raspoty volumio[798]: info: MPD Permissions set Nov 24 09:57:32 raspoty volumio[798]: info: Spotify config file written Nov 24 09:57:32 raspoty sudo[1165]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 24 09:57:32 raspoty sudo[1165]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 09:57:32 raspoty volumio[798]: 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 24 09:57:32 raspoty volumio[798]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty systemd[1]: Started go-librespot Daemon. Nov 24 09:57:32 raspoty go-librespot[1167]: Librespot-go daemon starting... Nov 24 09:57:32 raspoty sudo[1165]: pam_unix(sudo:session): session closed for user root Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 09:57:32 raspoty volumio[798]: info: No need to fix Spotify hosts Nov 24 09:57:32 raspoty volumio[798]: info: Volumio called home Nov 24 09:57:32 raspoty volumio[798]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 24 09:57:32 raspoty volumio[798]: SPOTIFY: BQABBL-CwfzKiKt1IG3D8JU69tYU8msXkZvvoYmKEPoRa3koNTb4D8ksp-0Hr78VWcwKhuAXpqRH0OkXAlkKvQKOQTmqst4saR6dEOdQmNoHyokFjnyXcz_pq1rKxk-e-kdHHxFuOZRnnMaHif1rjyA6S2Urgs8tR-lKqj_CuUClJgp9ZrLGuZajM1pUwAD0AxU2BYiEtw2OcJY-7TM0hTTpPX8yTTXDxaE_gIBlR_OCLE0lUz_XWbUn74KgEMpj2idpO89RO1T9i78 Nov 24 09:57:32 raspoty volumio[798]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 24 09:57:32 raspoty volumio[798]: info: New Spotify access token = BQABBL-CwfzKiKt1IG3D8JU69tYU8msXkZvvoYmKEPoRa3koNTb4D8ksp-0Hr78VWcwKhuAXpqRH0OkXAlkKvQKOQTmqst4saR6dEOdQmNoHyokFjnyXcz_pq1rKxk-e-kdHHxFuOZRnnMaHif1rjyA6S2Urgs8tR-lKqj_CuUClJgp9ZrLGuZajM1pUwAD0AxU2BYiEtw2OcJY-7TM0hTTpPX8yTTXDxaE_gIBlR_OCLE0lUz_XWbUn74KgEMpj2idpO89RO1T9i78 Nov 24 09:57:32 raspoty volumio[798]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::volumioGetState Nov 24 09:57:32 raspoty volumio[798]: info: CorePlayQueue::getTrack 0 Nov 24 09:57:32 raspoty go-librespot[1167]: time="2024-11-24T09:57:32+01:00" level=info msg="generated new device id: 8f57ede8df922966289d91866339fb3532fea559" Nov 24 09:57:32 raspoty go-librespot[1167]: time="2024-11-24T09:57:32+01:00" level=debug msg="stored credentials found for xwbwcha2azo5cepmlnbddvg9a" Nov 24 09:57:32 raspoty volumio[798]: 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"} Nov 24 09:57:32 raspoty volumio[798]: info: Spotify Successfully logged in Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 24 09:57:32 raspoty volumio[798]: info: [1732438652682] CoreMusicLibrary::Adding element Spotify Nov 24 09:57:32 raspoty volumio[798]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 24 09:57:32 raspoty volumio[798]: Cannot find translation for source Randomizer Nov 24 09:57:32 raspoty volumio[798]: Cannot find translation for source Spotify Nov 24 09:57:32 raspoty go-librespot[1167]: time="2024-11-24T09:57:32+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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 24 09:57:32 raspoty go-librespot[1167]: time="2024-11-24T09:57:32+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 24 09:57:32 raspoty go-librespot[1167]: time="2024-11-24T09:57:32+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 24 09:57:32 raspoty go-librespot[1167]: time="2024-11-24T09:57:32+01:00" level=debug msg="zeroconf server listening on port 38139" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="obtained new client token: AAD/Ykx2uzARtw5o49cYnzd/wpYDr6+QqK3Ck0NUHkjf4UBAqShDKM7/vwua+niYAthjx7hv5/M8CucFWos4f4w4oGljDyCnUgmEurjx+vlGqWYrcGKr1rQ3L7ufAZmJJE4dlVpInk7/rfdda8+gXrt7ALynO/ujHLF8J5Ij8eAFYigMyAyzzv6QDrckcgEJCsPVk9Qm9grlGgJgdFEAKaHDXUj+USyMm4Q0gezGucXxbm9WWxRw6cB6HzQ=" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=info msg="connected to ap-gew1.spotify.com:4070" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="completed keyexchange" Nov 24 09:57:33 raspoty mpd[1161]: Nov 24 09:57 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 24 09:57:33 raspoty systemd[1]: Started Music Player Daemon. Nov 24 09:57:33 raspoty sudo[1139]: pam_unix(sudo:session): session closed for user root Nov 24 09:57:33 raspoty sudo[1145]: pam_unix(sudo:session): session closed for user root Nov 24 09:57:33 raspoty volumio[798]: info: Completed starting Core Plugins Nov 24 09:57:33 raspoty volumio[798]: info: ------------------------------------------- Nov 24 09:57:33 raspoty volumio[798]: info: ----- MyVolumio plugins startup ---- Nov 24 09:57:33 raspoty volumio[798]: info: ------------------------------------------- Nov 24 09:57:33 raspoty volumio[798]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 24 09:57:33 raspoty volumio[798]: error: MPD error: The expression evaluated to a falsy value: Nov 24 09:57:33 raspoty volumio[798]: assert.ok(self.idling) Nov 24 09:57:33 raspoty volumio[798]: error: The expression evaluated to a falsy value: Nov 24 09:57:33 raspoty volumio[798]: assert.ok(self.idling) Nov 24 09:57:33 raspoty volumio[798]: info: MPD running with PID1161 Nov 24 09:57:33 raspoty volumio[798]: ,establishing connection Nov 24 09:57:33 raspoty volumio[798]: error: updateQueue error: null Nov 24 09:57:33 raspoty volumio[798]: error: updateQueue error: null Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="completed challenge" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="authenticated as xwbwcha2azo5cepmlnbddvg9a" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="authenticated as xwbwcha2azo5cepmlnbddvg9a" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="dealer connection opened" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="initializing zeroconf session, username: xwbwcha2azo5cepmlnbddvg9a" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="autoplay enabled: false" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="received connection id: OWFkOWFiYjMtNWQ1Zi00ZTM2LWE2YjMtODg0NTEwYzMwYWUzK2RlYWxlcit0Y3A6Ly8wYWNhNDFjNS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArNTcwRkEzNzFBOEVGMUY5RkFCODRCQzEyMjBERDI0QURBMzM0NzI1RDAyQjcwNTZEMDQwNjVDOUU2NkZCNDU0QQ==" Nov 24 09:57:33 raspoty go-librespot[1167]: time="2024-11-24T09:57:33+01:00" level=debug msg="put connect state because NEW_DEVICE" Nov 24 09:57:35 raspoty volumio[798]: info: go-librespot daemon successfully initialized Nov 24 09:57:36 raspoty sudo[1203]: 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 Nov 24 09:57:36 raspoty sudo[1203]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 09:57:36 raspoty kernel: CIFS: Attempting to mount //192.168.0.33/Musique Nov 24 09:57:36 raspoty sudo[1203]: pam_unix(sudo:session): session closed for user root Nov 24 09:57:36 raspoty volumio[798]: info: Cannot mount NAS Playlist at system boot, trial number 2 ,retrying in 5 seconds Nov 24 09:57:36 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 Nov 24 09:57:36 raspoty kernel: CIFS: VFS: cifs_mount failed w/return code = -95 Nov 24 09:57:38 raspoty volumio[798]: info: Initializing connection to go-librespot Websocket Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="handling transfer player command from bfc3d5019f48115d3edabeb833e01ab974674daa" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="new websocket client" Nov 24 09:57:38 raspoty volumio[798]: info: Connection to go-librespot Websocket established Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="resolved context of track" uri="spotify:album:3e9ROqDGRq3Mt1bqksn5Qk" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=trace msg="fetched new page 0 with 100 items (list: 100)" uri="spotify:album:3e9ROqDGRq3Mt1bqksn5Qk" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="shuffled context with seed 2079893520508552605 (len: 100, keep: 91)" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="loading track (paused: false, position: 27616ms)" uri="spotify:track:2duRqLu8SHCIMeAxl2YnMU" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=trace msg="emitting websocket event: will_play" Nov 24 09:57:38 raspoty volumio[798]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2duRqLu8SHCIMeAxl2YnMU","play_origin":"playlist"}} Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="selected format OGG_VORBIS_320 (19ee0fdbc70a41b2f3153f891e2eb904024d85f1)" uri="spotify:track:2duRqLu8SHCIMeAxl2YnMU" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="requested aes key for file 19ee0fdbc70a41b2f3153f891e2eb904024d85f1, gid: 2duRqLu8SHCIMeAxl2YnMU" Nov 24 09:57:38 raspoty volumio[798]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1688" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="fetched first chunk of 8, total size is 4144489 bytes" uri="spotify:track:2duRqLu8SHCIMeAxl2YnMU" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="fetched chunk 1/7, size: 524288" uri="spotify:track:2duRqLu8SHCIMeAxl2YnMU" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:2duRqLu8SHCIMeAxl2YnMU" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=trace msg="seek to 27616ms (diff: 53ms, samples: 1217865, bytes: 835788)" uri="spotify:track:2duRqLu8SHCIMeAxl2YnMU" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="fetched chunk 3/7, size: 524288" uri="spotify:track:2duRqLu8SHCIMeAxl2YnMU" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+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" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="created new output device" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=info msg="loaded track \"Also sprach Zarathustra, Op. 30, TrV 176: Richard STRAUSS : Ainsi parlait Zarathoustra, op.30 1Introduction\" (paused: false, position: 27616ms, duration: 119466ms, prefetched: false)" uri="spotify:track:2duRqLu8SHCIMeAxl2YnMU" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="fetched chunk 2/7, size: 524288" uri="spotify:track:2duRqLu8SHCIMeAxl2YnMU" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="fetched chunk 4/7, size: 524288" uri="spotify:track:2duRqLu8SHCIMeAxl2YnMU" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=trace msg="scheduling prefetch in 62s" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=trace msg="emitting websocket event: metadata" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=trace msg="emitting websocket event: active" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="sending successful reply for dealer request" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 24 09:57:38 raspoty volumio[798]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2duRqLu8SHCIMeAxl2YnMU","name":"Also sprach Zarathustra, Op. 30, TrV 176: Richard STRAUSS : Ainsi parlait Zarathoustra, op.30 1Introduction","artist_names":["Richard Strauss","Wiener Philharmoniker","Lorin Maazel"],"album_name":"Les 100 chefs-d'oeuvre de la musique classique","album_cover_url":"https://i.scdn.co/image/ab67616d00001e023bcfbc7361beaaffedac2466","position":27616,"duration":119466,"release_date":"year:2006 month:1 day:1","track_number":1,"disc_number":1}} Nov 24 09:57:38 raspoty volumio[798]: SPOTIFY: received: {"type":"active","data":null} Nov 24 09:57:38 raspoty volumio[798]: info: Aligning Spotify Volume to Volumio Volume Nov 24 09:57:38 raspoty volumio[798]: info: CoreCommandRouter::volumioGetState Nov 24 09:57:38 raspoty volumio[798]: info: CorePlayQueue::getTrack 0 Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1288" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 24 09:57:38 raspoty go-librespot[1167]: time="2024-11-24T09:57:38+01:00" level=trace msg="emitting websocket event: playing" Nov 24 09:57:38 raspoty volumio[798]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2duRqLu8SHCIMeAxl2YnMU","play_origin":"playlist"}} Nov 24 09:57:38 raspoty volumio[798]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 24 09:57:38 raspoty volumio[798]: TypeError: Cannot read property 'service' of undefined Nov 24 09:57:38 raspoty volumio[798]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Nov 24 09:57:38 raspoty volumio[798]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Nov 24 09:57:38 raspoty volumio[798]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Nov 24 09:57:38 raspoty volumio[798]: at WebSocket.emit (events.js:315:20) Nov 24 09:57:38 raspoty volumio[798]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Nov 24 09:57:38 raspoty volumio[798]: at Receiver.emit (events.js:315:20) Nov 24 09:57:38 raspoty volumio[798]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Nov 24 09:57:38 raspoty volumio[798]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Nov 24 09:57:38 raspoty volumio[798]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Nov 24 09:57:38 raspoty volumio[798]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Nov 24 09:57:38 raspoty volumio[798]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 24 09:57:39 raspoty sudo[1218]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-24 09:56 Nov 24 09:57:39 raspoty sudo[1218]: 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"