-- Logs begin at Thu 2019-02-14 19:11:59 JST, end at Tue 2025-07-08 09:48:59 JST. -- Jul 08 09:48:40 volumio systemd-timedated[1016]: Changed local time to Tue Jul 8 09:48:40 2025 Jul 08 09:48:40 volumio sudo[1014]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:40 volumio volumio-time-update[548]: volumio-time-update-util: System time updated successfully. Jul 08 09:48:40 volumio systemd[1]: Started Volumio Time Update Utility. Jul 08 09:48:40 volumio systemd[1]: Starting Daily apt download activities... Jul 08 09:48:40 volumio systemd[1]: Started Samba NMB Daemon. Jul 08 09:48:40 volumio nmbd[740]: [2025/07/08 09:48:40.302304, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jul 08 09:48:40 volumio nmbd[740]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Jul 08 09:48:40 volumio systemd[1]: Starting Samba Winbind Daemon... Jul 08 09:48:40 volumio winbindd[1020]: [2025/07/08 09:48:40.817009, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Jul 08 09:48:40 volumio winbindd[1020]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Jul 08 09:48:40 volumio winbindd[1020]: [2025/07/08 09:48:40.858329, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jul 08 09:48:40 volumio systemd[1]: Started Samba Winbind Daemon. Jul 08 09:48:40 volumio winbindd[1020]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Jul 08 09:48:40 volumio systemd[1]: Starting Samba SMB Daemon... Jul 08 09:48:41 volumio systemd[1]: apt-daily.service: Succeeded. Jul 08 09:48:41 volumio systemd[1]: Started Daily apt download activities. Jul 08 09:48:41 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Jul 08 09:48:41 volumio volumio[981]: info: MYVOLUMIO Environment detected Jul 08 09:48:41 volumio smbd[1049]: [2025/07/08 09:48:41.559979, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jul 08 09:48:41 volumio systemd[1]: Started Samba SMB Daemon. Jul 08 09:48:41 volumio smbd[1049]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Jul 08 09:48:41 volumio systemd[1]: Reached target Multi-User System. Jul 08 09:48:41 volumio systemd[1]: Reached target Graphical Interface. Jul 08 09:48:41 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Jul 08 09:48:41 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jul 08 09:48:41 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Jul 08 09:48:41 volumio volumio[981]: info: Plugin folders cleanup Jul 08 09:48:41 volumio volumio[981]: info: Scanning into folder /volumio/app/plugins/ Jul 08 09:48:41 volumio volumio[981]: info: Scanning category audio_interface Jul 08 09:48:41 volumio volumio[981]: info: Scanning category miscellanea Jul 08 09:48:41 volumio volumio[981]: info: Scanning category music_service Jul 08 09:48:41 volumio volumio[981]: info: Scanning category plugins.json Jul 08 09:48:41 volumio volumio[981]: info: Scanning category system_controller Jul 08 09:48:41 volumio volumio[981]: info: Scanning category user_interface Jul 08 09:48:41 volumio volumio[981]: info: Scanning into folder /data/plugins/ Jul 08 09:48:41 volumio volumio[981]: info: Scanning category music_service Jul 08 09:48:41 volumio volumio[981]: info: Plugin folders cleanup completed Jul 08 09:48:41 volumio volumio[981]: info: ------------------------------------------- Jul 08 09:48:41 volumio volumio[981]: info: ----- Core plugins startup ---- Jul 08 09:48:41 volumio volumio[981]: info: ------------------------------------------- Jul 08 09:48:41 volumio volumio[981]: info: Loading plugins from folder /volumio/app/plugins/ Jul 08 09:48:41 volumio volumio[981]: info: Adding plugin upnp to MyMusic Plugins Jul 08 09:48:41 volumio volumio[981]: info: Adding plugin airplay_emulation to MyMusic Plugins Jul 08 09:48:41 volumio volumio[981]: info: Adding plugin upnp_browser to MyMusic Plugins Jul 08 09:48:41 volumio volumio[981]: info: Loading plugins from folder /data/plugins/ Jul 08 09:48:41 volumio volumio[981]: info: Loading plugin "system"... Jul 08 09:48:41 volumio volumio[981]: info: Loading plugin "appearance"... Jul 08 09:48:42 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Jul 08 09:48:42 volumio systemd[1]: Started Daily apt upgrade and clean activities. Jul 08 09:48:42 volumio systemd[1]: Startup finished in 13.990s (kernel) + 35.559s (userspace) = 49.549s. Jul 08 09:48:42 volumio sh[486]: timed out Jul 08 09:48:42 volumio dhcpcd[520]: timed out Jul 08 09:48:42 volumio sh[486]: dhcpcd exited Jul 08 09:48:42 volumio dhcpcd[520]: dhcpcd exited Jul 08 09:48:42 volumio sh[486]: ifup: failed to bring up eth0 Jul 08 09:48:42 volumio systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Jul 08 09:48:42 volumio systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Jul 08 09:48:43 volumio volumio[981]: info: Loading plugin "network"... Jul 08 09:48:43 volumio volumio[981]: info: Refreshing Cached IP Addresses Jul 08 09:48:43 volumio sudo[1136]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 08 09:48:43 volumio sudo[1136]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:43 volumio sudo[1138]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 08 09:48:43 volumio sudo[1138]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:43 volumio sudo[1136]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:43 volumio sudo[1138]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:43 volumio volumio[981]: info: Loading plugin "services"... Jul 08 09:48:43 volumio volumio[981]: info: Loading plugin "alsa_controller"... Jul 08 09:48:43 volumio sudo[1147]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jul 08 09:48:43 volumio sudo[1147]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:43 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 08 09:48:43 volumio volumio[981]: info: Loading plugin "wizard"... Jul 08 09:48:43 volumio volumio[981]: info: Loading plugin "networkfs"... Jul 08 09:48:43 volumio volumio[981]: info: Starting Udev Watcher for removable devices Jul 08 09:48:43 volumio sudo[1164]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=user,password=97LKSR7X,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.3.16/SoundData/ /mnt/NAS/NAS Jul 08 09:48:43 volumio sudo[1164]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:43 volumio volumio[981]: info: Ignoring mount for partition: boot Jul 08 09:48:43 volumio volumio[981]: info: Ignoring mount for partition: volumio Jul 08 09:48:43 volumio volumio[981]: info: Ignoring mount for partition: volumio_data Jul 08 09:48:43 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 08 09:48:43 volumio volumio[981]: info: Loading plugin "volumio_command_line_client"... Jul 08 09:48:43 volumio volumio[981]: info: Loading plugin "upnp"... Jul 08 09:48:43 volumio volumio[981]: info: [1751935723712] Starting Upmpd Daemon Jul 08 09:48:43 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 08 09:48:43 volumio volumio[981]: info: Loading plugin "my_music"... Jul 08 09:48:43 volumio volumio[981]: info: Loading plugin "mpd"... Jul 08 09:48:43 volumio kernel: Key type cifs.spnego registered Jul 08 09:48:43 volumio kernel: Key type cifs.idmap registered Jul 08 09:48:43 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. Jul 08 09:48:43 volumio kernel: CIFS: Attempting to mount //192.168.3.16/SoundData Jul 08 09:48:43 volumio kernel: cryptd: max_cpu_qlen set to 1000 Jul 08 09:48:44 volumio smbd[1180]: [2025/07/08 09:48:44.092433, 0] ../source3/param/loadparm.c:3362(process_usershare_file) Jul 08 09:48:44 volumio smbd[1180]: process_usershare_file: stat of /var/lib/samba/usershares/sounddata failed. Permission denied Jul 08 09:48:44 volumio smbd[1180]: [2025/07/08 09:48:44.094716, 0] ../source3/param/loadparm.c:3362(process_usershare_file) Jul 08 09:48:44 volumio smbd[1180]: process_usershare_file: stat of /var/lib/samba/usershares/sounddata failed. No such file or directory Jul 08 09:48:44 volumio sudo[1164]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:44 volumio kernel: CIFS: VFS: BAD_NETWORK_NAME: \\192.168.3.16\SoundData Jul 08 09:48:44 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -2 Jul 08 09:48:44 volumio volumio[981]: info: Loading plugin "upnp_browser"... Jul 08 09:48:44 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Jul 08 09:48:44 volumio volumio[981]: info: Loading plugin "alarm-clock"... Jul 08 09:48:45 volumio volumio[981]: info: Loading plugin "airplay_emulation"... Jul 08 09:48:45 volumio volumio[981]: info: Starting Shairport Sync Jul 08 09:48:45 volumio volumio[981]: info: Loading plugin "last_100"... Jul 08 09:48:45 volumio volumio[981]: info: Loading plugin "webradio"... Jul 08 09:48:45 volumio volumio[981]: info: Loading plugin "i2s_dacs"... Jul 08 09:48:45 volumio volumio[981]: info: Loading plugin "volumiodiscovery"... Jul 08 09:48:45 volumio volumio[981]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 08 09:48:45 volumio volumio[981]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 08 09:48:45 volumio volumio[981]: *** WARNING *** For more information see Jul 08 09:48:45 volumio volumio[981]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 08 09:48:45 volumio node[981]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 08 09:48:45 volumio volumio[981]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 08 09:48:45 volumio volumio[981]: *** WARNING *** For more information see Jul 08 09:48:45 volumio node[981]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 08 09:48:45 volumio node[981]: *** WARNING *** For more information see Jul 08 09:48:45 volumio node[981]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 08 09:48:45 volumio node[981]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 08 09:48:45 volumio node[981]: *** WARNING *** For more information see Jul 08 09:48:45 volumio volumio[981]: info: Applying required configuration parameters for plugin volumiodiscovery Jul 08 09:48:45 volumio volumio-remote-updater[562]: [2025-07-08 09:48:45] [connect] Successful connection Jul 08 09:48:45 volumio volumio[981]: info: Discovery: Started advertising with name: Volumio Jul 08 09:48:45 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 08 09:48:45 volumio volumio[981]: info: Loading plugin "spop"... Jul 08 09:48:46 volumio sudo[1147]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:47 volumio volumio[981]: info: Loading plugin "outputs"... Jul 08 09:48:47 volumio volumio[981]: info: Loading plugin "albumart"... Jul 08 09:48:47 volumio volumio[981]: info: Plugin example_plugin is not enabled Jul 08 09:48:47 volumio volumio[981]: info: Loading plugin "inputs"... Jul 08 09:48:47 volumio volumio[981]: info: Loading plugin "updater_comm"... Jul 08 09:48:47 volumio volumio[981]: info: Plugin mpdemulation is not enabled Jul 08 09:48:47 volumio volumio[981]: info: Loading plugin "rest_api"... Jul 08 09:48:47 volumio volumio[981]: info: Loading plugin "websocket"... Jul 08 09:48:47 volumio volumio[981]: info: Starting Socket.io Server version 2.3.0 Jul 08 09:48:47 volumio volumio[981]: info: Loading i18n strings for locale ja Jul 08 09:48:47 volumio volumio[981]: Updating browse sources language Jul 08 09:48:47 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 09:48:48 volumio volumio[981]: Forking 3 albumart workers Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::initPlayerControls Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 08 09:48:48 volumio volumio[981]: Express server listening on port 3000 Jul 08 09:48:48 volumio volumio[981]: [Metrics] WebUI: 9s 449.66ms Jul 08 09:48:48 volumio volumio[981]: info: CoreStateMachine::resetVolumioState Jul 08 09:48:48 volumio volumio[981]: info: CoreStateMachine::getcurrentVolume Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::volumioRetrievevolume Jul 08 09:48:48 volumio volumio[981]: info: Volumio Network Manager: Network status updated: 2 Jul 08 09:48:48 volumio volumio[981]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Jul 08 09:48:48 volumio volumio-remote-updater[562]: [2025-07-08 09:48:48] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1751935725 101 Jul 08 09:48:48 volumio volumio[981]: 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 Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 09:48:48 volumio volumio[981]: info: Reloading queue from file Jul 08 09:48:48 volumio volumio[981]: info: Setting Device type: Raspberry PI Jul 08 09:48:48 volumio volumio[981]: info: Completed loading Core Plugins Jul 08 09:48:48 volumio volumio[981]: info: Preparing to generate the ALSA configuration file Jul 08 09:48:48 volumio volumio[981]: info: VolumeController:: Volume=50 Mute =false Jul 08 09:48:48 volumio volumio[981]: info: CoreStateMachine::pushState Jul 08 09:48:48 volumio volumio[981]: info: CorePlayQueue::getTrack 0 Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Jul 08 09:48:48 volumio volumio[981]: info: CoreStateMachine::updateTrackBlock Jul 08 09:48:48 volumio volumio[981]: info: CorePlayQueue::getTrackBlock Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::volumioRetrievevolume Jul 08 09:48:48 volumio volumio[981]: info: CoreStateMachine::setRepeat null single undefined Jul 08 09:48:48 volumio volumio[981]: info: CoreStateMachine::pushState Jul 08 09:48:48 volumio volumio[981]: info: CorePlayQueue::getTrack 0 Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Jul 08 09:48:48 volumio volumio[981]: info: CoreStateMachine::setRandom true Jul 08 09:48:48 volumio volumio[981]: info: CoreStateMachine::pushState Jul 08 09:48:48 volumio volumio[981]: info: CorePlayQueue::getTrack 0 Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Jul 08 09:48:48 volumio volumio[981]: info: Asound.conf file unchanged, so no further update is needed Jul 08 09:48:48 volumio volumio[981]: info: Output device has changed, restarting MPD Jul 08 09:48:48 volumio volumio[981]: Starting albumart workers Jul 08 09:48:48 volumio volumio[981]: Starting albumart workers Jul 08 09:48:48 volumio volumio[981]: Starting albumart workers Jul 08 09:48:48 volumio volumio[981]: info: Output device has changed, restarting Shairport Sync Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:48 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 09:48:48 volumio sudo[1249]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 08 09:48:49 volumio sudo[1249]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:49 volumio sudo[1251]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 08 09:48:49 volumio sudo[1251]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:49 volumio sudo[1249]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:49 volumio systemd[1]: Stopping Music Player Daemon... Jul 08 09:48:49 volumio volumio[981]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 08 09:48:49 volumio volumio[981]: info: ___________ START PLUGINS ___________ Jul 08 09:48:49 volumio volumio[981]: info: ControllerMpd::onStart: Initializing MPD Jul 08 09:48:49 volumio volumio[981]: info: Creating MPD Configuration file Jul 08 09:48:49 volumio sudo[1258]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 08 09:48:49 volumio sudo[1258]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 08 09:48:49 volumio volumio[981]: info: [1751935729122] CoreMusicLibrary::Adding element DLNAサーバー Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 09:48:49 volumio sudo[1258]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:49 volumio sudo[1260]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 08 09:48:49 volumio sudo[1260]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 09:48:49 volumio systemd[1]: mpd.service: Succeeded. Jul 08 09:48:49 volumio systemd[1]: Stopped Music Player Daemon. Jul 08 09:48:49 volumio volumio[981]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 09:48:49 volumio systemd[1]: Starting Music Player Daemon... Jul 08 09:48:49 volumio volumio[981]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 08 09:48:49 volumio volumio[981]: info: [1751935729393] CoreMusicLibrary::Adding element Last_100 Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 08 09:48:49 volumio volumio[981]: info: [1751935729410] CoreMusicLibrary::Adding element Webradio Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 08 09:48:49 volumio volumio[981]: info: Initializing BBC Radios Jul 08 09:48:49 volumio sudo[1266]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jul 08 09:48:49 volumio sudo[1266]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:49 volumio sudo[1266]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 09:48:49 volumio volumio[981]: info: Creating Spotify config file Jul 08 09:48:49 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:49 volumio volumio[981]: info: Volumio Calling Home Jul 08 09:48:50 volumio volumio[981]: info: MPD Permissions set Jul 08 09:48:50 volumio volumio[981]: info: MPD Permissions set Jul 08 09:48:50 volumio volumio[981]: info: VolumeController:: Volume=50 Mute =false Jul 08 09:48:50 volumio volumio[981]: info: CoreStateMachine::pushState Jul 08 09:48:50 volumio volumio[981]: info: CorePlayQueue::getTrack 0 Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Jul 08 09:48:50 volumio volumio[981]: info: Discovery: adding 3baaa9fa-edf1-47c4-ac12-8eda9eba171e Jul 08 09:48:50 volumio volumio[981]: info: Discovery: Found device Volumio Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::volumioGetState Jul 08 09:48:50 volumio volumio[981]: info: CorePlayQueue::getTrack 0 Jul 08 09:48:50 volumio volumio[981]: info: Spotify config file written Jul 08 09:48:50 volumio sudo[1310]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 08 09:48:50 volumio sudo[1310]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:50 volumio volumio[981]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 08 09:48:50 volumio systemd[1]: Started go-librespot Daemon. Jul 08 09:48:50 volumio go-librespot[1313]: Librespot-go daemon starting... Jul 08 09:48:50 volumio sudo[1310]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:50 volumio volumio[981]: info: Starting Shairport Sync Jul 08 09:48:50 volumio volumio[981]: info: Starting Shairport Sync Jul 08 09:48:50 volumio volumio[981]: info: Starting Shairport Sync Jul 08 09:48:50 volumio sudo[1323]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 08 09:48:50 volumio sudo[1323]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:50 volumio sudo[1325]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 08 09:48:50 volumio sudo[1325]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:50 volumio volumio[981]: info: CoreCommandRouter::volumioGetState Jul 08 09:48:50 volumio volumio[981]: info: CorePlayQueue::getTrack 0 Jul 08 09:48:50 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 08 09:48:50 volumio sudo[1328]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 08 09:48:50 volumio systemd[1]: shairport-sync.service: Succeeded. Jul 08 09:48:50 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 08 09:48:50 volumio sudo[1328]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:50 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 08 09:48:50 volumio sudo[1323]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:50 volumio sudo[1325]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:50 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 08 09:48:50 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Jul 08 09:48:50 volumio systemd[1]: shairport-sync.service: Succeeded. Jul 08 09:48:50 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 08 09:48:50 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 08 09:48:50 volumio sudo[1328]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:50 volumio volumio[981]: info: Shairport-Sync Started Jul 08 09:48:50 volumio volumio[981]: Error adding Membership: Error: addMembership EINVAL Jul 08 09:48:50 volumio volumio[981]: info: Shairport-Sync Started Jul 08 09:48:50 volumio volumio[981]: info: Shairport-Sync Started Jul 08 09:48:50 volumio volumio[981]: info: Volumio called home Jul 08 09:48:50 volumio volumio[981]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jul 08 09:48:50 volumio go-librespot[1313]: time="2025-07-08T09:48:50+09:00" level=info msg="generated new device id: be0c219c66a502b0e96c3bcafcf08ae6d4571928" Jul 08 09:48:51 volumio mpd[1272]: Jul 08 09:48 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 08 09:48:51 volumio systemd[1]: Started Music Player Daemon. Jul 08 09:48:51 volumio sudo[1260]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:51 volumio sudo[1251]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:51 volumio go-librespot[1313]: time="2025-07-08T09:48:51+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 08 09:48:51 volumio go-librespot[1313]: time="2025-07-08T09:48:51+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jul 08 09:48:51 volumio go-librespot[1313]: time="2025-07-08T09:48:51+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jul 08 09:48:51 volumio volumio[981]: info: Completed starting Core Plugins Jul 08 09:48:51 volumio volumio[981]: info: ------------------------------------------- Jul 08 09:48:51 volumio volumio[981]: info: ----- MyVolumio plugins startup ---- Jul 08 09:48:51 volumio volumio[981]: info: ------------------------------------------- Jul 08 09:48:51 volumio volumio[981]: info: [MyVolumio PluginManager] Fetching plans data.... Jul 08 09:48:51 volumio go-librespot[1313]: time="2025-07-08T09:48:51+09:00" level=debug msg="zeroconf server listening on port 40023" Jul 08 09:48:51 volumio volumio[981]: info: MPD running with PID1272 Jul 08 09:48:51 volumio volumio[981]: ,establishing connection Jul 08 09:48:51 volumio volumio[981]: error: MPD error: The expression evaluated to a falsy value: Jul 08 09:48:51 volumio volumio[981]: assert.ok(self.idling) Jul 08 09:48:51 volumio volumio[981]: error: The expression evaluated to a falsy value: Jul 08 09:48:51 volumio volumio[981]: assert.ok(self.idling) Jul 08 09:48:51 volumio volumio[981]: error: MPD error: The expression evaluated to a falsy value: Jul 08 09:48:51 volumio volumio[981]: assert.ok(self.idling) Jul 08 09:48:51 volumio volumio[981]: error: The expression evaluated to a falsy value: Jul 08 09:48:51 volumio volumio[981]: assert.ok(self.idling) Jul 08 09:48:51 volumio volumio[981]: error: updateQueue error: null Jul 08 09:48:53 volumio volumio[981]: info: go-librespot daemon successfully initialized Jul 08 09:48:53 volumio sudo[1361]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=user,password=97LKSR7X,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.3.16/SoundData/ /mnt/NAS/NAS Jul 08 09:48:53 volumio sudo[1361]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:53 volumio kernel: CIFS: Attempting to mount //192.168.3.16/SoundData Jul 08 09:48:53 volumio smbd[1366]: [2025/07/08 09:48:53.554462, 0] ../source3/param/loadparm.c:3362(process_usershare_file) Jul 08 09:48:53 volumio smbd[1366]: process_usershare_file: stat of /var/lib/samba/usershares/sounddata failed. Permission denied Jul 08 09:48:53 volumio smbd[1366]: [2025/07/08 09:48:53.555370, 0] ../source3/param/loadparm.c:3362(process_usershare_file) Jul 08 09:48:53 volumio smbd[1366]: process_usershare_file: stat of /var/lib/samba/usershares/sounddata failed. No such file or directory Jul 08 09:48:53 volumio sudo[1361]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:53 volumio kernel: CIFS: VFS: BAD_NETWORK_NAME: \\192.168.3.16\SoundData Jul 08 09:48:53 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -2 Jul 08 09:48:53 volumio volumio[981]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Jul 08 09:48:53 volumio sudo[1368]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 08 09:48:53 volumio sudo[1368]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:53 volumio sudo[1368]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:53 volumio sudo[1370]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 08 09:48:53 volumio sudo[1370]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:53 volumio sudo[1370]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:53 volumio sudo[1373]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jul 08 09:48:53 volumio sudo[1373]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:53 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Jul 08 09:48:53 volumio sudo[1373]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:53 volumio volumio[981]: info: Upmpdcli Daemon Started Jul 08 09:48:54 volumio volumio[1376]: Generating RSA private key, 4096 bit long modulus (2 primes) Jul 08 09:48:56 volumio volumio[981]: info: Initializing connection to go-librespot Websocket Jul 08 09:48:56 volumio go-librespot[1313]: time="2025-07-08T09:48:56+09:00" level=debug msg="new websocket client" Jul 08 09:48:56 volumio volumio[981]: info: Connection to go-librespot Websocket established Jul 08 09:48:56 volumio volumio[981]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jul 08 09:48:56 volumio go-librespot[1313]: time="2025-07-08T09:48:56+09:00" level=debug msg="obtained new client token: AADFjRMuMrGIBqfxHNyhnTT0W7Iq5EMOC9QjggZGxnq847REq/rvmEEp5gLvqmPwGNiZulfzqMmBXhG8ey3i0XzQZ9WNTgPrTJu4sHS/+2K3R0wccy/7o7USKinyCoDRbyn1hULapBna99SkexH0IaYFiBnGya94Up0RqMlRBsteoiobhttre2S5ivi/oHjetMHvuPpo6IPljzjHI81l/h/kZhhHWcvrg9EZHhidbcVqXLfHwd7zXFrLp/k=" Jul 08 09:48:56 volumio go-librespot[1313]: time="2025-07-08T09:48:56+09:00" level=debug msg="completed keyexchange" Jul 08 09:48:57 volumio go-librespot[1313]: time="2025-07-08T09:48:57+09:00" level=debug msg="completed challenge" Jul 08 09:48:57 volumio go-librespot[1313]: time="2025-07-08T09:48:57+09:00" level=debug msg="authenticated as 314pxixc3avgsnfzimse6ayipja4" Jul 08 09:48:57 volumio go-librespot[1313]: time="2025-07-08T09:48:57+09:00" level=debug msg="authenticated as 314pxixc3avgsnfzimse6ayipja4" Jul 08 09:48:57 volumio go-librespot[1313]: time="2025-07-08T09:48:57+09:00" level=debug msg="dealer connection opened" Jul 08 09:48:57 volumio go-librespot[1313]: time="2025-07-08T09:48:57+09:00" level=info msg="accepted zeroconf user 314pxixc3avgsnfzimse6ayipja4 from Redmi Note 13 Pro 5G" Jul 08 09:48:57 volumio go-librespot[1313]: time="2025-07-08T09:48:57+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 08 09:48:57 volumio go-librespot[1313]: time="2025-07-08T09:48:57+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 08 09:48:57 volumio go-librespot[1313]: time="2025-07-08T09:48:57+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 08 09:48:57 volumio go-librespot[1313]: time="2025-07-08T09:48:57+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 08 09:48:57 volumio go-librespot[1313]: time="2025-07-08T09:48:57+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 08 09:48:57 volumio go-librespot[1313]: time="2025-07-08T09:48:57+09:00" level=debug msg="received connection id: YjBkMTE3YjUtYzVmMy00ZjZmLTg3OWItMTdmMzM5OTljNTZjK2RlYWxlcit0Y3A6Ly8wYWIxNTgzMy5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArMzk0M0IxNzAwNDZERUZERTE2RTRBMDE5MEY0OUZFRDhBNTEyRTQ1NTM4MEZGNjM3QjIzNjk1Nzc0ODk4OENDMw==" Jul 08 09:48:57 volumio go-librespot[1313]: time="2025-07-08T09:48:57+09:00" level=debug msg="put connect state because NEW_DEVICE" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="handling transfer player command from 3e75ec27a82dd2f6379f89849ece2d303ee7a5ad" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=trace msg="fetched new page 0 with 40 items (list: 40)" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="shuffled context with seed 12010363437339296573 (len: 40, keep: 32)" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="loading track spotify:track:1f3yAtsJtY87CTmM8RLnxf (paused: true, position: 4922ms)" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=trace msg="emitting websocket event: will_play" Jul 08 09:48:58 volumio volumio[981]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1f3yAtsJtY87CTmM8RLnxf","play_origin":"your_library"}} Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:1f3yAtsJtY87CTmM8RLnxf" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="requested aes key for file 7b63c0cca4a2a9d690e7c800f49a5652f999cf0d, gid: 1f3yAtsJtY87CTmM8RLnxf" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1378" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="fetched first chunk of 24, total size is 12167416 bytes" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=trace msg="seek to 4922ms (diff: 283ms, samples: 217060, bytes: 149080)" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1135" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="fetched chunk 1/23, size: 524288" Jul 08 09:48:58 volumio sudo[1397]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=user,password=97LKSR7X,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.3.16/SoundData/ /mnt/NAS/NAS Jul 08 09:48:58 volumio sudo[1397]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=info msg="loaded track \"Smells Like Teen Spirit\" (uri: spotify:track:1f3yAtsJtY87CTmM8RLnxf, paused: true, position: 4922ms, duration: 301920ms)" Jul 08 09:48:58 volumio kernel: CIFS: Attempting to mount //192.168.3.16/SoundData Jul 08 09:48:58 volumio smbd[1402]: [2025/07/08 09:48:58.643048, 0] ../source3/param/loadparm.c:3362(process_usershare_file) Jul 08 09:48:58 volumio smbd[1402]: process_usershare_file: stat of /var/lib/samba/usershares/sounddata failed. Permission denied Jul 08 09:48:58 volumio smbd[1402]: [2025/07/08 09:48:58.649893, 0] ../source3/param/loadparm.c:3362(process_usershare_file) Jul 08 09:48:58 volumio smbd[1402]: process_usershare_file: stat of /var/lib/samba/usershares/sounddata failed. No such file or directory Jul 08 09:48:58 volumio sudo[1397]: pam_unix(sudo:session): session closed for user root Jul 08 09:48:58 volumio volumio[981]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Jul 08 09:48:58 volumio kernel: CIFS: VFS: BAD_NETWORK_NAME: \\192.168.3.16\SoundData Jul 08 09:48:58 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -2 Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="fetched chunk 2/23, size: 524288" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=trace msg="emitting websocket event: metadata" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=trace msg="emitting websocket event: active" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="sending successful reply for delaer request" Jul 08 09:48:58 volumio volumio[981]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1f3yAtsJtY87CTmM8RLnxf","name":"Smells Like Teen Spirit","artist_names":["Nirvana"],"album_name":"Nevermind (Deluxe Edition)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0228a90d00a2819504364880e4","position":4922,"duration":301920,"release_date":"year:1991 month:9 day:26","track_number":1,"disc_number":1}} Jul 08 09:48:58 volumio volumio[981]: SPOTIFY: received: {"type":"active","data":null} Jul 08 09:48:58 volumio volumio[981]: info: Aligning Spotify Volume to Volumio Volume Jul 08 09:48:58 volumio volumio[981]: info: CoreCommandRouter::volumioGetState Jul 08 09:48:58 volumio volumio[981]: info: CorePlayQueue::getTrack 0 Jul 08 09:48:58 volumio volumio[981]: info: Setting Spotify Volume from Volumio: 50 Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="fetched chunk 3/23, size: 524288" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 08 09:48:58 volumio go-librespot[1313]: time="2025-07-08T09:48:58+09:00" level=trace msg="emitting websocket event: paused" Jul 08 09:48:58 volumio volumio[981]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:1f3yAtsJtY87CTmM8RLnxf","play_origin":"your_library"}} Jul 08 09:48:58 volumio volumio[981]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 09:48:58 volumio volumio[981]: TypeError: Cannot read property 'service' of undefined Jul 08 09:48:58 volumio volumio[981]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Jul 08 09:48:58 volumio volumio[981]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Jul 08 09:48:58 volumio volumio[981]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Jul 08 09:48:58 volumio volumio[981]: at WebSocket.emit (events.js:315:20) Jul 08 09:48:58 volumio volumio[981]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Jul 08 09:48:58 volumio volumio[981]: at Receiver.emit (events.js:315:20) Jul 08 09:48:58 volumio volumio[981]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Jul 08 09:48:58 volumio volumio[981]: at internal/process/task_queues.js:149:7 Jul 08 09:48:58 volumio volumio[981]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Jul 08 09:48:58 volumio volumio[981]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Jul 08 09:48:58 volumio volumio[981]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jul 08 09:48:58 volumio volumio[981]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 08 09:48:59 volumio sudo[1412]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-08 09:47 Jul 08 09:48:59 volumio sudo[1412]: 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"