-- Logs begin at Thu 2019-02-14 02:11:59 PST, end at Tue 2024-11-26 16:21:00 PST. -- Nov 26 16:20:00 volumio bthelper[637]: Changing power off succeeded Nov 26 16:20:00 volumio sh[536]: eth0: soliciting an IPv6 router Nov 26 16:20:00 volumio dhcpcd[585]: eth0: soliciting an IPv6 router Nov 26 16:20:00 volumio volumio-remote-updater[609]: [2024-11-26 16:20:00] [info] asio async_connect error: system:111 (Connection refused) Nov 26 16:20:00 volumio volumio-remote-updater[609]: [2024-11-26 16:20:00] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Nov 26 16:20:00 volumio volumio-remote-updater[609]: [2024-11-26 16:20:00] [error] handle_connect error: Underlying Transport Error Nov 26 16:20:00 volumio bthelper[637]: [CHG] Controller D8:3A:DD:2C:C8:AC Class: 0x0000041c Nov 26 16:20:00 volumio bthelper[637]: Changing power on succeeded Nov 26 16:20:00 volumio ifplugd(eth0)[804]: Link beat detected. Nov 26 16:20:00 volumio volumio-time-update[622]: volumio-time-update-util: Fetching time from Volumio... Nov 26 16:20:00 volumio sh[536]: eth0: offered 192.168.1.29 from 192.168.1.1 Nov 26 16:20:00 volumio dhcpcd[585]: eth0: offered 192.168.1.29 from 192.168.1.1 Nov 26 16:20:00 volumio volumio-time-update[622]: volumio-time-update-util: Date not found in response Nov 26 16:20:00 volumio volumio-time-update[622]: volumio-time-update-util: Retrying in 5 seconds... Nov 26 16:20:00 volumio ifplugd(eth0)[804]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Nov 26 16:20:00 volumio ifplugd(eth0)[804]: client: ifup: waiting for lock on /run/network/ifstate.eth0 Nov 26 16:20:00 volumio sh[536]: eth0: probing address 192.168.1.29/24 Nov 26 16:20:00 volumio dhcpcd[585]: eth0: probing address 192.168.1.29/24 Nov 26 16:20:00 volumio ntpd[785]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Nov 26 16:20:01 volumio mpd[794]: Nov 26 16:20 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 26 16:20:01 volumio systemd[1]: Started Music Player Daemon. Nov 26 16:20:01 volumio mpd_monitor.sh[626]: MPD restarted due to no mpc output. Nov 26 16:20:02 volumio sudo[844]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:02 volumio wireless.js[623]: SETTING APPROPRIATE REG DOMAIN: US Nov 26 16:20:02 volumio sudo[870]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up Nov 26 16:20:02 volumio sudo[870]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:02 volumio sudo[870]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:02 volumio sudo[872]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set US Nov 26 16:20:02 volumio sudo[872]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:02 volumio sudo[872]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:02 volumio wireless.js[623]: SUCCESSFULLY SET NEW REGDOMAIN: US Nov 26 16:20:02 volumio sudo[879]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Nov 26 16:20:02 volumio sudo[879]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:02 volumio sudo[879]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:02 volumio sudo[881]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Nov 26 16:20:02 volumio sudo[881]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:03 volumio sudo[881]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:03 volumio wireless.js[623]: Hotspot is disabled, not starting it Nov 26 16:20:03 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Nov 26 16:20:03 volumio systemd[1]: wireless.service: Succeeded. Nov 26 16:20:03 volumio systemd[1]: Started Wireless Services. Nov 26 16:20:03 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Nov 26 16:20:03 volumio systemd[1]: Started Volumio Backend Module. Nov 26 16:20:03 volumio systemd[1]: Started Volumio Cpu Tweaker. Nov 26 16:20:03 volumio volumio-cpu-tweak[888]: Setting RT Priority for mpd Nov 26 16:20:03 volumio volumio-cpu-tweak[888]: Setting MPD Affinity Nov 26 16:20:03 volumio volumio-cpu-tweak[888]: pid 794's current affinity mask: f Nov 26 16:20:03 volumio volumio-cpu-tweak[888]: pid 794's new affinity mask: 3 Nov 26 16:20:03 volumio volumio-cpu-tweak[888]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Nov 26 16:20:03 volumio volumio-cpu-tweak[888]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Nov 26 16:20:03 volumio systemd[1]: volumio_cpu_tweak.service: Succeeded. Nov 26 16:20:05 volumio volumio-time-update[622]: volumio-time-update-util: Fetching time from Volumio... Nov 26 16:20:05 volumio sh[536]: eth0: leased 192.168.1.29 for 86400 seconds Nov 26 16:20:05 volumio dhcpcd[585]: eth0: leased 192.168.1.29 for 86400 seconds Nov 26 16:20:05 volumio avahi-daemon[604]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.29. Nov 26 16:20:05 volumio avahi-daemon[604]: New relevant interface eth0.IPv4 for mDNS. Nov 26 16:20:05 volumio volumio-time-update[622]: volumio-time-update-util: Date not found in response Nov 26 16:20:05 volumio volumio-time-update[622]: volumio-time-update-util: Retrying in 5 seconds... Nov 26 16:20:05 volumio sh[536]: eth0: adding route to 192.168.1.0/24 Nov 26 16:20:05 volumio sh[536]: eth0: adding default route via 192.168.1.1 Nov 26 16:20:05 volumio avahi-daemon[604]: Registering new address record for 192.168.1.29 on eth0.IPv4. Nov 26 16:20:05 volumio dhcpcd[585]: eth0: adding route to 192.168.1.0/24 Nov 26 16:20:05 volumio dhcpcd[585]: eth0: adding default route via 192.168.1.1 Nov 26 16:20:05 volumio sh[536]: forked to background, child pid 929 Nov 26 16:20:05 volumio dhcpcd[585]: forked to background, child pid 929 Nov 26 16:20:05 volumio ifplugd(eth0)[804]: client: ifup: interface eth0 already configured Nov 26 16:20:05 volumio sh[536]: eth0=eth0 Nov 26 16:20:05 volumio ifplugd(eth0)[804]: Program executed successfully. Nov 26 16:20:06 volumio ntpd[785]: Listen normally on 3 eth0 192.168.1.29:123 Nov 26 16:20:06 volumio ntpd[785]: new interface(s) found: waking up resolver Nov 26 16:20:06 volumio volumio[887]: info: ------------------------------------------- Nov 26 16:20:06 volumio volumio[887]: info: ----- Volumio3 ---- Nov 26 16:20:06 volumio volumio[887]: info: ------------------------------------------- Nov 26 16:20:06 volumio volumio[887]: info: ----- System startup ---- Nov 26 16:20:06 volumio volumio[887]: info: ------------------------------------------- Nov 26 16:20:07 volumio volumio-remote-updater[609]: [2024-11-26 16:20:07] [connect] Successful connection Nov 26 16:20:08 volumio nmbd[779]: [2024/11/26 16:20:08.118986, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 26 16:20:08 volumio nmbd[779]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Nov 26 16:20:08 volumio systemd[1]: Started Samba NMB Daemon. Nov 26 16:20:08 volumio volumio[887]: info: MYVOLUMIO Environment detected Nov 26 16:20:08 volumio systemd[1]: Starting Samba Winbind Daemon... Nov 26 16:20:08 volumio volumio[887]: info: Plugin folders cleanup Nov 26 16:20:08 volumio volumio[887]: info: Scanning into folder /volumio/app/plugins/ Nov 26 16:20:08 volumio volumio[887]: info: Scanning category audio_interface Nov 26 16:20:08 volumio volumio[887]: info: Scanning category miscellanea Nov 26 16:20:08 volumio volumio[887]: info: Scanning category music_service Nov 26 16:20:08 volumio volumio[887]: info: Scanning category plugins.json Nov 26 16:20:08 volumio volumio[887]: info: Scanning category system_controller Nov 26 16:20:08 volumio volumio[887]: info: Scanning category user_interface Nov 26 16:20:08 volumio volumio[887]: info: Scanning into folder /data/plugins/ Nov 26 16:20:08 volumio volumio[887]: info: Scanning category music_service Nov 26 16:20:08 volumio volumio[887]: info: Plugin folders cleanup completed Nov 26 16:20:08 volumio volumio[887]: info: ------------------------------------------- Nov 26 16:20:08 volumio volumio[887]: info: ----- Core plugins startup ---- Nov 26 16:20:08 volumio volumio[887]: info: ------------------------------------------- Nov 26 16:20:08 volumio volumio[887]: info: Loading plugins from folder /volumio/app/plugins/ Nov 26 16:20:08 volumio volumio[887]: info: Adding plugin upnp to MyMusic Plugins Nov 26 16:20:08 volumio volumio[887]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 26 16:20:08 volumio volumio[887]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 26 16:20:08 volumio volumio[887]: info: Loading plugins from folder /data/plugins/ Nov 26 16:20:08 volumio volumio[887]: info: Loading plugin "system"... Nov 26 16:20:08 volumio volumio[887]: info: Loading plugin "appearance"... Nov 26 16:20:08 volumio winbindd[965]: [2024/11/26 16:20:08.600816, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Nov 26 16:20:08 volumio winbindd[965]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Nov 26 16:20:09 volumio winbindd[965]: [2024/11/26 16:20:09.599806, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 26 16:20:09 volumio winbindd[965]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Nov 26 16:20:09 volumio systemd[1]: Started Samba Winbind Daemon. Nov 26 16:20:09 volumio systemd[1]: Starting Samba SMB Daemon... Nov 26 16:20:10 volumio volumio-time-update[622]: volumio-time-update-util: Fetching time from Volumio... Nov 26 16:20:10 volumio systemd[1]: Started Samba SMB Daemon. Nov 26 16:20:10 volumio smbd[973]: [2024/11/26 16:20:10.621812, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 26 16:20:10 volumio smbd[973]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Nov 26 16:20:10 volumio volumio-time-update[622]: volumio-time-update-util: Setting system time to: 2024-11-26 16:20:43 Nov 26 16:20:10 volumio sudo[986]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2024-11-26 16:20:43 Nov 26 16:20:10 volumio sudo[986]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:10 volumio dbus-daemon[612]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.10' (uid=0 pid=987 comm="timedatectl set-time 2024-11-26 16:20:43 ") Nov 26 16:20:11 volumio systemd[1]: Starting Time & Date Service... Nov 26 16:20:11 volumio dbus-daemon[612]: [system] Successfully activated service 'org.freedesktop.timedate1' Nov 26 16:20:11 volumio systemd[1]: Started Time & Date Service. Nov 26 16:20:43 volumio systemd-timedated[988]: Changed local time to Tue Nov 26 16:20:43 2024 Nov 26 16:20:43 volumio sudo[986]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:43 volumio volumio-time-update[622]: volumio-time-update-util: System time updated successfully. Nov 26 16:20:43 volumio systemd[1]: Started Volumio Time Update Utility. Nov 26 16:20:43 volumio systemd[1]: Reached target Multi-User System. Nov 26 16:20:43 volumio systemd[1]: Reached target Graphical Interface. Nov 26 16:20:43 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Nov 26 16:20:43 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Nov 26 16:20:43 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Nov 26 16:20:43 volumio systemd[1]: Startup finished in 13.791s (kernel) + 23.103s (userspace) = 36.895s. Nov 26 16:20:43 volumio volumio[887]: info: Loading plugin "network"... Nov 26 16:20:43 volumio volumio[887]: info: Refreshing Cached IP Addresses Nov 26 16:20:43 volumio sudo[994]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 26 16:20:43 volumio sudo[994]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:43 volumio sudo[994]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:43 volumio sudo[996]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 26 16:20:43 volumio sudo[996]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:43 volumio sudo[996]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:43 volumio volumio[887]: info: Loading plugin "services"... Nov 26 16:20:43 volumio volumio[887]: info: Loading plugin "alsa_controller"... Nov 26 16:20:43 volumio sudo[1005]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Nov 26 16:20:43 volumio sudo[1005]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:43 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 26 16:20:43 volumio volumio[887]: info: Loading plugin "wizard"... Nov 26 16:20:43 volumio volumio[887]: info: Loading plugin "networkfs"... Nov 26 16:20:43 volumio volumio[887]: info: Starting Udev Watcher for removable devices Nov 26 16:20:43 volumio sudo[1022]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //Mac-mini.local/M1 data /mnt/NAS/Mac_Mini Nov 26 16:20:43 volumio sudo[1022]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:43 volumio volumio[887]: info: Ignoring mount for partition: boot Nov 26 16:20:43 volumio volumio[887]: info: Ignoring mount for partition: volumio Nov 26 16:20:43 volumio volumio[887]: info: Ignoring mount for partition: volumio_data Nov 26 16:20:43 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 26 16:20:43 volumio volumio[887]: info: Loading plugin "volumio_command_line_client"... Nov 26 16:20:43 volumio volumio[887]: info: Loading plugin "upnp"... Nov 26 16:20:43 volumio volumio[887]: info: [1732666843754] Starting Upmpd Daemon Nov 26 16:20:43 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 26 16:20:43 volumio volumio[887]: info: Loading plugin "my_music"... Nov 26 16:20:43 volumio volumio[887]: info: Loading plugin "mpd"... Nov 26 16:20:44 volumio kernel: Key type cifs.spnego registered Nov 26 16:20:44 volumio kernel: Key type cifs.idmap registered Nov 26 16:20:44 volumio kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Nov 26 16:20:44 volumio kernel: CIFS: Attempting to mount //Mac-mini.local/M1 data Nov 26 16:20:44 volumio volumio[887]: info: Loading plugin "upnp_browser"... Nov 26 16:20:44 volumio sudo[1022]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:44 volumio kernel: CIFS: Status code returned 0xc000006d STATUS_LOGON_FAILURE Nov 26 16:20:44 volumio kernel: CIFS: VFS: \\Mac-mini.local Send error in SessSetup = -13 Nov 26 16:20:44 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -13 Nov 26 16:20:45 volumio volumio[887]: info: Loading plugin "alarm-clock"... Nov 26 16:20:45 volumio volumio[887]: info: Loading plugin "airplay_emulation"... Nov 26 16:20:45 volumio volumio[887]: info: Starting Shairport Sync Nov 26 16:20:45 volumio volumio[887]: info: Loading plugin "last_100"... Nov 26 16:20:45 volumio volumio[887]: info: Loading plugin "webradio"... Nov 26 16:20:45 volumio volumio[887]: info: Loading plugin "i2s_dacs"... Nov 26 16:20:45 volumio volumio[887]: info: I2S DAC not set, start Auto-detection Nov 26 16:20:45 volumio volumio[887]: info: Loading plugin "volumiodiscovery"... Nov 26 16:20:45 volumio volumio[887]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 26 16:20:45 volumio volumio[887]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 26 16:20:45 volumio node[887]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 26 16:20:45 volumio volumio[887]: *** WARNING *** For more information see Nov 26 16:20:45 volumio volumio[887]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 26 16:20:45 volumio volumio[887]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 26 16:20:45 volumio volumio[887]: *** WARNING *** For more information see Nov 26 16:20:45 volumio node[887]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 26 16:20:45 volumio node[887]: *** WARNING *** For more information see Nov 26 16:20:45 volumio node[887]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 26 16:20:45 volumio node[887]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 26 16:20:45 volumio node[887]: *** WARNING *** For more information see Nov 26 16:20:45 volumio volumio[887]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 26 16:20:45 volumio volumio[887]: info: Discovery: Started advertising with name: Volumio Nov 26 16:20:45 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 26 16:20:45 volumio volumio[887]: info: Loading plugin "spop"... Nov 26 16:20:46 volumio sudo[1005]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:47 volumio volumio[887]: info: Loading plugin "ytmusic"... Nov 26 16:20:48 volumio volumio[887]: info: Loading plugin "outputs"... Nov 26 16:20:48 volumio volumio[887]: info: Loading plugin "albumart"... Nov 26 16:20:48 volumio volumio[887]: info: Plugin example_plugin is not enabled Nov 26 16:20:48 volumio volumio[887]: info: Loading plugin "inputs"... Nov 26 16:20:48 volumio volumio[887]: info: Loading plugin "updater_comm"... Nov 26 16:20:49 volumio volumio[887]: info: Plugin mpdemulation is not enabled Nov 26 16:20:49 volumio volumio[887]: info: Loading plugin "rest_api"... Nov 26 16:20:49 volumio volumio[887]: info: Loading plugin "websocket"... Nov 26 16:20:49 volumio volumio[887]: info: Starting Socket.io Server version 2.3.0 Nov 26 16:20:49 volumio volumio[887]: info: Loading i18n strings for locale en Nov 26 16:20:49 volumio volumio[887]: Updating browse sources language Nov 26 16:20:49 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 26 16:20:49 volumio volumio[887]: Forking 3 albumart workers Nov 26 16:20:49 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 26 16:20:49 volumio volumio[887]: info: CoreCommandRouter::initPlayerControls Nov 26 16:20:49 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:49 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:49 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:49 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:49 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:49 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:49 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:49 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:50 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 26 16:20:50 volumio volumio[887]: Express server listening on port 3000 Nov 26 16:20:50 volumio volumio[887]: [Metrics] WebUI: 12s 771.24ms Nov 26 16:20:50 volumio volumio[887]: info: CoreStateMachine::resetVolumioState Nov 26 16:20:50 volumio volumio[887]: info: CoreStateMachine::getcurrentVolume Nov 26 16:20:50 volumio volumio[887]: info: CoreCommandRouter::volumioRetrievevolume Nov 26 16:20:50 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 16:20:50 volumio volumio[887]: info: Cannot read play queue from file Nov 26 16:20:50 volumio volumio[887]: info: Volumio Network Manager: Network status updated: 1 Nov 26 16:20:50 volumio volumio[887]: info: Cannot mount NAS Mac_Mini at system boot, trial number 1 ,retrying in 5 seconds Nov 26 16:20:50 volumio volumio[887]: info: CoreStateMachine::setRepeat null single undefined Nov 26 16:20:50 volumio volumio[887]: info: CoreStateMachine::pushState Nov 26 16:20:50 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:50 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 26 16:20:50 volumio volumio[887]: info: CoreCommandRouter::volumioPushState Nov 26 16:20:50 volumio volumio[887]: info: CoreStateMachine::setRandom null Nov 26 16:20:50 volumio volumio[887]: info: CoreStateMachine::pushState Nov 26 16:20:50 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:50 volumio volumio[887]: info: CoreCommandRouter::volumioPushState Nov 26 16:20:50 volumio volumio[887]: info: Setting Device type: Raspberry PI Nov 26 16:20:50 volumio volumio[887]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Nov 26 16:20:50 volumio volumio[887]: info: USB Boot Capable - System SBC Revision found in cpuinfo: d03115 Nov 26 16:20:50 volumio volumio[887]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Nov 26 16:20:50 volumio volumio[887]: Starting albumart workers Nov 26 16:20:50 volumio volumio[887]: info: VolumeController:: Volume=59 Mute =false Nov 26 16:20:50 volumio volumio[887]: info: CoreStateMachine::pushState Nov 26 16:20:50 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:50 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 26 16:20:50 volumio volumio[887]: info: CoreCommandRouter::volumioPushState Nov 26 16:20:50 volumio volumio[887]: info: CoreStateMachine::updateTrackBlock Nov 26 16:20:50 volumio volumio[887]: info: CorePlayQueue::getTrackBlock Nov 26 16:20:50 volumio volumio[887]: info: CoreCommandRouter::volumioRetrievevolume Nov 26 16:20:50 volumio volumio[887]: Starting albumart workers Nov 26 16:20:50 volumio volumio[887]: Starting albumart workers Nov 26 16:20:50 volumio volumio[887]: info: VolumeController:: Volume=59 Mute =false Nov 26 16:20:50 volumio volumio[887]: info: CoreStateMachine::pushState Nov 26 16:20:50 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:50 volumio volumio[887]: info: CoreCommandRouter::volumioPushState Nov 26 16:20:50 volumio volumio[887]: info: Completed loading Core Plugins Nov 26 16:20:50 volumio volumio[887]: info: Preparing to generate the ALSA configuration file Nov 26 16:20:50 volumio volumio[887]: info: Asound.conf file unchanged, so no further update is needed Nov 26 16:20:50 volumio volumio[887]: info: Output device has changed, restarting MPD Nov 26 16:20:51 volumio volumio[887]: info: Output device has changed, restarting Shairport Sync Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 16:20:51 volumio sudo[1091]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 26 16:20:51 volumio sudo[1091]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:51 volumio sudo[1091]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:51 volumio sudo[1093]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 26 16:20:51 volumio sudo[1093]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:51 volumio volumio[887]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 26 16:20:51 volumio volumio[887]: info: ___________ START PLUGINS ___________ Nov 26 16:20:51 volumio volumio[887]: info: ControllerMpd::onStart: Initializing MPD Nov 26 16:20:51 volumio volumio[887]: info: Creating MPD Configuration file Nov 26 16:20:51 volumio systemd[1]: Stopping Music Player Daemon... Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 26 16:20:51 volumio sudo[1100]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 26 16:20:51 volumio sudo[1100]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 26 16:20:51 volumio volumio[887]: info: [1732666851318] CoreMusicLibrary::Adding element Media Servers Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 26 16:20:51 volumio sudo[1100]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:51 volumio sudo[1102]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 26 16:20:51 volumio sudo[1102]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:51 volumio systemd[1]: mpd.service: Succeeded. Nov 26 16:20:51 volumio systemd[1]: Stopped Music Player Daemon. Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 16:20:51 volumio systemd[1]: Starting Music Player Daemon... Nov 26 16:20:51 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Nov 26 16:20:51 volumio systemd[1]: mpd.service: Succeeded. Nov 26 16:20:51 volumio systemd[1]: Stopped Music Player Daemon. Nov 26 16:20:51 volumio systemd[1]: Starting Music Player Daemon... Nov 26 16:20:51 volumio volumio[887]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 16:20:51 volumio sudo[1109]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 26 16:20:51 volumio sudo[1109]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:51 volumio sudo[1109]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:51 volumio volumio[887]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 26 16:20:51 volumio volumio[887]: info: [1732666851713] CoreMusicLibrary::Adding element Last_100 Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 26 16:20:51 volumio volumio[887]: info: [1732666851719] CoreMusicLibrary::Adding element Webradio Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 26 16:20:51 volumio volumio[887]: info: Initializing BBC Radios Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 16:20:51 volumio volumio[887]: info: Creating Spotify config file Nov 26 16:20:51 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 26 16:20:52 volumio volumio[887]: info: [1732666852041] CoreMusicLibrary::Adding element YouTube Music Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 26 16:20:52 volumio volumio[887]: Cannot find translation for source YouTube Music Nov 26 16:20:52 volumio volumio[887]: info: Volumio Calling Home Nov 26 16:20:52 volumio volumio[887]: info: Discovery: adding 5d13cfcf-fa82-434b-acd1-6d70a84850f8 Nov 26 16:20:52 volumio volumio[887]: info: Discovery: Found device Volumio Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::volumioGetState Nov 26 16:20:52 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:52 volumio volumio[887]: info: MPD Permissions set Nov 26 16:20:52 volumio volumio[887]: info: MPD Permissions set Nov 26 16:20:52 volumio volumio[887]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Nov 26 16:20:52 volumio volumio[887]: info: Spotify config file written Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:52 volumio sudo[1153]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 26 16:20:52 volumio sudo[1153]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 26 16:20:52 volumio systemd[1]: Started go-librespot Daemon. Nov 26 16:20:52 volumio volumio[887]: info: No need to fix Spotify hosts Nov 26 16:20:52 volumio go-librespot[1160]: Librespot-go daemon starting... Nov 26 16:20:52 volumio sudo[1153]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:52 volumio volumio[887]: info: Volumio called home Nov 26 16:20:52 volumio volumio[887]: info: CoreCommandRouter::volumioGetState Nov 26 16:20:52 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:52 volumio volumio[887]: info: Starting Shairport Sync Nov 26 16:20:52 volumio volumio[887]: info: Starting Shairport Sync Nov 26 16:20:52 volumio sudo[1171]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 26 16:20:52 volumio sudo[1171]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:52 volumio volumio[887]: info: Starting Shairport Sync Nov 26 16:20:52 volumio sudo[1173]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 26 16:20:52 volumio sudo[1173]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:52 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 26 16:20:52 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 26 16:20:52 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 26 16:20:52 volumio sudo[1179]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 26 16:20:52 volumio sudo[1179]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:52 volumio go-librespot[1160]: time="2024-11-26T16:20:52-08:00" level=info msg="generated new device id: 7f0121d568015b0551bc528398eb43e80f068334" Nov 26 16:20:52 volumio go-librespot[1160]: time="2024-11-26T16:20:52-08:00" level=debug msg="stored credentials found for sbisheff" Nov 26 16:20:52 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 26 16:20:52 volumio sudo[1171]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:53 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 26 16:20:53 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 26 16:20:53 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 26 16:20:53 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 26 16:20:53 volumio sudo[1173]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:53 volumio sudo[1179]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:53 volumio volumio[887]: info: Shairport-Sync Started Nov 26 16:20:53 volumio volumio[887]: Error adding Membership: Error: addMembership EINVAL Nov 26 16:20:53 volumio volumio[887]: info: Shairport-Sync Started Nov 26 16:20:53 volumio volumio[887]: info: Shairport-Sync Started Nov 26 16:20:53 volumio volumio[887]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 26 16:20:53 volumio mpd[1126]: Nov 26 16:20 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 26 16:20:53 volumio volumio[887]: SPOTIFY: BQBuofBnN2W2brThdkMdUezEduJiUM7FQqW8m-C80rDrXBJr1HgvKEbGpYy0GwdQViYjdT6lxJElJnQyF5AyrP7Qdfg9w-Zh6mnbRe1CH40fke363HKsGFkmPgnBpfNcK9REFLzutm4TEZzVukvluyiHvSANq95Fia-9iSFV8fGnK1IEDLqN7K-bMah8CmmEQVPduzVKPSRySN2E8CwBMxOOVt5FqIaDl0bLPWtP6FvCuNry0hd6stU4 Nov 26 16:20:53 volumio volumio[887]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 26 16:20:53 volumio systemd[1]: Started Music Player Daemon. Nov 26 16:20:53 volumio volumio[887]: info: New Spotify access token = BQBuofBnN2W2brThdkMdUezEduJiUM7FQqW8m-C80rDrXBJr1HgvKEbGpYy0GwdQViYjdT6lxJElJnQyF5AyrP7Qdfg9w-Zh6mnbRe1CH40fke363HKsGFkmPgnBpfNcK9REFLzutm4TEZzVukvluyiHvSANq95Fia-9iSFV8fGnK1IEDLqN7K-bMah8CmmEQVPduzVKPSRySN2E8CwBMxOOVt5FqIaDl0bLPWtP6FvCuNry0hd6stU4 Nov 26 16:20:53 volumio volumio[887]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 26 16:20:53 volumio sudo[1102]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:53 volumio sudo[1093]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:53 volumio go-librespot[1160]: time="2024-11-26T16:20:53-08:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 26 16:20:53 volumio go-librespot[1160]: time="2024-11-26T16:20:53-08:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 26 16:20:53 volumio go-librespot[1160]: time="2024-11-26T16:20:53-08:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 26 16:20:53 volumio volumio[887]: info: Completed starting Core Plugins Nov 26 16:20:53 volumio volumio[887]: info: ------------------------------------------- Nov 26 16:20:53 volumio volumio[887]: info: ----- MyVolumio plugins startup ---- Nov 26 16:20:53 volumio volumio[887]: info: ------------------------------------------- Nov 26 16:20:53 volumio volumio[887]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 26 16:20:53 volumio go-librespot[1160]: time="2024-11-26T16:20:53-08:00" level=debug msg="zeroconf server listening on port 41067" Nov 26 16:20:53 volumio sudo[1209]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 26 16:20:53 volumio sudo[1209]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:53 volumio sudo[1209]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:53 volumio sudo[1212]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 26 16:20:53 volumio sudo[1212]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:53 volumio sudo[1212]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:53 volumio go-librespot[1160]: time="2024-11-26T16:20:53-08:00" level=debug msg="obtained new client token: AACYjJ6K7xDuL5T49gBFVgAIEpu19W5MiiLpW0yTVBPbalrUEBZ09arEwUdI++yVgY4QZtclvZeFeDe4515ojE1KG+26ySW50YRfFnvEK7RWk9VK457aQv5Imi8KJlqzuXXwnrAOGa4ufX/19z0Nd+bpT07dX9KGPVdbpmL+O5wp4p7jtxiOXaDcP/RlvwpPq0+q/UBV4HrGVIjJKAbu5rMxIZsdxZGSC3sCtoa6J6t9uqpuQL82DMP8Mw==" Nov 26 16:20:53 volumio volumio[887]: error: MPD error: The expression evaluated to a falsy value: Nov 26 16:20:53 volumio volumio[887]: assert.ok(self.idling) Nov 26 16:20:53 volumio volumio[887]: error: The expression evaluated to a falsy value: Nov 26 16:20:53 volumio volumio[887]: assert.ok(self.idling) Nov 26 16:20:53 volumio volumio[887]: info: MPD running with PID1126 Nov 26 16:20:53 volumio volumio[887]: ,establishing connection Nov 26 16:20:53 volumio go-librespot[1160]: time="2024-11-26T16:20:53-08:00" level=info msg="connected to ap-guc3.spotify.com:4070" Nov 26 16:20:53 volumio sudo[1215]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 26 16:20:53 volumio sudo[1215]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:53 volumio volumio[887]: error: updateQueue error: null Nov 26 16:20:53 volumio sudo[1215]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:53 volumio sudo[1217]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 26 16:20:53 volumio sudo[1217]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:53 volumio go-librespot[1160]: time="2024-11-26T16:20:53-08:00" level=debug msg="completed keyexchange" Nov 26 16:20:53 volumio sudo[1217]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:54 volumio volumio[887]: error: updateQueue error: null Nov 26 16:20:54 volumio volumio[887]: verbose: New Socket.io Connection to 192.168.1.29 from 192.168.1.68 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.6 Safari/605.1.15 Engine version: 3 Transport: polling Total Clients: 2 Nov 26 16:20:54 volumio sudo[1221]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 26 16:20:54 volumio sudo[1221]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 26 16:20:54 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Nov 26 16:20:54 volumio sudo[1221]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::volumioGetVisibleSources Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::volumioGetState Nov 26 16:20:54 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Nov 26 16:20:54 volumio volumio[887]: info: Received Get System Info Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 26 16:20:54 volumio volumio[887]: info: Discovery: Getting this device information Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::volumioGetState Nov 26 16:20:54 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::volumioGetState Nov 26 16:20:54 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:54 volumio volumio[887]: info: Listing playlists Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 26 16:20:54 volumio volumio[887]: info: Upmpdcli Daemon Started Nov 26 16:20:54 volumio volumio-remote-updater[609]: [2024-11-26 16:20:54] [connect] Successful connection Nov 26 16:20:54 volumio volumio[887]: SPOTIFY: User informations: {"country":"US","display_name":"sbisheff","email":"sbisheff@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/sbisheff"},"followers":{"href":null,"total":21},"href":"https://api.spotify.com/v1/users/sbisheff","id":"sbisheff","images":[],"product":"premium","type":"user","uri":"spotify:user:sbisheff"} Nov 26 16:20:54 volumio volumio[887]: info: Spotify Successfully logged in Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 26 16:20:54 volumio volumio[887]: info: [1732666854355] CoreMusicLibrary::Adding element Spotify Nov 26 16:20:54 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 26 16:20:54 volumio volumio[887]: Cannot find translation for source YouTube Music Nov 26 16:20:54 volumio volumio[887]: Cannot find translation for source Spotify Nov 26 16:20:54 volumio volumio-remote-updater[609]: [2024-11-26 16:20:54] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1732666854 101 Nov 26 16:20:54 volumio volumio[887]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 3 Nov 26 16:20:54 volumio volumio[1223]: Generating RSA private key, 4096 bit long modulus (2 primes) Nov 26 16:20:54 volumio go-librespot[1160]: time="2024-11-26T16:20:54-08:00" level=debug msg="completed challenge" Nov 26 16:20:54 volumio go-librespot[1160]: time="2024-11-26T16:20:54-08:00" level=debug msg="authenticated as sbisheff" Nov 26 16:20:54 volumio go-librespot[1160]: time="2024-11-26T16:20:54-08:00" level=debug msg="authenticated as sbisheff" Nov 26 16:20:54 volumio go-librespot[1160]: time="2024-11-26T16:20:54-08:00" level=debug msg="dealer connection opened" Nov 26 16:20:54 volumio go-librespot[1160]: time="2024-11-26T16:20:54-08:00" level=debug msg="initializing zeroconf session, username: sbisheff" Nov 26 16:20:54 volumio go-librespot[1160]: time="2024-11-26T16:20:54-08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 26 16:20:54 volumio go-librespot[1160]: time="2024-11-26T16:20:54-08:00" level=debug msg="received connection id: ZGViZGQyZGQtZjgzNS00Yzk0LWFlNzktZDNkMzMwZmMzY2EyK2RlYWxlcit0Y3A6Ly8wYWNiZDkyNC5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArOTc0REVERTUwQkJFMDA2REY4RTEzMDNDREVDMDYyRDA4RjBCNjlFMjQxNUE2MjgwMDA3QzQxREQ2NUI1ODQ0RQ==" Nov 26 16:20:54 volumio go-librespot[1160]: time="2024-11-26T16:20:54-08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 26 16:20:55 volumio volumio[887]: info: CoreCommandRouter::volumioGetState Nov 26 16:20:55 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:55 volumio go-librespot[1160]: time="2024-11-26T16:20:55-08:00" level=debug msg="put connect state because NEW_DEVICE" Nov 26 16:20:55 volumio go-librespot[1160]: time="2024-11-26T16:20:55-08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 26 16:20:55 volumio go-librespot[1160]: time="2024-11-26T16:20:55-08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 26 16:20:55 volumio go-librespot[1160]: time="2024-11-26T16:20:55-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 26 16:20:55 volumio go-librespot[1160]: time="2024-11-26T16:20:55-08:00" level=debug msg="autoplay enabled: false" Nov 26 16:20:55 volumio sudo[1241]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //Mac-mini.local/M1 data /mnt/NAS/Mac_Mini Nov 26 16:20:55 volumio sudo[1241]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 16:20:55 volumio systemd[1]: systemd-fsckd.service: Succeeded. Nov 26 16:20:55 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 26 16:20:55 volumio volumio[887]: info: Received Get System Info Nov 26 16:20:55 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 26 16:20:55 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 26 16:20:55 volumio volumio[887]: info: Discovery: Getting this device information Nov 26 16:20:55 volumio volumio[887]: info: CoreCommandRouter::volumioGetState Nov 26 16:20:55 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:55 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 26 16:20:55 volumio volumio[887]: info: go-librespot daemon successfully initialized Nov 26 16:20:55 volumio kernel: CIFS: Attempting to mount //Mac-mini.local/M1 data Nov 26 16:20:55 volumio sudo[1241]: pam_unix(sudo:session): session closed for user root Nov 26 16:20:55 volumio volumio[887]: info: Cannot mount NAS Mac_Mini at system boot, trial number 2 ,retrying in 5 seconds Nov 26 16:20:55 volumio kernel: CIFS: Status code returned 0xc000006d STATUS_LOGON_FAILURE Nov 26 16:20:55 volumio kernel: CIFS: VFS: \\Mac-mini.local Send error in SessSetup = -13 Nov 26 16:20:55 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -13 Nov 26 16:20:55 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Nov 26 16:20:56 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Nov 26 16:20:56 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 26 16:20:56 volumio volumio[887]: info: Received Get System Info Nov 26 16:20:56 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 26 16:20:56 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 26 16:20:56 volumio volumio[887]: info: Discovery: Getting this device information Nov 26 16:20:56 volumio volumio[887]: info: CoreCommandRouter::volumioGetState Nov 26 16:20:56 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:56 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 26 16:20:56 volumio volumio[887]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Nov 26 16:20:58 volumio volumio[1223]: ...............++++ Nov 26 16:20:58 volumio go-librespot[1160]: time="2024-11-26T16:20:58-08:00" level=debug msg="handling transfer player command from a6a9becc880a8939354712d5031089d038043c20" Nov 26 16:20:58 volumio go-librespot[1160]: time="2024-11-26T16:20:58-08:00" level=debug msg="resolved context of track" uri="spotify:playlist:3I6v8C5LFPSE2pTATap8wv" Nov 26 16:20:58 volumio go-librespot[1160]: time="2024-11-26T16:20:58-08:00" level=trace msg="fetched new page 0 with 44 items (list: 44)" uri="spotify:playlist:3I6v8C5LFPSE2pTATap8wv" Nov 26 16:20:58 volumio go-librespot[1160]: time="2024-11-26T16:20:58-08:00" level=debug msg="shuffled context with seed 11877527423633381483 (len: 44, keep: 32)" Nov 26 16:20:58 volumio go-librespot[1160]: time="2024-11-26T16:20:58-08:00" level=debug msg="loading track (paused: false, position: 59878ms)" uri="spotify:track:2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:58 volumio volumio[887]: info: Initializing connection to go-librespot Websocket Nov 26 16:20:58 volumio go-librespot[1160]: time="2024-11-26T16:20:58-08:00" level=debug msg="new websocket client" Nov 26 16:20:58 volumio volumio[887]: info: Connection to go-librespot Websocket established Nov 26 16:20:58 volumio go-librespot[1160]: time="2024-11-26T16:20:58-08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 26 16:20:58 volumio go-librespot[1160]: time="2024-11-26T16:20:58-08:00" level=trace msg="emitting websocket event: will_play" Nov 26 16:20:58 volumio volumio[887]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2PorsG3wc8DeFa5MRNi7jh","play_origin":"com.spotify.gaia"}} Nov 26 16:20:58 volumio volumio[887]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 26 16:20:58 volumio go-librespot[1160]: time="2024-11-26T16:20:58-08:00" level=debug msg="selected format OGG_VORBIS_320 (f4217990a2a91c08d699f2cfe04cdb77ff434097)" uri="spotify:track:2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:58 volumio go-librespot[1160]: time="2024-11-26T16:20:58-08:00" level=debug msg="requested aes key for file f4217990a2a91c08d699f2cfe04cdb77ff434097, gid: 2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:58 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Nov 26 16:20:58 volumio go-librespot[1160]: time="2024-11-26T16:20:58-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 26 16:20:58 volumio go-librespot[1160]: time="2024-11-26T16:20:58-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1332" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1110" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="fetched first chunk of 18, total size is 9115487 bytes" uri="spotify:track:2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="fetched chunk 6/17, size: 524288" uri="spotify:track:2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="fetched chunk 5/17, size: 524288" uri="spotify:track:2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="fetched chunk 4/17, size: 524288" uri="spotify:track:2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=trace msg="seek to 59878ms (diff: 190ms, samples: 2640619, bytes: 2243470)" uri="spotify:track:2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="fetched chunk 7/17, size: 524288" uri="spotify:track:2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="created new output device" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=info msg="loaded track \"El Infierno Está Cerca\" (paused: false, position: 59878ms, duration: 248995ms, prefetched: false)" uri="spotify:track:2PorsG3wc8DeFa5MRNi7jh" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=trace msg="scheduling prefetch in 159s" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=trace msg="emitting websocket event: metadata" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=trace msg="emitting websocket event: active" Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="sending successful reply for dealer request" Nov 26 16:20:59 volumio volumio[887]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2PorsG3wc8DeFa5MRNi7jh","name":"El Infierno Está Cerca","artist_names":["St. Vincent"],"album_name":"Todos Nacen Gritando","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027ed7d757c4b4243a49f4123e","position":59878,"duration":248995,"release_date":"year:2024 month:11 day:15","track_number":1,"disc_number":1}} Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 26 16:20:59 volumio go-librespot[1160]: time="2024-11-26T16:20:59-08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 26 16:20:59 volumio volumio[887]: SPOTIFY: received: {"type":"active","data":null} Nov 26 16:20:59 volumio volumio[887]: info: Aligning Spotify Volume to Volumio Volume Nov 26 16:20:59 volumio volumio[887]: info: CoreCommandRouter::volumioGetState Nov 26 16:20:59 volumio volumio[887]: info: CorePlayQueue::getTrack 0 Nov 26 16:20:59 volumio volumio[887]: info: Setting Spotify Volume from Volumio: 59 Nov 26 16:21:00 volumio go-librespot[1160]: time="2024-11-26T16:21:00-08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 26 16:21:00 volumio go-librespot[1160]: time="2024-11-26T16:21:00-08:00" level=trace msg="emitting websocket event: playing" Nov 26 16:21:00 volumio volumio[887]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2PorsG3wc8DeFa5MRNi7jh","play_origin":"com.spotify.gaia"}} Nov 26 16:21:00 volumio volumio[887]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 26 16:21:00 volumio volumio[887]: TypeError: Cannot read property 'service' of undefined Nov 26 16:21:00 volumio volumio[887]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Nov 26 16:21:00 volumio volumio[887]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Nov 26 16:21:00 volumio volumio[887]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Nov 26 16:21:00 volumio volumio[887]: at WebSocket.emit (events.js:315:20) Nov 26 16:21:00 volumio volumio[887]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Nov 26 16:21:00 volumio volumio[887]: at Receiver.emit (events.js:315:20) Nov 26 16:21:00 volumio volumio[887]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Nov 26 16:21:00 volumio volumio[887]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Nov 26 16:21:00 volumio volumio[887]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Nov 26 16:21:00 volumio volumio[887]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Nov 26 16:21:00 volumio volumio[887]: at writeOrBuffer (internal/streams/writable.js:358:12) Nov 26 16:21:00 volumio volumio[887]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Nov 26 16:21:00 volumio volumio[887]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Nov 26 16:21:00 volumio volumio[887]: at Socket.emit (events.js:315:20) Nov 26 16:21:00 volumio volumio[887]: at addChunk (internal/streams/readable.js:309:12) Nov 26 16:21:00 volumio volumio[887]: at readableAddChunk (internal/streams/readable.js:284:9) Nov 26 16:21:00 volumio volumio[887]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 26 16:21:00 volumio sudo[1259]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-26 16:20 Nov 26 16:21:00 volumio sudo[1259]: 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"