-- Logs begin at Sun 2026-04-05 10:19:47 JST, end at Wed 2026-04-15 20:05:04 JST. -- Apr 15 20:04:50 volumio-3b systemd-timedated[1020]: Changed local time to Wed Apr 15 20:04:50 2026 Apr 15 20:04:50 volumio-3b sudo[1018]: pam_unix(sudo:session): session closed for user root Apr 15 20:04:50 volumio-3b volumio-time-update[626]: volumio-time-update-util: System time updated successfully. Apr 15 20:04:50 volumio-3b systemd[1]: Starting Daily apt download activities... Apr 15 20:04:50 volumio-3b systemd[1]: Started Volumio Time Update Utility. Apr 15 20:04:50 volumio-3b systemd[1]: Reached target Multi-User System. Apr 15 20:04:50 volumio-3b systemd[1]: Reached target Graphical Interface. Apr 15 20:04:50 volumio-3b systemd[1]: Starting Update UTMP about System Runlevel Changes... Apr 15 20:04:50 volumio-3b systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Apr 15 20:04:50 volumio-3b systemd[1]: Started Update UTMP about System Runlevel Changes. Apr 15 20:04:50 volumio-3b volumio[970]: info: Loading plugin "network"... Apr 15 20:04:50 volumio-3b volumio[970]: info: Refreshing Cached IP Addresses Apr 15 20:04:50 volumio-3b sudo[1044]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 15 20:04:50 volumio-3b sudo[1044]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:04:50 volumio-3b sudo[1044]: pam_unix(sudo:session): session closed for user root Apr 15 20:04:50 volumio-3b sudo[1048]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 15 20:04:50 volumio-3b sudo[1048]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:04:50 volumio-3b sudo[1048]: pam_unix(sudo:session): session closed for user root Apr 15 20:04:50 volumio-3b volumio[970]: info: Loading plugin "services"... Apr 15 20:04:50 volumio-3b volumio[970]: info: Loading plugin "volumio5onboarding"... Apr 15 20:04:50 volumio-3b sudo[1057]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Apr 15 20:04:50 volumio-3b sudo[1057]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:04:50 volumio-3b volumio[970]: info: Loading plugin "alsa_controller"... Apr 15 20:04:50 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 15 20:04:50 volumio-3b volumio[970]: info: Loading plugin "wizard"... Apr 15 20:04:50 volumio-3b volumio[970]: info: Loading plugin "networkfs"... Apr 15 20:04:50 volumio-3b volumio[970]: info: Starting Udev Watcher for removable devices Apr 15 20:04:50 volumio-3b sudo[1091]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=sakurai.makoto@outlook.com,password=7Sakura5,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.155.61/m /mnt/NAS/J4105NHU Apr 15 20:04:50 volumio-3b sudo[1091]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:04:50 volumio-3b volumio[970]: info: Ignoring mount for partition: boot Apr 15 20:04:50 volumio-3b volumio[970]: info: Ignoring mount for partition: volumio Apr 15 20:04:50 volumio-3b volumio[970]: info: Ignoring mount for partition: volumio_data Apr 15 20:04:50 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 15 20:04:51 volumio-3b volumio[970]: info: Loading plugin "volumio_command_line_client"... Apr 15 20:04:51 volumio-3b volumio[970]: info: Loading plugin "upnp"... Apr 15 20:04:51 volumio-3b volumio[970]: info: [1776251091026] Starting Upmpd Daemon Apr 15 20:04:51 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 15 20:04:51 volumio-3b volumio[970]: info: Loading plugin "my_music"... Apr 15 20:04:51 volumio-3b volumio[970]: info: Loading plugin "mpd"... Apr 15 20:04:51 volumio-3b systemd[1]: apt-daily.service: Succeeded. Apr 15 20:04:51 volumio-3b kernel: Key type cifs.spnego registered Apr 15 20:04:51 volumio-3b kernel: Key type cifs.idmap registered Apr 15 20:04:51 volumio-3b 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. Apr 15 20:04:51 volumio-3b kernel: CIFS: Attempting to mount //192.168.155.61/m Apr 15 20:04:51 volumio-3b systemd[1]: Started Daily apt download activities. Apr 15 20:04:51 volumio-3b systemd[1]: Starting Daily apt upgrade and clean activities... Apr 15 20:04:51 volumio-3b sudo[1057]: pam_unix(sudo:session): session closed for user root Apr 15 20:04:51 volumio-3b volumio[970]: info: Plugin upnp_browser is not enabled Apr 15 20:04:51 volumio-3b volumio[970]: info: Loading plugin "alarm-clock"... Apr 15 20:04:51 volumio-3b sudo[1091]: pam_unix(sudo:session): session closed for user root Apr 15 20:04:52 volumio-3b volumio[970]: info: Plugin airplay_emulation is not enabled Apr 15 20:04:52 volumio-3b volumio[970]: info: Loading plugin "last_100"... Apr 15 20:04:52 volumio-3b volumio[970]: info: Loading plugin "webradio"... Apr 15 20:04:52 volumio-3b systemd[1]: apt-daily-upgrade.service: Succeeded. Apr 15 20:04:52 volumio-3b systemd[1]: Started Daily apt upgrade and clean activities. Apr 15 20:04:52 volumio-3b systemd[1]: Startup finished in 13.343s (kernel) + 24.666s (userspace) = 38.010s. Apr 15 20:04:52 volumio-3b volumio[970]: info: Loading plugin "i2s_dacs"... Apr 15 20:04:52 volumio-3b volumio[970]: info: Loading plugin "volumiodiscovery"... Apr 15 20:04:52 volumio-3b volumio[970]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 15 20:04:52 volumio-3b volumio[970]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 15 20:04:52 volumio-3b volumio[970]: *** WARNING *** For more information see Apr 15 20:04:52 volumio-3b node[970]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 15 20:04:52 volumio-3b volumio[970]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 15 20:04:52 volumio-3b volumio[970]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 15 20:04:52 volumio-3b volumio[970]: *** WARNING *** For more information see Apr 15 20:04:52 volumio-3b node[970]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 15 20:04:52 volumio-3b node[970]: *** WARNING *** For more information see Apr 15 20:04:52 volumio-3b node[970]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 15 20:04:52 volumio-3b node[970]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 15 20:04:52 volumio-3b node[970]: *** WARNING *** For more information see Apr 15 20:04:52 volumio-3b volumio[970]: info: Applying required configuration parameters for plugin volumiodiscovery Apr 15 20:04:52 volumio-3b volumio[970]: info: Discovery: Started advertising with name: Volumio-3B Apr 15 20:04:52 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 15 20:04:52 volumio-3b volumio[970]: info: Loading plugin "spop"... Apr 15 20:04:54 volumio-3b volumio[970]: info: Loading plugin "outputs"... Apr 15 20:04:54 volumio-3b volumio[970]: info: Loading plugin "albumart"... Apr 15 20:04:54 volumio-3b volumio[970]: info: Plugin example_plugin is not enabled Apr 15 20:04:54 volumio-3b volumio[970]: info: Loading plugin "inputs"... Apr 15 20:04:54 volumio-3b volumio[970]: info: Loading plugin "updater_comm"... Apr 15 20:04:54 volumio-3b volumio[970]: info: Plugin mpdemulation is not enabled Apr 15 20:04:54 volumio-3b volumio[970]: info: Loading plugin "rest_api"... Apr 15 20:04:54 volumio-3b volumio[970]: info: Loading plugin "websocket"... Apr 15 20:04:54 volumio-3b volumio[970]: info: Starting Socket.io Server version 2.3.0 Apr 15 20:04:54 volumio-3b volumio[970]: info: Loading i18n strings for locale ja Apr 15 20:04:54 volumio-3b volumio[970]: Updating browse sources language Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 15 20:04:54 volumio-3b volumio[970]: Forking 3 albumart workers Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::initPlayerControls Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 15 20:04:54 volumio-3b volumio[970]: Express server listening on port 3000 Apr 15 20:04:54 volumio-3b volumio[970]: [Metrics] WebUI: 8s 461.32ms Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreStateMachine::resetVolumioState Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreStateMachine::getcurrentVolume Apr 15 20:04:54 volumio-3b volumio[970]: info: CoreCommandRouter::volumioRetrievevolume Apr 15 20:04:54 volumio-3b volumio[970]: info: Volumio Network Manager: Network status updated: 2 Apr 15 20:04:55 volumio-3b volumio[970]: info: Reloading queue from file Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 15 20:04:55 volumio-3b volumio[970]: info: Setting Device type: Raspberry PI Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreStateMachine::setRepeat null single undefined Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreStateMachine::pushState Apr 15 20:04:55 volumio-3b volumio[970]: info: CorePlayQueue::getTrack 0 Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::volumioPushState Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreStateMachine::setRandom null Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreStateMachine::pushState Apr 15 20:04:55 volumio-3b volumio[970]: info: CorePlayQueue::getTrack 0 Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::volumioPushState Apr 15 20:04:55 volumio-3b volumio[970]: info: Completed loading Core Plugins Apr 15 20:04:55 volumio-3b volumio[970]: info: Preparing to generate the ALSA configuration file Apr 15 20:04:55 volumio-3b volumio[970]: info: VolumeController:: Volume=51 Mute =false Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreStateMachine::pushState Apr 15 20:04:55 volumio-3b volumio[970]: info: CorePlayQueue::getTrack 0 Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::volumioPushState Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreStateMachine::updateTrackBlock Apr 15 20:04:55 volumio-3b volumio[970]: info: CorePlayQueue::getTrackBlock Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::volumioRetrievevolume Apr 15 20:04:55 volumio-3b volumio[970]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Apr 15 20:04:55 volumio-3b volumio[970]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a32082 Apr 15 20:04:55 volumio-3b volumio[970]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Apr 15 20:04:55 volumio-3b volumio[970]: info: Asound.conf file unchanged, so no further update is needed Apr 15 20:04:55 volumio-3b volumio[970]: info: Output device has changed, restarting MPD Apr 15 20:04:55 volumio-3b volumio[970]: info: ___________ START PLUGINS ___________ Apr 15 20:04:55 volumio-3b sudo[1228]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 15 20:04:55 volumio-3b sudo[1228]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:04:55 volumio-3b sudo[1228]: pam_unix(sudo:session): session closed for user root Apr 15 20:04:55 volumio-3b sudo[1230]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 15 20:04:55 volumio-3b sudo[1230]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:04:55 volumio-3b volumio[970]: info: ControllerMpd::onStart: Initializing MPD Apr 15 20:04:55 volumio-3b volumio[970]: info: Creating MPD Configuration file Apr 15 20:04:55 volumio-3b sudo[1233]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Apr 15 20:04:55 volumio-3b sudo[1233]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:04:55 volumio-3b sudo[1237]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 15 20:04:55 volumio-3b sudo[1237]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 15 20:04:55 volumio-3b volumio[970]: info: [1776251095514] CoreMusicLibrary::Adding element Last_100 Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 15 20:04:55 volumio-3b volumio[970]: info: [1776251095519] CoreMusicLibrary::Adding element Webradio Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 15 20:04:55 volumio-3b sudo[1237]: pam_unix(sudo:session): session closed for user root Apr 15 20:04:55 volumio-3b volumio[970]: Starting albumart workers Apr 15 20:04:55 volumio-3b sudo[1241]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 15 20:04:55 volumio-3b volumio[970]: info: Initializing BBC Radios Apr 15 20:04:55 volumio-3b systemd[1]: Listening on mpd.socket. Apr 15 20:04:55 volumio-3b sudo[1241]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:04:55 volumio-3b systemd[1]: Starting Music Player Daemon... Apr 15 20:04:55 volumio-3b volumio[970]: Starting albumart workers Apr 15 20:04:55 volumio-3b systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Apr 15 20:04:55 volumio-3b systemd[1]: mpd.service: Succeeded. Apr 15 20:04:55 volumio-3b systemd[1]: Stopped Music Player Daemon. Apr 15 20:04:55 volumio-3b systemd[1]: Started Volumio5 Onboarding Server. Apr 15 20:04:55 volumio-3b systemd[1]: Starting Music Player Daemon... Apr 15 20:04:55 volumio-3b sudo[1233]: pam_unix(sudo:session): session closed for user root Apr 15 20:04:55 volumio-3b volumio[970]: Starting albumart workers Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 15 20:04:55 volumio-3b volumio[970]: info: Creating Spotify config file Apr 15 20:04:55 volumio-3b sudo[1251]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Apr 15 20:04:55 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:55 volumio-3b sudo[1251]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:04:55 volumio-3b sudo[1251]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Apr 15 20:04:55 volumio-3b sudo[1251]: pam_unix(sudo:session): session closed for user root Apr 15 20:04:56 volumio-3b volumio[970]: info: Volumio Calling Home Apr 15 20:04:56 volumio-3b volumio[970]: info: MPD Permissions set Apr 15 20:04:56 volumio-3b volumio[970]: info: Spotify config file written Apr 15 20:04:56 volumio-3b sudo[1269]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 15 20:04:56 volumio-3b sudo[1269]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:04:56 volumio-3b volumio5-onboarding[1248]: time=2026-04-15T20:04:56.373+09:00 level=INFO msg="running volumio5-device-gateway" version=687ad144+CHANGES buildDate=2026-02-10T16:50:24Z Apr 15 20:04:56 volumio-3b volumio[970]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Apr 15 20:04:56 volumio-3b systemd[1]: Started go-librespot Daemon. Apr 15 20:04:56 volumio-3b go-librespot[1271]: go-librespot daemon starting... Apr 15 20:04:56 volumio-3b volumio[970]: info: No need to fix Spotify hosts Apr 15 20:04:56 volumio-3b sudo[1269]: pam_unix(sudo:session): session closed for user root Apr 15 20:04:56 volumio-3b volumio[970]: info: Discovery: adding 34f5e2d0-3cc4-4e63-9065-f80c213bbda0 Apr 15 20:04:56 volumio-3b volumio[970]: info: Discovery: Found device Volumio-3B Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::volumioGetState Apr 15 20:04:56 volumio-3b volumio[970]: info: CorePlayQueue::getTrack 0 Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 20:04:56 volumio-3b volumio[970]: info: Discovery: adding 995d288f-202a-43d7-9b16-498974bdba55 Apr 15 20:04:56 volumio-3b volumio[970]: info: Discovery: Found device Volumio-4B Apr 15 20:04:56 volumio-3b volumio[970]: info: Discovery: Connecting to remote: 192.168.155.14 Apr 15 20:04:56 volumio-3b volumio[970]: info: VolumeController:: Volume=51 Mute =false Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreStateMachine::pushState Apr 15 20:04:56 volumio-3b volumio[970]: info: CorePlayQueue::getTrack 0 Apr 15 20:04:56 volumio-3b volumio[970]: info: CoreCommandRouter::volumioPushState Apr 15 20:04:56 volumio-3b volumio[970]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Apr 15 20:04:56 volumio-3b kernel: hwmon hwmon1: Undervoltage detected! Apr 15 20:04:57 volumio-3b volumio[970]: info: Discovery: Connected to remote: 192.168.155.14 Apr 15 20:04:57 volumio-3b volumio[970]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Apr 15 20:04:57 volumio-3b volumio[970]: info: Received Get System Info Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 15 20:04:57 volumio-3b volumio[970]: info: Discovery: Getting this device information Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::volumioGetState Apr 15 20:04:57 volumio-3b volumio[970]: info: CorePlayQueue::getTrack 0 Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 15 20:04:57 volumio-3b volumio5-onboarding[1248]: time=2026-04-15T20:04:57.113+09:00 level=INFO msg="system info for 7af53fe2733e0820d1e6a947eb09341f" deviceName=Volumio-3B deviceVariant=volumio deviceModel= softwareVersion=3.912 Apr 15 20:04:57 volumio-3b volumio[970]: info: Received Get System Info Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 15 20:04:57 volumio-3b volumio[970]: info: Discovery: Getting this device information Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::volumioGetState Apr 15 20:04:57 volumio-3b volumio[970]: info: CorePlayQueue::getTrack 0 Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 15 20:04:57 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:57+09:00" level=info msg="running go-librespot 0.4.0" Apr 15 20:04:57 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:57+09:00" level=debug msg="app state loaded" Apr 15 20:04:57 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:57+09:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::volumioGetState Apr 15 20:04:57 volumio-3b volumio[970]: info: CorePlayQueue::getTrack 0 Apr 15 20:04:57 volumio-3b volumio[970]: info: Volumio called home Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 15 20:04:57 volumio-3b volumio5-onboarding[1248]: time=2026-04-15T20:04:57.356+09:00 level=INFO msg="enabling local network discovery" Apr 15 20:04:57 volumio-3b volumio5-onboarding[1248]: time=2026-04-15T20:04:57.411+09:00 level=INFO msg="enabling BLE discovery" Apr 15 20:04:57 volumio-3b bluetoothd[741]: src/adapter.c:store_adapter_info() Unable set contents for /usr/var/lib/bluetooth/B8:27:EB:9B:E1:00/settings: (Failed to create file “/usr/var/lib/bluetooth/B8:27:EB:9B:E1:00/settings.0M6JN3”: No such file or directory) Apr 15 20:04:57 volumio-3b volumio5-onboarding[1248]: time=2026-04-15T20:04:57.546+09:00 level=INFO msg="bootstrapping state" hasInternet=true Apr 15 20:04:57 volumio-3b volumio[970]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 15 20:04:57 volumio-3b volumio[970]: SPOTIFY: BQC0AF3nzb2t5QnHvUAilhZue6UeG-W1xUYGEkj6tRw6zxC5sKr3Hq1FytHXK8l3AQ-PAxW2Hu3x5AlHesQZipFx1vaMJrdyx483NsTTp7EowOduy4JM_m36qpzQk66bjncH5dUcFzCkzKTEJ7EEbeN_dlVxAfSwgqQxkzYDaMVr8WkDq_sfp28fVnoNj3KouuzEloHEFZta9eSY4LNpjmFZkslWEoilBq42vXS8WTLDesgkbfgmhkw3aLIPyTr2yUYdJvtNh3DWx3aQTvZNOkDVXLhK0npTUJw Apr 15 20:04:57 volumio-3b volumio[970]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 15 20:04:57 volumio-3b volumio[970]: info: New Spotify access token = BQC0AF3nzb2t5QnHvUAilhZue6UeG-W1xUYGEkj6tRw6zxC5sKr3Hq1FytHXK8l3AQ-PAxW2Hu3x5AlHesQZipFx1vaMJrdyx483NsTTp7EowOduy4JM_m36qpzQk66bjncH5dUcFzCkzKTEJ7EEbeN_dlVxAfSwgqQxkzYDaMVr8WkDq_sfp28fVnoNj3KouuzEloHEFZta9eSY4LNpjmFZkslWEoilBq42vXS8WTLDesgkbfgmhkw3aLIPyTr2yUYdJvtNh3DWx3aQTvZNOkDVXLhK0npTUJw Apr 15 20:04:57 volumio-3b volumio[970]: info: Spotify credentials grant success - running version from March 24, 2019 Apr 15 20:04:57 volumio-3b volumio[970]: info: Received Get System Info Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 15 20:04:57 volumio-3b volumio[970]: info: Discovery: Getting this device information Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::volumioGetState Apr 15 20:04:57 volumio-3b volumio[970]: info: CorePlayQueue::getTrack 0 Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 15 20:04:57 volumio-3b volumio[970]: SPOTIFY: User informations: {"country":"JP","display_name":"makolabo","email":"makolabo@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/makolabo"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/makolabo","id":"makolabo","images":[],"product":"premium","type":"user","uri":"spotify:user:makolabo"} Apr 15 20:04:57 volumio-3b volumio[970]: info: Spotify Successfully logged in Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 15 20:04:57 volumio-3b volumio[970]: info: [1776251097827] CoreMusicLibrary::Adding element Spotify Apr 15 20:04:57 volumio-3b volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 15 20:04:57 volumio-3b volumio[970]: Cannot find translation for source Spotify Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=info msg="zeroconf server listening on port 42147" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="obtained new client token: AABF9czSGoscIwe+mmqWrKYYiY88ku9Zn4KPrNsKawj8jCryUEX5HePaxIIamWsLQ4H8htcZwSW3g0o6GUsAqlzlWTMike/q2Zj5Kclo+3NLUdH4mCVUOguw+FDX8dmLUKDI2Ky6ajes9uZSoxBKxdGKB3oDEDvSYQ8nkHMSAB7imCdiYYnuFTug7rTOd56QTFx72ExFh8JPI/q0vkTEZR5k4khOmAPeYtTVMVWN5ZHhTrbmi9zNSw==" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="completed keyexchange" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="completed challenge" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=info msg="authenticated AP" username="ma****bo" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=info msg="authenticated Login5" username="ma****bo" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="initializing zeroconf session" username="ma****bo" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="dealer connection opened" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=trace msg="starting accesspoint recv loop" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=trace msg="starting dealer recv loop" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=trace msg="received accesspoint ping" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 15 20:04:58 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:58+09:00" level=debug msg="received connection id: NjdjNzUzNzAtZmRj...MDVGMTk2M0Y2Mw==" Apr 15 20:04:59 volumio-3b go-librespot[1271]: time="2026-04-15T20:04:59+09:00" level=debug msg="put connect state because NEW_DEVICE" Apr 15 20:04:59 volumio-3b volumio[970]: info: go-librespot daemon successfully initialized Apr 15 20:05:00 volumio-3b systemd[1]: systemd-fsckd.service: Succeeded. Apr 15 20:05:00 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:00+09:00" level=trace msg="received accesspoint pong ack" Apr 15 20:05:00 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:00+09:00" level=debug msg="handling transfer player command from 39786714d909a3f64869d2a64eceb1989fee3c3e" Apr 15 20:05:00 volumio-3b mpd[1257]: Apr 15 20:05 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 15 20:05:00 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:00+09:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E360kWkPPyeZ5" Apr 15 20:05:00 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:00+09:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E360kWkPPyeZ5" Apr 15 20:05:00 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:00+09:00" level=debug msg="loading track (paused: false, position: 78575ms)" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:01 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:01+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 15 20:05:01 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:01+09:00" level=trace msg="emitting websocket event: will_play" Apr 15 20:05:01 volumio-3b sudo[1334]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 15 20:05:01 volumio-3b systemd[1]: Started Music Player Daemon. Apr 15 20:05:01 volumio-3b sudo[1334]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:05:01 volumio-3b sudo[1230]: pam_unix(sudo:session): session closed for user root Apr 15 20:05:01 volumio-3b sudo[1241]: pam_unix(sudo:session): session closed for user root Apr 15 20:05:01 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:01+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 314" Apr 15 20:05:01 volumio-3b sudo[1338]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 15 20:05:01 volumio-3b sudo[1338]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:05:01 volumio-3b sudo[1334]: pam_unix(sudo:session): session closed for user root Apr 15 20:05:01 volumio-3b sudo[1338]: pam_unix(sudo:session): session closed for user root Apr 15 20:05:01 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:01+09:00" level=debug msg="selected format OGG_VORBIS_320 (872433ba1898341fb8d98d56a1e8527631343b36)" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:01 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:01+09:00" level=debug msg="requested aes key for file 872433ba1898341fb8d98d56a1e8527631343b36, gid: 7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:01 volumio-3b sudo[1342]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Apr 15 20:05:01 volumio-3b sudo[1342]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 15 20:05:01 volumio-3b volumio[970]: info: Completed starting Core Plugins Apr 15 20:05:01 volumio-3b volumio[970]: info: ------------------------------------------- Apr 15 20:05:01 volumio-3b volumio[970]: info: ----- MyVolumio plugins startup ---- Apr 15 20:05:01 volumio-3b volumio[970]: info: ------------------------------------------- Apr 15 20:05:01 volumio-3b volumio[970]: info: [MyVolumio PluginManager] Fetching plans data.... Apr 15 20:05:01 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:01+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1361" Apr 15 20:05:01 volumio-3b systemd[1]: Started UPnP Renderer front-end to MPD. Apr 15 20:05:01 volumio-3b volumio[970]: error: MPD error: The expression evaluated to a falsy value: Apr 15 20:05:01 volumio-3b volumio[970]: assert.ok(self.idling) Apr 15 20:05:01 volumio-3b volumio[970]: error: The expression evaluated to a falsy value: Apr 15 20:05:01 volumio-3b volumio[970]: assert.ok(self.idling) Apr 15 20:05:01 volumio-3b sudo[1342]: pam_unix(sudo:session): session closed for user root Apr 15 20:05:01 volumio-3b volumio[970]: info: MPD running with PID1257 Apr 15 20:05:01 volumio-3b volumio[970]: ,establishing connection Apr 15 20:05:01 volumio-3b volumio[970]: error: updateQueue error: null Apr 15 20:05:01 volumio-3b volumio[970]: info: Upmpdcli Daemon Started Apr 15 20:05:01 volumio-3b volumio[970]: error: updateQueue error: null Apr 15 20:05:01 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:01+09:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:01 volumio-3b volumio[1346]: Generating RSA private key, 4096 bit long modulus (2 primes) Apr 15 20:05:01 volumio-3b volumio-remote-updater[631]: [2026-04-15 20:05:01] [connect] Successful connection Apr 15 20:05:01 volumio-3b volumio-remote-updater[631]: [2026-04-15 20:05:01] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1776251101 101 Apr 15 20:05:01 volumio-3b volumio[970]: 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 Apr 15 20:05:01 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:01+09:00" level=debug msg="fetched first chunk of 21, total size is 10775180 bytes" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:02 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:02+09:00" level=debug msg="fetched chunk 2/20, size: 524288" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:02 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:02+09:00" level=debug msg="fetched chunk 1/20, size: 524288" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:02 volumio-3b sh[518]: timed out Apr 15 20:05:02 volumio-3b dhcpcd[568]: timed out Apr 15 20:05:02 volumio-3b sh[518]: dhcpcd exited Apr 15 20:05:02 volumio-3b dhcpcd[568]: dhcpcd exited Apr 15 20:05:02 volumio-3b sh[518]: ifup: failed to bring up eth0 Apr 15 20:05:02 volumio-3b systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Apr 15 20:05:02 volumio-3b systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Apr 15 20:05:02 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:02+09:00" level=debug msg="fetched chunk 3/20, size: 524288" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:02 volumio-3b volumio[970]: info: Initializing connection to go-librespot Websocket Apr 15 20:05:02 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:02+09:00" level=debug msg="new websocket client" Apr 15 20:05:02 volumio-3b volumio[970]: info: Connection to go-librespot Websocket established Apr 15 20:05:03 volumio-3b kernel: hwmon hwmon1: Voltage normalised Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=debug msg="fetched chunk 6/20, size: 524288" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=trace msg="seek to 78575ms (diff: 134ms, samples: 3465157, bytes: 3305180)" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=debug msg="created new output device" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09: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, PCM format = FLOAT_LE" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=info msg="loaded track \"Sonthee\" (paused: false, position: 78575ms, duration: 256000ms, prefetched: false)" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=debug msg="fetched chunk 9/20, size: 524288" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=debug msg="fetched chunk 8/20, size: 524288" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=trace msg="scheduling prefetch in 147s" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=trace msg="emitting websocket event: metadata" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=trace msg="emitting websocket event: active" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=debug msg="sending successful reply for dealer request" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 15 20:05:03 volumio-3b volumio[970]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7fKAiHWnUcGeZ4BFFItpQy","name":"Sonthee","artist_names":["LAR"],"album_name":"Sonthee","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0266c0890cfe0050c31e2f6e3d","position":78575,"duration":256000,"release_date":"year:2022 month:10 day:21","track_number":1,"disc_number":1}} Apr 15 20:05:03 volumio-3b volumio[970]: SPOTIFY: received: {"type":"active","data":null} Apr 15 20:05:03 volumio-3b volumio[970]: info: Aligning Spotify Volume to Volumio Volume Apr 15 20:05:03 volumio-3b volumio[970]: info: CoreCommandRouter::volumioGetState Apr 15 20:05:03 volumio-3b volumio[970]: info: CorePlayQueue::getTrack 0 Apr 15 20:05:03 volumio-3b volumio[970]: info: Setting Spotify Volume from Volumio: 51 Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=debug msg="fetched chunk 7/20, size: 524288" uri="spotify:track:7fKAiHWnUcGeZ4BFFItpQy" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 15 20:05:03 volumio-3b go-librespot[1271]: time="2026-04-15T20:05:03+09:00" level=trace msg="emitting websocket event: playing" Apr 15 20:05:03 volumio-3b volumio[970]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1E360kWkPPyeZ5","uri":"spotify:track:7fKAiHWnUcGeZ4BFFItpQy","resume":false,"play_origin":"playlist/ondemand"}} Apr 15 20:05:03 volumio-3b volumio[970]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 15 20:05:03 volumio-3b volumio[970]: TypeError: Cannot read property 'service' of undefined Apr 15 20:05:03 volumio-3b volumio[970]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Apr 15 20:05:03 volumio-3b volumio[970]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Apr 15 20:05:03 volumio-3b volumio[970]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Apr 15 20:05:03 volumio-3b volumio[970]: at WebSocket.emit (events.js:315:20) Apr 15 20:05:03 volumio-3b volumio[970]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Apr 15 20:05:03 volumio-3b volumio[970]: at Receiver.emit (events.js:315:20) Apr 15 20:05:03 volumio-3b volumio[970]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Apr 15 20:05:03 volumio-3b volumio[970]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Apr 15 20:05:03 volumio-3b volumio[970]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Apr 15 20:05:03 volumio-3b volumio[970]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Apr 15 20:05:03 volumio-3b volumio[970]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 15 20:05:04 volumio-3b sudo[1374]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-04-15 20:04 Apr 15 20:05:04 volumio-3b sudo[1374]: 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="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="464fc672d77d3df6ee72b331d36cdf1fa936e1ec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 27 Feb 2026 10:59:40 AM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="37c6ab864cb114e1344d540995c69f86"