-- Logs begin at Thu 2019-02-14 18:12:00 CST, end at Sat 2025-06-21 08:04:53 CST. -- Jun 21 08:04:13 hjl systemd-timedated[920]: Changed local time to Sat Jun 21 08:04:13 2025 Jun 21 08:04:13 hjl sudo[918]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:13 hjl volumio-time-update[528]: volumio-time-update-util: System time updated successfully. Jun 21 08:04:13 hjl systemd[1]: Starting Daily apt download activities... Jun 21 08:04:13 hjl systemd[1]: Started Volumio Time Update Utility. Jun 21 08:04:13 hjl systemd[1]: Reached target Multi-User System. Jun 21 08:04:13 hjl systemd[1]: Reached target Graphical Interface. Jun 21 08:04:13 hjl systemd[1]: Starting Update UTMP about System Runlevel Changes... Jun 21 08:04:13 hjl systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jun 21 08:04:13 hjl systemd[1]: Started Update UTMP about System Runlevel Changes. Jun 21 08:04:13 hjl volumio-remote-updater[522]: [2025-06-21 08:04:13] [info] asio async_connect error: system:111 (Connection refused) Jun 21 08:04:13 hjl volumio-remote-updater[522]: [2025-06-21 08:04:13] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jun 21 08:04:13 hjl volumio-remote-updater[522]: [2025-06-21 08:04:13] [error] handle_connect error: Underlying Transport Error Jun 21 08:04:15 hjl systemd[1]: apt-daily.service: Succeeded. Jun 21 08:04:15 hjl systemd[1]: Started Daily apt download activities. Jun 21 08:04:15 hjl systemd[1]: Starting Daily apt upgrade and clean activities... Jun 21 08:04:17 hjl systemd[1]: systemd-fsckd.service: Succeeded. Jun 21 08:04:17 hjl systemd[1]: apt-daily-upgrade.service: Succeeded. Jun 21 08:04:17 hjl systemd[1]: Started Daily apt upgrade and clean activities. Jun 21 08:04:17 hjl systemd[1]: Startup finished in 16.732s (kernel) + 39.076s (userspace) = 55.808s. Jun 21 08:04:18 hjl volumio[888]: info: ------------------------------------------- Jun 21 08:04:18 hjl volumio[888]: info: ----- Volumio3 ---- Jun 21 08:04:18 hjl volumio[888]: info: ------------------------------------------- Jun 21 08:04:18 hjl volumio[888]: info: ----- System startup ---- Jun 21 08:04:18 hjl volumio[888]: info: ------------------------------------------- Jun 21 08:04:20 hjl sh[435]: timed out Jun 21 08:04:20 hjl dhcpcd[476]: timed out Jun 21 08:04:20 hjl sh[435]: dhcpcd exited Jun 21 08:04:20 hjl dhcpcd[476]: dhcpcd exited Jun 21 08:04:20 hjl sh[435]: ifup: failed to bring up eth0 Jun 21 08:04:20 hjl systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Jun 21 08:04:20 hjl systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Jun 21 08:04:20 hjl volumio[888]: info: MYVOLUMIO Environment detected Jun 21 08:04:21 hjl volumio[888]: info: Plugin folders cleanup Jun 21 08:04:21 hjl volumio[888]: info: Scanning into folder /volumio/app/plugins/ Jun 21 08:04:21 hjl volumio[888]: info: Scanning category audio_interface Jun 21 08:04:21 hjl volumio[888]: info: Scanning category miscellanea Jun 21 08:04:21 hjl volumio[888]: info: Scanning category music_service Jun 21 08:04:21 hjl volumio[888]: info: Scanning category plugins.json Jun 21 08:04:21 hjl volumio[888]: info: Scanning category system_controller Jun 21 08:04:21 hjl volumio[888]: info: Scanning category user_interface Jun 21 08:04:21 hjl volumio[888]: info: Scanning into folder /data/plugins/ Jun 21 08:04:21 hjl volumio[888]: info: Scanning category music_service Jun 21 08:04:21 hjl volumio[888]: info: Plugin folders cleanup completed Jun 21 08:04:21 hjl volumio[888]: info: ------------------------------------------- Jun 21 08:04:21 hjl volumio[888]: info: ----- Core plugins startup ---- Jun 21 08:04:21 hjl volumio[888]: info: ------------------------------------------- Jun 21 08:04:21 hjl volumio[888]: info: Loading plugins from folder /volumio/app/plugins/ Jun 21 08:04:21 hjl volumio[888]: info: Adding plugin upnp to MyMusic Plugins Jun 21 08:04:21 hjl volumio[888]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 21 08:04:21 hjl volumio[888]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 21 08:04:21 hjl volumio[888]: info: Loading plugins from folder /data/plugins/ Jun 21 08:04:21 hjl volumio[888]: info: Loading plugin "system"... Jun 21 08:04:21 hjl volumio[888]: info: Loading plugin "appearance"... Jun 21 08:04:23 hjl volumio-remote-updater[522]: [2025-06-21 08:04:23] [connect] Successful connection Jun 21 08:04:25 hjl volumio[888]: info: Loading plugin "network"... Jun 21 08:04:25 hjl volumio[888]: info: Refreshing Cached IP Addresses Jun 21 08:04:25 hjl sudo[1039]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 21 08:04:25 hjl sudo[1039]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:25 hjl sudo[1039]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:25 hjl sudo[1041]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 21 08:04:25 hjl sudo[1041]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:25 hjl volumio[888]: info: Loading plugin "services"... Jun 21 08:04:25 hjl sudo[1041]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:25 hjl volumio[888]: info: Loading plugin "alsa_controller"... Jun 21 08:04:25 hjl sudo[1050]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 21 08:04:25 hjl sudo[1050]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:25 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 21 08:04:25 hjl volumio[888]: info: Loading plugin "wizard"... Jun 21 08:04:25 hjl volumio[888]: info: Loading plugin "networkfs"... Jun 21 08:04:25 hjl volumio[888]: info: Starting Udev Watcher for removable devices Jun 21 08:04:25 hjl sudo[1065]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=hung4630,password=eAq7uO_jC63Y,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.50.99/hung4630/music /mnt/NAS/TrueNAS Jun 21 08:04:25 hjl sudo[1065]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:25 hjl volumio[888]: info: Ignoring mount for partition: boot Jun 21 08:04:25 hjl volumio[888]: info: Ignoring mount for partition: volumio Jun 21 08:04:25 hjl volumio[888]: info: Ignoring mount for partition: volumio_data Jun 21 08:04:26 hjl volumio[888]: info: Mounting Device KINGSTON Jun 21 08:04:26 hjl sudo[1075]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/KINGSTON -o noatime Jun 21 08:04:26 hjl sudo[1075]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:26 hjl kernel: Key type cifs.spnego registered Jun 21 08:04:26 hjl kernel: Key type cifs.idmap registered Jun 21 08:04:26 hjl 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. Jun 21 08:04:26 hjl kernel: CIFS: Attempting to mount //192.168.50.99/hung4630/music Jun 21 08:04:26 hjl mount.exfat[1077]: volume was not unmounted cleanly Jun 21 08:04:26 hjl sudo[1075]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:26 hjl volumio[888]: WARN: volume was not unmounted cleanly. Jun 21 08:04:26 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 21 08:04:26 hjl volumio[888]: info: Loading plugin "volumio_command_line_client"... Jun 21 08:04:26 hjl volumio[888]: info: Loading plugin "upnp"... Jun 21 08:04:26 hjl volumio[888]: info: [1750464266731] Starting Upmpd Daemon Jun 21 08:04:26 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 21 08:04:26 hjl volumio[888]: info: Loading plugin "my_music"... Jun 21 08:04:26 hjl volumio[888]: info: Loading plugin "mpd"... Jun 21 08:04:27 hjl volumio[888]: info: Loading plugin "upnp_browser"... Jun 21 08:04:29 hjl volumio[888]: info: Loading plugin "alarm-clock"... Jun 21 08:04:29 hjl sudo[1050]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:29 hjl volumio[888]: info: Loading plugin "airplay_emulation"... Jun 21 08:04:29 hjl volumio[888]: info: Starting Shairport Sync Jun 21 08:04:29 hjl volumio[888]: info: Loading plugin "last_100"... Jun 21 08:04:29 hjl volumio[888]: info: Loading plugin "webradio"... Jun 21 08:04:30 hjl volumio[888]: info: Loading plugin "i2s_dacs"... Jun 21 08:04:30 hjl volumio[888]: info: Loading plugin "volumiodiscovery"... Jun 21 08:04:30 hjl volumio[888]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 21 08:04:30 hjl volumio[888]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 21 08:04:30 hjl volumio[888]: *** WARNING *** For more information see Jun 21 08:04:30 hjl node[888]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 21 08:04:30 hjl volumio[888]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 21 08:04:30 hjl volumio[888]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 21 08:04:30 hjl volumio[888]: *** WARNING *** For more information see Jun 21 08:04:30 hjl node[888]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 21 08:04:30 hjl node[888]: *** WARNING *** For more information see Jun 21 08:04:30 hjl node[888]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 21 08:04:30 hjl node[888]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 21 08:04:30 hjl node[888]: *** WARNING *** For more information see Jun 21 08:04:30 hjl volumio[888]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 21 08:04:30 hjl volumio[888]: info: Discovery: Started advertising with name: HJL Jun 21 08:04:30 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 21 08:04:30 hjl volumio[888]: info: Loading plugin "spop"... Jun 21 08:04:34 hjl volumio[888]: info: Loading plugin "outputs"... Jun 21 08:04:34 hjl volumio[888]: info: Loading plugin "albumart"... Jun 21 08:04:34 hjl volumio[888]: info: Plugin example_plugin is not enabled Jun 21 08:04:34 hjl volumio[888]: info: Loading plugin "inputs"... Jun 21 08:04:34 hjl volumio[888]: info: Loading plugin "updater_comm"... Jun 21 08:04:35 hjl volumio[888]: info: Plugin mpdemulation is not enabled Jun 21 08:04:35 hjl volumio[888]: info: Loading plugin "rest_api"... Jun 21 08:04:35 hjl volumio[888]: info: Loading plugin "websocket"... Jun 21 08:04:35 hjl volumio[888]: info: Starting Socket.io Server version 2.3.0 Jun 21 08:04:35 hjl volumio[888]: info: Loading i18n strings for locale zh_TW Jun 21 08:04:35 hjl volumio[888]: Updating browse sources language Jun 21 08:04:35 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 21 08:04:35 hjl volumio[888]: Forking 3 albumart workers Jun 21 08:04:36 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 21 08:04:36 hjl volumio[888]: info: CoreCommandRouter::initPlayerControls Jun 21 08:04:36 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:36 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:36 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:36 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:36 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:36 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:36 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:36 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:36 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 21 08:04:36 hjl volumio[888]: Express server listening on port 3000 Jun 21 08:04:36 hjl volumio[888]: [Metrics] WebUI: 20s 953.88ms Jun 21 08:04:36 hjl kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Jun 21 08:04:36 hjl kernel: CIFS: VFS: cifs_mount failed w/return code = -115 Jun 21 08:04:36 hjl volumio[888]: info: CoreStateMachine::resetVolumioState Jun 21 08:04:36 hjl volumio[888]: info: CoreStateMachine::getcurrentVolume Jun 21 08:04:36 hjl sudo[1065]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:36 hjl volumio[888]: info: CoreCommandRouter::volumioRetrievevolume Jun 21 08:04:36 hjl volumio[888]: info: Volumio Network Manager: Network status updated: 2 Jun 21 08:04:36 hjl volumio[888]: info: Cannot mount NAS TrueNAS at system boot, trial number 1 ,retrying in 5 seconds Jun 21 08:04:36 hjl sudo[1141]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 21 08:04:36 hjl sudo[1141]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:36 hjl sudo[1143]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 21 08:04:36 hjl sudo[1141]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:36 hjl sudo[1143]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:37 hjl sudo[1143]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:37 hjl volumio[888]: info: CoreStateMachine::pushState Jun 21 08:04:37 hjl volumio[888]: info: CorePlayQueue::getTrack 0 Jun 21 08:04:37 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 21 08:04:37 hjl volumio[888]: info: CoreCommandRouter::volumioPushState Jun 21 08:04:37 hjl volumio[888]: info: CoreStateMachine::updateTrackBlock Jun 21 08:04:37 hjl volumio[888]: info: CorePlayQueue::getTrackBlock Jun 21 08:04:37 hjl volumio[888]: info: CoreCommandRouter::volumioRetrievevolume Jun 21 08:04:37 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 21 08:04:37 hjl volumio[888]: info: Reloading queue from file Jun 21 08:04:37 hjl volumio[888]: info: CoreStateMachine::setRepeat null single undefined Jun 21 08:04:37 hjl volumio[888]: info: CoreStateMachine::pushState Jun 21 08:04:37 hjl volumio[888]: info: CorePlayQueue::getTrack 0 Jun 21 08:04:37 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 21 08:04:37 hjl volumio[888]: info: CoreCommandRouter::volumioPushState Jun 21 08:04:37 hjl volumio[888]: info: CoreStateMachine::setRandom null Jun 21 08:04:37 hjl volumio[888]: info: CoreStateMachine::pushState Jun 21 08:04:37 hjl volumio[888]: info: CorePlayQueue::getTrack 0 Jun 21 08:04:37 hjl volumio[888]: info: CoreCommandRouter::volumioPushState Jun 21 08:04:37 hjl volumio[888]: info: Setting Device type: Raspberry PI Jun 21 08:04:37 hjl volumio[888]: info: Completed loading Core Plugins Jun 21 08:04:37 hjl volumio[888]: info: Preparing to generate the ALSA configuration file Jun 21 08:04:37 hjl volumio[888]: info: CoreStateMachine::pushState Jun 21 08:04:37 hjl volumio[888]: info: CorePlayQueue::getTrack 0 Jun 21 08:04:37 hjl volumio[888]: info: CoreCommandRouter::volumioPushState Jun 21 08:04:37 hjl volumio[888]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Jun 21 08:04:37 hjl volumio[888]: info: Reading ALSA contributions from plugins. Jun 21 08:04:37 hjl volumio[888]: info: Asound.conf file unchanged, so no further update is needed Jun 21 08:04:37 hjl volumio[888]: info: Output device has changed, restarting MPD Jun 21 08:04:37 hjl sudo[1158]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 21 08:04:37 hjl sudo[1158]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:37 hjl volumio[888]: info: Output device has changed, restarting Shairport Sync Jun 21 08:04:37 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:37 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 21 08:04:37 hjl sudo[1160]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 21 08:04:37 hjl sudo[1160]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:37 hjl sudo[1160]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:37 hjl sudo[1162]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 21 08:04:37 hjl sudo[1162]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:38 hjl systemd[1]: Started UPnP Renderer front-end to MPD. Jun 21 08:04:38 hjl volumio[888]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 21 08:04:38 hjl sudo[1158]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:38 hjl systemd[1]: Stopping Music Player Daemon... Jun 21 08:04:38 hjl volumio[888]: info: ___________ START PLUGINS ___________ Jun 21 08:04:38 hjl volumio[888]: info: ControllerMpd::onStart: Initializing MPD Jun 21 08:04:38 hjl volumio[888]: info: Creating MPD Configuration file Jun 21 08:04:38 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 21 08:04:38 hjl volumio[888]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 21 08:04:38 hjl volumio[888]: info: [1750464278383] CoreMusicLibrary::Adding element Media Servers Jun 21 08:04:38 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 21 08:04:38 hjl sudo[1171]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 21 08:04:38 hjl sudo[1171]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:38 hjl sudo[1171]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:38 hjl systemd[1]: mpd.service: Succeeded. Jun 21 08:04:38 hjl systemd[1]: Stopped Music Player Daemon. Jun 21 08:04:38 hjl sudo[1173]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 21 08:04:38 hjl sudo[1173]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:38 hjl systemd[1]: Starting Music Player Daemon... Jun 21 08:04:38 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:38 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 21 08:04:38 hjl systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Jun 21 08:04:38 hjl systemd[1]: mpd.service: Succeeded. Jun 21 08:04:38 hjl systemd[1]: Stopped Music Player Daemon. Jun 21 08:04:38 hjl systemd[1]: Starting Music Player Daemon... Jun 21 08:04:38 hjl volumio-remote-updater[522]: [2025-06-21 08:04:38] [connect] Successful connection Jun 21 08:04:38 hjl volumio[888]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 21 08:04:38 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:38 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 21 08:04:38 hjl volumio[888]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 21 08:04:38 hjl volumio[888]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 21 08:04:38 hjl volumio[888]: info: [1750464278984] CoreMusicLibrary::Adding element Last_100 Jun 21 08:04:38 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 21 08:04:38 hjl volumio[888]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 21 08:04:38 hjl volumio[888]: info: [1750464278995] CoreMusicLibrary::Adding element Webradio Jun 21 08:04:38 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 21 08:04:39 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 21 08:04:39 hjl volumio[888]: info: Initializing BBC Radios Jun 21 08:04:39 hjl sudo[1177]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 21 08:04:39 hjl sudo[1177]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:39 hjl sudo[1177]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:39 hjl volumio[888]: Starting albumart workers Jun 21 08:04:39 hjl volumio[888]: Starting albumart workers Jun 21 08:04:39 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 21 08:04:39 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 21 08:04:39 hjl volumio[888]: info: Creating Spotify config file Jun 21 08:04:39 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:39 hjl volumio[888]: Starting albumart workers Jun 21 08:04:39 hjl volumio[888]: info: Volumio Calling Home Jun 21 08:04:40 hjl volumio[888]: info: Discovery: adding 91e0b2a6-6113-42f5-8ea7-6c9f02d8a4bb Jun 21 08:04:40 hjl volumio[888]: info: Discovery: Found device HJL Jun 21 08:04:40 hjl volumio[888]: info: CoreCommandRouter::volumioGetState Jun 21 08:04:40 hjl volumio[888]: info: CorePlayQueue::getTrack 0 Jun 21 08:04:40 hjl volumio[888]: info: MPD Permissions set Jun 21 08:04:40 hjl volumio[888]: info: MPD Permissions set Jun 21 08:04:40 hjl volumio[888]: info: Upmpdcli Daemon Started Jun 21 08:04:40 hjl volumio-remote-updater[522]: [2025-06-21 08:04:40] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1750464278 101 Jun 21 08:04:40 hjl volumio[888]: 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 Jun 21 08:04:40 hjl volumio[888]: info: Spotify config file written Jun 21 08:04:40 hjl sudo[1201]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 21 08:04:40 hjl sudo[1201]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:41 hjl systemd[1]: Started go-librespot Daemon. Jun 21 08:04:41 hjl go-librespot[1204]: go-librespot daemon starting... Jun 21 08:04:41 hjl sudo[1201]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:41 hjl volumio[888]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jun 21 08:04:41 hjl volumio[888]: info: Volumio called home Jun 21 08:04:41 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:41 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:41 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:41 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:41 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:41 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:41 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 21 08:04:41 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:41 hjl volumio[888]: info: No need to fix Spotify hosts Jun 21 08:04:41 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:41 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:41 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:41 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:42 hjl go-librespot[1204]: time="2025-06-21T08:04:42+08:00" level=info msg="running go-librespot 0.2.0" Jun 21 08:04:42 hjl go-librespot[1204]: time="2025-06-21T08:04:42+08:00" level=debug msg="app state loaded" Jun 21 08:04:42 hjl go-librespot[1204]: time="2025-06-21T08:04:42+08:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 21 08:04:42 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 21 08:04:42 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 21 08:04:42 hjl sudo[1244]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=hung4630,password=eAq7uO_jC63Y,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.50.99/hung4630/music /mnt/NAS/TrueNAS Jun 21 08:04:42 hjl sudo[1244]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:42 hjl kernel: CIFS: Attempting to mount //192.168.50.99/hung4630/music Jun 21 08:04:42 hjl volumio[888]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 21 08:04:42 hjl volumio[888]: SPOTIFY: BQAV04cB5cV52SiCfnEmmUuP5UOHTnHu2FP_IMPtIOTSIXOJ1vTycwkAJP5j4Y2L-7hKCW2wjgNWNwvxJmcHE_Obca8LtkcuL1WI3qPCIUd3otttG7ev3yaqgYxcEFmVjx7RTbPZXUbFUBCKGyKCHgZROIjVxhLe6gvFwkbVVBdIC_kF47Lrb29FdfsY6unwcS6jqJwGvfFdsBV6QqoHd3tdFdEnPcuf7i80fL7VUJtByBS0y4-VHutoLmZmNZoJdeWwt8uXcM23MsIpGiCddls0CwZ6nqRJyYPS0xChRQehZEZwlg0 Jun 21 08:04:42 hjl volumio[888]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 21 08:04:42 hjl volumio[888]: info: New Spotify access token = BQAV04cB5cV52SiCfnEmmUuP5UOHTnHu2FP_IMPtIOTSIXOJ1vTycwkAJP5j4Y2L-7hKCW2wjgNWNwvxJmcHE_Obca8LtkcuL1WI3qPCIUd3otttG7ev3yaqgYxcEFmVjx7RTbPZXUbFUBCKGyKCHgZROIjVxhLe6gvFwkbVVBdIC_kF47Lrb29FdfsY6unwcS6jqJwGvfFdsBV6QqoHd3tdFdEnPcuf7i80fL7VUJtByBS0y4-VHutoLmZmNZoJdeWwt8uXcM23MsIpGiCddls0CwZ6nqRJyYPS0xChRQehZEZwlg0 Jun 21 08:04:42 hjl volumio[888]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 21 08:04:43 hjl volumio[888]: info: Starting Shairport Sync Jun 21 08:04:43 hjl systemd[1]: systemd-timedated.service: Succeeded. Jun 21 08:04:43 hjl volumio[888]: info: Starting Shairport Sync Jun 21 08:04:43 hjl sudo[1251]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 21 08:04:43 hjl volumio[888]: info: Starting Shairport Sync Jun 21 08:04:43 hjl sudo[1251]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:43 hjl sudo[1255]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 21 08:04:43 hjl sudo[1255]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:43 hjl systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 21 08:04:43 hjl systemd[1]: shairport-sync.service: Succeeded. Jun 21 08:04:43 hjl go-librespot[1204]: time="2025-06-21T08:04:43+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 21 08:04:43 hjl go-librespot[1204]: time="2025-06-21T08:04:43+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 21 08:04:43 hjl go-librespot[1204]: time="2025-06-21T08:04:43+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 21 08:04:43 hjl systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 21 08:04:43 hjl volumio[888]: info: CoreCommandRouter::volumioGetState Jun 21 08:04:43 hjl volumio[888]: info: CorePlayQueue::getTrack 0 Jun 21 08:04:43 hjl go-librespot[1204]: time="2025-06-21T08:04:43+08:00" level=info msg="zeroconf server listening on port 44779" Jun 21 08:04:43 hjl sudo[1259]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 21 08:04:43 hjl sudo[1259]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 21 08:04:43 hjl systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 21 08:04:43 hjl sudo[1251]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:43 hjl go-librespot[1204]: time="2025-06-21T08:04:43+08:00" level=debug msg="obtained new client token: AAAYpp73QWHPy7zoEkWJdB6aVTJ8bhAWBcYLk4In/YYe2Ccv/sMwbOMm38b2TP9/ExWdW1znnztHCih46/wIotWZgRNTx1rshH7tT9TD0J6pwknqt6S+aVAsTTsAaL7hOmZMV/EEpnDXYzoC6ne0tgdOpukK9UX5doSIXj9Cwc2hIYfgomboLTZbip9yYNu066Nd1j+xEYFAjpLXCGu6mjjAAwFhQGNpdt3qiYM4egA/lJe1d/FGMVmU" Jun 21 08:04:43 hjl sudo[1255]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:43 hjl go-librespot[1204]: time="2025-06-21T08:04:43+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 21 08:04:43 hjl systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 21 08:04:43 hjl systemd[1]: shairport-sync.service: Succeeded. Jun 21 08:04:43 hjl systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 21 08:04:43 hjl volumio[888]: info: Shairport-Sync Started Jun 21 08:04:43 hjl go-librespot[1204]: time="2025-06-21T08:04:43+08:00" level=debug msg="completed keyexchange" Jun 21 08:04:43 hjl go-librespot[1204]: time="2025-06-21T08:04:43+08:00" level=debug msg="completed challenge" Jun 21 08:04:43 hjl volumio[888]: Error adding Membership: Error: addMembership EINVAL Jun 21 08:04:43 hjl volumio[888]: info: Shairport-Sync Started Jun 21 08:04:43 hjl systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 21 08:04:43 hjl go-librespot[1204]: time="2025-06-21T08:04:43+08:00" level=info msg="authenticated AP as 3145lxrg3jopwifmkk4kotuiwshi" Jun 21 08:04:43 hjl sudo[1259]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:43 hjl volumio[888]: info: Shairport-Sync Started Jun 21 08:04:43 hjl volumio[888]: SPOTIFY: User informations: {"country":"TW","display_name":"retired_monkey","email":"hung4630@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/3145lxrg3jopwifmkk4kotuiwshi"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/3145lxrg3jopwifmkk4kotuiwshi","id":"3145lxrg3jopwifmkk4kotuiwshi","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee853bab31bf0f7d6a9cfcdcbd6f","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b823bab31bf0f7d6a9cfcdcbd6f","width":64}],"product":"premium","type":"user","uri":"spotify:user:3145lxrg3jopwifmkk4kotuiwshi"} Jun 21 08:04:43 hjl volumio[888]: info: Spotify Successfully logged in Jun 21 08:04:43 hjl volumio[888]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 21 08:04:43 hjl volumio[888]: info: [1750464283880] CoreMusicLibrary::Adding element Spotify Jun 21 08:04:43 hjl volumio[888]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 21 08:04:43 hjl volumio[888]: Cannot find translation for source Spotify Jun 21 08:04:43 hjl go-librespot[1204]: time="2025-06-21T08:04:43+08:00" level=info msg="authenticated Login5 as 3145lxrg3jopwifmkk4kotuiwshi" Jun 21 08:04:43 hjl go-librespot[1204]: time="2025-06-21T08:04:43+08:00" level=debug msg="initializing zeroconf session, username: 3145lxrg3jopwifmkk4kotuiwshi" Jun 21 08:04:44 hjl mpd[1187]: Jun 21 08:04 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=debug msg="dealer connection opened" Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=trace msg="starting accesspoint recv loop" Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=trace msg="starting dealer recv loop" Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=trace msg="received accesspoint ping" Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=trace msg="received accesspoint pong ack" Jun 21 08:04:44 hjl systemd[1]: Started Music Player Daemon. Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=debug msg="received connection id: ZmRjMDlhODItN2MyZi00OTIyLThiODctNDg4ZGU1MzA5NjkyK2RlYWxlcit0Y3A6Ly8wYWM5NDkxOC5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArMTBGODIwNzY4NTNDQjg2NzdEMDgyNjE0OTZFQTkzNEY3Nzk0RUUzQ0IxNTZDREM2NEQ2NEVFODFEQjY0QzUwNQ==" Jun 21 08:04:44 hjl volumio[888]: Upnp client error: Error: This socket has been ended by the other party Jun 21 08:04:44 hjl sudo[1162]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:44 hjl sudo[1173]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:44 hjl volumio[888]: info: Completed starting Core Plugins Jun 21 08:04:44 hjl volumio[888]: info: ------------------------------------------- Jun 21 08:04:44 hjl volumio[888]: info: ----- MyVolumio plugins startup ---- Jun 21 08:04:44 hjl volumio[888]: info: ------------------------------------------- Jun 21 08:04:44 hjl volumio[888]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=debug msg="put connect state because NEW_DEVICE" Jun 21 08:04:44 hjl volumio[888]: error: MPD error: The expression evaluated to a falsy value: Jun 21 08:04:44 hjl volumio[888]: assert.ok(self.idling) Jun 21 08:04:44 hjl volumio[888]: error: The expression evaluated to a falsy value: Jun 21 08:04:44 hjl volumio[888]: assert.ok(self.idling) Jun 21 08:04:44 hjl volumio[888]: info: MPD running with PID1187 Jun 21 08:04:44 hjl volumio[888]: ,establishing connection Jun 21 08:04:44 hjl volumio[888]: error: updateQueue error: null Jun 21 08:04:44 hjl volumio[888]: error: updateQueue error: null Jun 21 08:04:44 hjl volumio[1169]: Generating RSA private key, 4096 bit long modulus (2 primes) Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 21 08:04:44 hjl go-librespot[1204]: time="2025-06-21T08:04:44+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 250" Jun 21 08:04:45 hjl volumio[888]: info: go-librespot daemon successfully initialized Jun 21 08:04:46 hjl volumio[1169]: ..++++ Jun 21 08:04:46 hjl go-librespot[1204]: time="2025-06-21T08:04:46+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 21 08:04:46 hjl go-librespot[1204]: time="2025-06-21T08:04:46+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 337" Jun 21 08:04:48 hjl volumio[888]: info: Initializing connection to go-librespot Websocket Jun 21 08:04:48 hjl go-librespot[1204]: time="2025-06-21T08:04:48+08:00" level=debug msg="new websocket client" Jun 21 08:04:48 hjl volumio[888]: info: Connection to go-librespot Websocket established Jun 21 08:04:50 hjl go-librespot[1204]: time="2025-06-21T08:04:50+08:00" level=debug msg="handling transfer player command from 626be5ac9a379041a08915625bf9403f9aec51fc" Jun 21 08:04:50 hjl go-librespot[1204]: time="2025-06-21T08:04:50+08:00" level=debug msg="resolved context of track" uri="spotify:playlist:0F7HgAepq5tXPEHd7wfgHB" Jun 21 08:04:50 hjl go-librespot[1204]: time="2025-06-21T08:04:50+08:00" level=trace msg="fetched new page 0 with 295 items (list: 295)" uri="spotify:playlist:0F7HgAepq5tXPEHd7wfgHB" Jun 21 08:04:50 hjl go-librespot[1204]: time="2025-06-21T08:04:50+08:00" level=debug msg="loading track (paused: false, position: 4746ms)" uri="spotify:track:1P47jw1VxOTQ0MM6sGKCkP" Jun 21 08:04:50 hjl go-librespot[1204]: time="2025-06-21T08:04:50+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 21 08:04:50 hjl go-librespot[1204]: time="2025-06-21T08:04:50+08:00" level=trace msg="emitting websocket event: will_play" Jun 21 08:04:50 hjl go-librespot[1204]: time="2025-06-21T08:04:50+08:00" level=debug msg="selected format OGG_VORBIS_320 (1f80d723de634568c093ba9a4531d578a5caeec4)" uri="spotify:track:1P47jw1VxOTQ0MM6sGKCkP" Jun 21 08:04:50 hjl go-librespot[1204]: time="2025-06-21T08:04:50+08:00" level=debug msg="requested aes key for file 1f80d723de634568c093ba9a4531d578a5caeec4, gid: 1P47jw1VxOTQ0MM6sGKCkP" Jun 21 08:04:50 hjl go-librespot[1204]: time="2025-06-21T08:04:50+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 242" Jun 21 08:04:50 hjl volumio[888]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1P47jw1VxOTQ0MM6sGKCkP","play_origin":"playlist"}} Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=debug msg="fetched first chunk of 11, total size is 5357669 bytes" uri="spotify:track:1P47jw1VxOTQ0MM6sGKCkP" Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=trace msg="seek to 4746ms (diff: 104ms, samples: 209298, bytes: 112966)" uri="spotify:track:1P47jw1VxOTQ0MM6sGKCkP" Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=debug msg="created new output device" Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=info msg="loaded track \"On a Clear Day\" (paused: false, position: 4746ms, duration: 136040ms, prefetched: false)" uri="spotify:track:1P47jw1VxOTQ0MM6sGKCkP" Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=trace msg="scheduling prefetch in 101s" Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=trace msg="emitting websocket event: metadata" Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=trace msg="emitting websocket event: active" Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=debug msg="sending successful reply for dealer request" Jun 21 08:04:51 hjl volumio[888]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1P47jw1VxOTQ0MM6sGKCkP","name":"On a Clear Day","artist_names":["Joe Hisaishi"],"album_name":"Kiki's Delivery Service Soundtrack Music Collection","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0299e60198d20bd0a2ab2900a7","position":4746,"duration":136040,"release_date":"year:1989 month:8 day:10","track_number":1,"disc_number":1}} Jun 21 08:04:51 hjl volumio[888]: SPOTIFY: received: {"type":"active","data":null} Jun 21 08:04:51 hjl volumio[888]: info: Aligning Spotify Volume to Volumio Volume Jun 21 08:04:51 hjl volumio[888]: info: CoreCommandRouter::volumioGetState Jun 21 08:04:51 hjl volumio[888]: info: CorePlayQueue::getTrack 0 Jun 21 08:04:51 hjl volumio[888]: info: Setting Spotify Volume from Volumio: 75 Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=debug msg="fetched chunk 2/10, size: 524288" uri="spotify:track:1P47jw1VxOTQ0MM6sGKCkP" Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=trace msg="emitting websocket event: playing" Jun 21 08:04:51 hjl volumio[888]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1P47jw1VxOTQ0MM6sGKCkP","play_origin":"playlist"}} Jun 21 08:04:51 hjl volumio[888]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 21 08:04:51 hjl volumio[888]: TypeError: Cannot read property 'service' of undefined Jun 21 08:04:51 hjl volumio[888]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) Jun 21 08:04:51 hjl volumio[888]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:266:18) Jun 21 08:04:51 hjl volumio[888]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) Jun 21 08:04:51 hjl volumio[888]: at WebSocket.emit (events.js:315:20) Jun 21 08:04:51 hjl volumio[888]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jun 21 08:04:51 hjl volumio[888]: at Receiver.emit (events.js:315:20) Jun 21 08:04:51 hjl volumio[888]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jun 21 08:04:51 hjl volumio[888]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jun 21 08:04:51 hjl volumio[888]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jun 21 08:04:51 hjl volumio[888]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jun 21 08:04:51 hjl volumio[888]: at writeOrBuffer (internal/streams/writable.js:358:12) Jun 21 08:04:51 hjl volumio[888]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jun 21 08:04:51 hjl volumio[888]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Jun 21 08:04:51 hjl volumio[888]: at Socket.emit (events.js:315:20) Jun 21 08:04:51 hjl volumio[888]: at addChunk (internal/streams/readable.js:309:12) Jun 21 08:04:51 hjl volumio[888]: at readableAddChunk (internal/streams/readable.js:284:9) Jun 21 08:04:51 hjl volumio[888]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=debug msg="fetched chunk 3/10, size: 524288" uri="spotify:track:1P47jw1VxOTQ0MM6sGKCkP" Jun 21 08:04:51 hjl go-librespot[1204]: time="2025-06-21T08:04:51+08:00" level=debug msg="fetched chunk 1/10, size: 524288" uri="spotify:track:1P47jw1VxOTQ0MM6sGKCkP" Jun 21 08:04:52 hjl kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Jun 21 08:04:52 hjl kernel: CIFS: VFS: cifs_mount failed w/return code = -115 Jun 21 08:04:53 hjl sudo[1244]: pam_unix(sudo:session): session closed for user root Jun 21 08:04:53 hjl sudo[1350]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-21 08:03 Jun 21 08:04:53 hjl sudo[1350]: 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="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"