-- Logs begin at Sat 2025-12-20 07:31:25 JST, end at Sat 2025-12-20 16:48:36 JST. -- Dec 20 16:47:01 jbl-4312 go-librespot[10222]: time="2025-12-20T16:47:01+09:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Dec 20 16:47:01 jbl-4312 volumio[3110]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Dec 20 16:47:01 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 20 16:47:01 jbl-4312 sudo[11641]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service Dec 20 16:47:01 jbl-4312 sudo[11641]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:01 jbl-4312 volumio[3110]: info: Disabling plugin spop Dec 20 16:47:01 jbl-4312 volumio[3110]: info: Done. Dec 20 16:47:01 jbl-4312 volumio[3110]: info: Connection to go-librespot Websocket closed Dec 20 16:47:01 jbl-4312 systemd[1]: Stopping go-librespot Daemon... Dec 20 16:47:01 jbl-4312 systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Dec 20 16:47:01 jbl-4312 systemd[1]: go-librespot-daemon.service: Succeeded. Dec 20 16:47:01 jbl-4312 systemd[1]: Stopped go-librespot Daemon. Dec 20 16:47:01 jbl-4312 sudo[11641]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:03 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 20 16:47:07 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:07.630+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:08 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:08.062+09:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0a00 addr=10 Dec 20 16:47:08 jbl-4312 volumiologrotate[2841]: ls: cannot access '/var/log/samba/log.wb-JBL': No such file or directory Dec 20 16:47:08 jbl-4312 volumiologrotate[2841]: ls: cannot access '4312': No such file or directory Dec 20 16:47:12 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:12.640+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:13 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:13.056+09:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0a00 addr=10 Dec 20 16:47:14 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 20 16:47:14 jbl-4312 volumio[3110]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 20 16:47:14 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 20 16:47:14 jbl-4312 volumio[3110]: info: Received Get System Version Dec 20 16:47:14 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 20 16:47:14 jbl-4312 volumio[3110]: info: Received Get System Info Dec 20 16:47:14 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:14 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:14 jbl-4312 volumio[3110]: info: Discovery: Getting this device information Dec 20 16:47:14 jbl-4312 volumio[3110]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:14 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:14 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:14.656+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:14 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:14.812+09:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0a00 addr=10 Dec 20 16:47:19 jbl-4312 volumio[3110]: info: Enabling plugin fusiondsp Dec 20 16:47:19 jbl-4312 volumio[3110]: info: Loading plugin "fusiondsp"... Dec 20 16:47:20 jbl-4312 volumio[3110]: info: Applying required configuration parameters for plugin fusiondsp Dec 20 16:47:20 jbl-4312 volumio[3110]: info: Preparing to generate the ALSA configuration file Dec 20 16:47:20 jbl-4312 volumio[3110]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Dec 20 16:47:20 jbl-4312 volumio[3110]: info: Reading ALSA contributions from plugins. Dec 20 16:47:20 jbl-4312 volumio[3110]: info: Asound.conf file written Dec 20 16:47:20 jbl-4312 sudo[11733]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 20 16:47:20 jbl-4312 sudo[11733]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:20 jbl-4312 sudo[11733]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:20 jbl-4312 kernel: Fine tdm clk setting range (0~2000000), 12287994 Dec 20 16:47:20 jbl-4312 kernel: Err: can not set rate to 4278967296! Dec 20 16:47:20 jbl-4312 kernel: Range[3920000 - 500000000] Dec 20 16:47:20 jbl-4312 kernel: out of value, fixed it Dec 20 16:47:20 jbl-4312 kernel: id=0 set inskew=0 Dec 20 16:47:20 jbl-4312 volumio[3110]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:eARC_TX CDS:0' : Operation not permitted Dec 20 16:47:20 jbl-4312 volumio[3110]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:I2SIn CLK:0' : Operation not permitted Dec 20 16:47:20 jbl-4312 volumio[3110]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:SPDIFIN audio samplerate:0' : Operation not permitted Dec 20 16:47:20 jbl-4312 volumio[3110]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:SPDIFIN Audio Type:0' : Operation not permitted Dec 20 16:47:20 jbl-4312 volumio[3110]: info: Output device has changed, restarting MPD Dec 20 16:47:20 jbl-4312 sudo[11738]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 20 16:47:20 jbl-4312 sudo[11738]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:20 jbl-4312 sudo[11738]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:20 jbl-4312 volumio[3110]: info: PLUGIN START: fusiondsp Dec 20 16:47:20 jbl-4312 volumio[3110]: info: Loading i18n strings for locale ja Dec 20 16:47:20 jbl-4312 sudo[11741]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 20 16:47:20 jbl-4312 sudo[11741]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:20 jbl-4312 volumio[3110]: info: FusionDsp - mixtype--------------------- undefined Dec 20 16:47:20 jbl-4312 volumio[3110]: info: Preparing to generate the ALSA configuration file Dec 20 16:47:20 jbl-4312 systemd[1]: Stopping Music Player Daemon... Dec 20 16:47:20 jbl-4312 volumio[3110]: info: Done. Dec 20 16:47:20 jbl-4312 volumio[3110]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Dec 20 16:47:20 jbl-4312 volumio[3110]: info: Reading ALSA contributions from plugins. Dec 20 16:47:20 jbl-4312 volumio[3110]: info: MPD Permissions set Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Dec 20 16:47:20 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:20 jbl-4312 systemd[1]: mpd.service: Succeeded. Dec 20 16:47:20 jbl-4312 systemd[1]: Stopped Music Player Daemon. Dec 20 16:47:20 jbl-4312 systemd[1]: Starting Music Player Daemon... Dec 20 16:47:21 jbl-4312 sudo[11749]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 20 16:47:21 jbl-4312 sudo[11749]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:21 jbl-4312 sudo[11749]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:21 jbl-4312 volumio[3110]: info: Asound.conf file unchanged, so no further update is needed Dec 20 16:47:21 jbl-4312 volumio[3110]: info: Output device has changed, restarting MPD Dec 20 16:47:21 jbl-4312 sudo[11762]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 20 16:47:21 jbl-4312 sudo[11762]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:21 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:21 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:21 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:21 jbl-4312 sudo[11762]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:21 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:21 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:21 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:21 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:21 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:21 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:21 jbl-4312 sudo[11765]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 20 16:47:21 jbl-4312 sudo[11765]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:21 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:47:21 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Dec 20 16:47:21 jbl-4312 systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Dec 20 16:47:21 jbl-4312 systemd[1]: mpd.service: Succeeded. Dec 20 16:47:21 jbl-4312 systemd[1]: Stopped Music Player Daemon. Dec 20 16:47:21 jbl-4312 volumio[3110]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:21 jbl-4312 volumio[3110]: info: MPD Permissions set Dec 20 16:47:21 jbl-4312 systemd[1]: Starting Music Player Daemon... Dec 20 16:47:21 jbl-4312 sudo[11773]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 20 16:47:21 jbl-4312 sudo[11773]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:21 jbl-4312 sudo[11773]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:21 jbl-4312 volumio[3110]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 20 16:47:21 jbl-4312 volumio[3110]: TypeError: Cannot read property 'off' of undefined Dec 20 16:47:21 jbl-4312 volumio[3110]: at FusionDsp.onStop (/data/plugins/audio_interface/fusiondsp/index.js:107:15) Dec 20 16:47:21 jbl-4312 volumio[3110]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) Dec 20 16:47:21 jbl-4312 volumio[3110]: at PluginManager.disableAndStopPlugin (/volumio/app/pluginmanager.js:1883:8) Dec 20 16:47:21 jbl-4312 volumio[3110]: at CoreCommandRouter.disableAndStopPlugin (/volumio/app/index.js:1556:29) Dec 20 16:47:21 jbl-4312 volumio[3110]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1412:47) Dec 20 16:47:21 jbl-4312 volumio[3110]: at Socket.emit (events.js:400:28) Dec 20 16:47:21 jbl-4312 volumio[3110]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Dec 20 16:47:21 jbl-4312 volumio[3110]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Dec 20 16:47:21 jbl-4312 volumio[3110]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 20 16:47:22 jbl-4312 sudo[11803]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-20 16:46 Dec 20 16:47:22 jbl-4312 sudo[11803]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:22 jbl-4312 sudo[11803]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:22 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:22.655+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:23 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:23.051+09:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0a00 addr=10 Dec 20 16:47:23 jbl-4312 mpd[11776]: Dec 20 16:47 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 20 16:47:23 jbl-4312 sudo[11765]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:23 jbl-4312 systemd[1]: Started Music Player Daemon. Dec 20 16:47:23 jbl-4312 sudo[11741]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:23 jbl-4312 volumio-remote-updater[2842]: [2025-12-20 16:47:23] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 20 16:47:23 jbl-4312 volumio-remote-updater[2842]: [2025-12-20 16:47:23] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 20 16:47:23 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:23.450+09:00 level=ERROR msg="failed reading message" component=volumio/socket error="read tcp 127.0.0.1:47102->127.0.0.1:3000: read: connection reset by peer" Dec 20 16:47:23 jbl-4312 systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 20 16:47:23 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:23.452+09:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Dec 20 16:47:23 jbl-4312 systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 20 16:47:23 jbl-4312 systemd[1]: Started dynamicswap service. Dec 20 16:47:23 jbl-4312 systemd[1]: dynamicswap.service: Succeeded. Dec 20 16:47:24 jbl-4312 systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Dec 20 16:47:24 jbl-4312 systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Dec 20 16:47:24 jbl-4312 systemd[1]: Started dynamicswap service. Dec 20 16:47:24 jbl-4312 systemd[1]: Stopped Volumio Backend Module. Dec 20 16:47:24 jbl-4312 systemd[1]: Started Volumio Backend Module. Dec 20 16:47:24 jbl-4312 systemd[1]: dynamicswap.service: Succeeded. Dec 20 16:47:24 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:24.454+09:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Dec 20 16:47:25 jbl-4312 volumio[11822]: info: ------------------------------------------- Dec 20 16:47:25 jbl-4312 volumio[11822]: info: ----- Volumio3 ---- Dec 20 16:47:25 jbl-4312 volumio[11822]: info: ------------------------------------------- Dec 20 16:47:25 jbl-4312 volumio[11822]: info: ----- System startup ---- Dec 20 16:47:25 jbl-4312 volumio[11822]: info: ------------------------------------------- Dec 20 16:47:26 jbl-4312 volumio[11822]: info: MYVOLUMIO Environment detected Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Plugin folders cleanup Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Scanning into folder /volumio/app/plugins/ Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Scanning category audio_interface Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Scanning category miscellanea Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Scanning category music_service Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Scanning category plugins.json Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Scanning category system_controller Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Scanning category user_interface Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Scanning into folder /data/plugins/ Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Scanning category audio_interface Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Scanning category music_service Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Scanning category user_interface Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Plugin folders cleanup completed Dec 20 16:47:26 jbl-4312 volumio[11822]: info: ------------------------------------------- Dec 20 16:47:26 jbl-4312 volumio[11822]: info: ----- Core plugins startup ---- Dec 20 16:47:26 jbl-4312 volumio[11822]: info: ------------------------------------------- Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Loading plugins from folder /volumio/app/plugins/ Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Adding plugin bluetooth to MyMusic Plugins Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Adding plugin multiroom to MyMusic Plugins Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Adding plugin upnp to MyMusic Plugins Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Adding plugin metavolumio to MyMusic Plugins Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Adding plugin cd_controller to MyMusic Plugins Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Adding plugin raat to MyMusic Plugins Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Loading plugins from folder /data/plugins/ Dec 20 16:47:26 jbl-4312 volumio[11822]: info: Loading plugin "system"... Dec 20 16:47:27 jbl-4312 volumio[11822]: info: Loading plugin "appearance"... Dec 20 16:47:27 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:27.662+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:28 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:28.041+09:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0a00 addr=10 Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Loading plugin "network"... Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Refreshing Cached IP Addresses Dec 20 16:47:28 jbl-4312 sudo[11850]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 20 16:47:28 jbl-4312 sudo[11850]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Loading plugin "services"... Dec 20 16:47:28 jbl-4312 sudo[11850]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:28 jbl-4312 sudo[11852]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Loading plugin "volumio5onboarding"... Dec 20 16:47:28 jbl-4312 sudo[11852]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:28 jbl-4312 sudo[11852]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Loading plugin "alsa_controller"... Dec 20 16:47:28 jbl-4312 volumio[11822]: warn: Unable to locate the audio output device SMSL USB AUDIO. Please configure a valid output device. Dec 20 16:47:28 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Loading plugin "wizard"... Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Loading plugin "networkfs"... Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Starting Udev Watcher for removable devices Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Ignoring mount for partition: BOOT Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Ignoring mount for partition: volumio Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Ignoring mount for partition: volumio_data Dec 20 16:47:28 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Loading plugin "volumio_command_line_client"... Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Plugin upnp is not enabled Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Loading plugin "my_music"... Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Loading plugin "mpd"... Dec 20 16:47:28 jbl-4312 volumio-remote-updater[2842]: [2025-12-20 16:47:28] [connect] Successful connection Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Plugin upnp_browser is not enabled Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Plugin bluetooth is not enabled Dec 20 16:47:28 jbl-4312 volumio[11822]: info: Loading plugin "alarm-clock"... Dec 20 16:47:29 jbl-4312 volumio[11822]: info: Loading plugin "manifestui"... Dec 20 16:47:29 jbl-4312 volumio[11822]: info: Plugin metavolumio is not enabled Dec 20 16:47:29 jbl-4312 volumio[11822]: info: Plugin airplay_emulation is not enabled Dec 20 16:47:29 jbl-4312 volumio[11822]: info: Plugin cd_controller is not enabled Dec 20 16:47:29 jbl-4312 volumio[11822]: info: Loading plugin "last_100"... Dec 20 16:47:29 jbl-4312 volumio[11822]: info: Plugin qobuzconnect is not enabled Dec 20 16:47:29 jbl-4312 volumio[11822]: info: Plugin raat is not enabled Dec 20 16:47:29 jbl-4312 volumio[11822]: info: Loading plugin "streaming_services"... Dec 20 16:47:30 jbl-4312 volumio[11822]: info: Starting Streaming Service Transparent Proxy Dec 20 16:47:30 jbl-4312 volumio[11822]: info: Plugin tidalconnect is not enabled Dec 20 16:47:30 jbl-4312 volumio[11822]: info: Loading plugin "webradio"... Dec 20 16:47:30 jbl-4312 volumio[11822]: info: Loading plugin "i2s_dacs"... Dec 20 16:47:30 jbl-4312 volumio[11822]: info: I2S DAC not set, start Auto-detection Dec 20 16:47:30 jbl-4312 volumio[11822]: info: Loading plugin "volumiodiscovery"... Dec 20 16:47:30 jbl-4312 volumio[11822]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 20 16:47:30 jbl-4312 volumio[11822]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 20 16:47:30 jbl-4312 volumio[11822]: *** WARNING *** For more information see Dec 20 16:47:30 jbl-4312 node[11822]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 20 16:47:30 jbl-4312 volumio[11822]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 20 16:47:30 jbl-4312 volumio[11822]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 20 16:47:30 jbl-4312 volumio[11822]: *** WARNING *** For more information see Dec 20 16:47:30 jbl-4312 node[11822]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 20 16:47:30 jbl-4312 node[11822]: *** WARNING *** For more information see Dec 20 16:47:30 jbl-4312 node[11822]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 20 16:47:30 jbl-4312 node[11822]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 20 16:47:30 jbl-4312 volumio[11822]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 20 16:47:30 jbl-4312 node[11822]: *** WARNING *** For more information see Dec 20 16:47:30 jbl-4312 volumio[11822]: info: Discovery: Started advertising with name: JBL 4312 Dec 20 16:47:30 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 20 16:47:30 jbl-4312 volumio[11822]: info: Plugin spop is not enabled Dec 20 16:47:30 jbl-4312 volumio[11822]: info: Loading plugin "ytcr"... Dec 20 16:47:31 jbl-4312 volumio[11822]: STREAMING PROXY: Starting server on port 3245 Dec 20 16:47:31 jbl-4312 volumio[11822]: Node JS runtime: 14 Dec 20 16:47:32 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:32.670+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:32 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:32.834+09:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0a00 addr=10 Dec 20 16:47:35 jbl-4312 volumio[11822]: info: Loading plugin "ytmusic"... Dec 20 16:47:35 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:35.457+09:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="read tcp 127.0.0.1:47618->127.0.0.1:3000: i/o timeout" Dec 20 16:47:38 jbl-4312 volumio[11822]: info: Plugin multiroom is not enabled Dec 20 16:47:38 jbl-4312 volumio[11822]: info: Loading plugin "outputs"... Dec 20 16:47:38 jbl-4312 volumio[11822]: info: Loading plugin "albumart"... Dec 20 16:47:38 jbl-4312 volumio[11822]: info: Plugin example_plugin is not enabled Dec 20 16:47:38 jbl-4312 volumio[11822]: info: Loading plugin "hi_res_audio"... Dec 20 16:47:39 jbl-4312 volumio[11822]: Forking 3 albumart workers Dec 20 16:47:40 jbl-4312 volumio[11822]: info: Applying required configuration parameters for plugin hi_res_audio Dec 20 16:47:40 jbl-4312 volumio[11822]: info: Loading plugin "inputs"... Dec 20 16:47:40 jbl-4312 volumio[11822]: Starting albumart workers Dec 20 16:47:40 jbl-4312 volumio[11822]: Starting albumart workers Dec 20 16:47:40 jbl-4312 volumio[11822]: Starting albumart workers Dec 20 16:47:40 jbl-4312 volumio[11822]: info: Loading plugin "qobuz"... Dec 20 16:47:40 jbl-4312 volumio-remote-updater[2842]: [2025-12-20 16:47:40] [connect] Successful connection Dec 20 16:47:41 jbl-4312 volumio[11822]: info: Plugin smart_inputs is not enabled Dec 20 16:47:41 jbl-4312 volumio[11822]: info: Loading plugin "tidal"... Dec 20 16:47:42 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:42.497+09:00 level=ERROR msg="failed to read message" component=conn/ws remoteAddr=192.168.3.13:50333 error="websocket: close 1006 (abnormal closure): unexpected EOF" Dec 20 16:47:42 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:42.497+09:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.3.13:50333 Dec 20 16:47:42 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:42.498+09:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.3.13:50333 Dec 20 16:47:42 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:42.687+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:42 jbl-4312 dbus-daemon[2844]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.12" (uid=0 pid=3453 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Dec 20 16:47:42 jbl-4312 volumio[11822]: info: Loading plugin "rivopluscontrol"... Dec 20 16:47:42 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:42.988+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Adding this device properties Dec 20 16:47:43 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , setThisDeviceVolumioProperties Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Setting Additional Device Volumio Properties: [object Object] Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Loading plugin "updater_comm"... Dec 20 16:47:43 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:43.289+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Loading plugin "cec_controller"... Dec 20 16:47:43 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:43.578+09:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.3.13:50983 Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Applying required configuration parameters for plugin cec_controller Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Plugin mpdemulation is not enabled Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Loading plugin "rest_api"... Dec 20 16:47:43 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:43.590+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Loading plugin "websocket"... Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Starting Socket.io Server version 2.3.0 Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Loading plugin "fusiondsp"... Dec 20 16:47:43 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:43.635+09:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.3.13:50983 @ 0x1c0c510" latency=1.111999ms timeout=10s Dec 20 16:47:43 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:43.635+09:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.3.13:50983 @ 0x1c0c510" latency=2.434541ms platform=PLATFORM_IOS version=4.251125.0 Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Applying required configuration parameters for plugin fusiondsp Dec 20 16:47:43 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:43.891+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Plugin ferrum_streaming_control_technology is not enabled Dec 20 16:47:43 jbl-4312 volumio[11822]: info: Loading i18n strings for locale ja Dec 20 16:47:43 jbl-4312 volumio[11822]: Updating browse sources language Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::initPlayerControls Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:44 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:44.192+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 20 16:47:44 jbl-4312 volumio[11822]: Express server listening on port 3000 Dec 20 16:47:44 jbl-4312 volumio[11822]: [Metrics] WebUI: 18s 863.32ms Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreStateMachine::resetVolumioState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreStateMachine::getcurrentVolume Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioRetrievevolume Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:47:44 jbl-4312 volumio[11822]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Completed loading Core Plugins Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Preparing to generate the ALSA configuration file Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Volumio Network Manager: Network status updated: 1 Dec 20 16:47:44 jbl-4312 volumio[11822]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: Invalid card number. Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Cannot read proc/cpuinfo: Error: Command failed: cat /proc/cpuinfo | grep Revision Dec 20 16:47:44 jbl-4312 volumio[11822]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Reading ALSA contributions from plugins. Dec 20 16:47:44 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:44.492+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:44 jbl-4312 volumio[11822]: 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: 3 Dec 20 16:47:44 jbl-4312 volumio-remote-updater[2842]: [2025-12-20 16:47:44] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1766216860 101 Dec 20 16:47:44 jbl-4312 volumio[11822]: 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: 4 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: VolumeController:: Volume=undefined Mute =false Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreStateMachine::pushState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioPushState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreStateMachine::updateTrackBlock Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrackBlock Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioRetrievevolume Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:44 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:44.698+09:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.3.13:50983 @ 0x1c0c510" latency=-14.032281ms platform=PLATFORM_IOS version=4.251125.0 Dec 20 16:47:44 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:44.699+09:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.3.13:50983 @ 0x1c0c510" latency=-14.072156ms timeout=10s Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:44 jbl-4312 volumio[11822]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: Invalid card number. Dec 20 16:47:44 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:44.793+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:44 jbl-4312 volumio[11822]: 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: 5 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: VolumeController:: Volume=undefined Mute =false Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreStateMachine::pushState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioPushState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreStateMachine::setRepeat null single undefined Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreStateMachine::pushState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioPushState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreStateMachine::setRandom null Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreStateMachine::pushState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioPushState Dec 20 16:47:44 jbl-4312 volumio[11822]: verbose: New Socket.io Connection to 192.168.3.4:3000 from 192.168.3.13 UA: Dart/3.9 (dart:io) Engine version: 3 Transport: websocket Total Clients: 5 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Dec 20 16:47:44 jbl-4312 volumio[11822]: 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: 6 Dec 20 16:47:44 jbl-4312 volumio[11822]: 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: 6 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Discovery: adding 828d392e-1778-458c-910e-8134e75d720b Dec 20 16:47:44 jbl-4312 volumio[11822]: info: Discovery: Found device JBL 4312 Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:44 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Asound.conf file unchanged, so no further update is needed Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Output device has changed, restarting MPD Dec 20 16:47:45 jbl-4312 sudo[11981]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 20 16:47:45 jbl-4312 sudo[11981]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 sudo[11981]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:45 jbl-4312 volumio[11822]: info: ___________ START PLUGINS ___________ Dec 20 16:47:45 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:45.093+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:45 jbl-4312 sudo[11984]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 20 16:47:45 jbl-4312 sudo[11984]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 volumio[11822]: info: ControllerMpd::onStart: Initializing MPD Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Creating MPD Configuration file Dec 20 16:47:45 jbl-4312 systemd[1]: Stopping Music Player Daemon... Dec 20 16:47:45 jbl-4312 sudo[11987]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Dec 20 16:47:45 jbl-4312 sudo[11987]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 sudo[11990]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 20 16:47:45 jbl-4312 sudo[11990]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 sudo[11987]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:45 jbl-4312 systemd[1]: mpd.service: Succeeded. Dec 20 16:47:45 jbl-4312 systemd[1]: Stopped Music Player Daemon. Dec 20 16:47:45 jbl-4312 sudo[11990]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 20 16:47:45 jbl-4312 volumio[11822]: info: [1766216865182] CoreMusicLibrary::Adding element Last_100 Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 20 16:47:45 jbl-4312 systemd[1]: Starting Music Player Daemon... Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Streaming services startup Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Starting Streaming Daemon Dec 20 16:47:45 jbl-4312 sudo[11993]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 20 16:47:45 jbl-4312 sudo[11993]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 sudo[12001]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 20 16:47:45 jbl-4312 sudo[12001]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Dec 20 16:47:45 jbl-4312 systemd[1]: mpd.service: Succeeded. Dec 20 16:47:45 jbl-4312 systemd[1]: Stopped Music Player Daemon. Dec 20 16:47:45 jbl-4312 systemd[1]: Starting Music Player Daemon... Dec 20 16:47:45 jbl-4312 sudo[12001]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 20 16:47:45 jbl-4312 volumio[11822]: info: [1766216865321] CoreMusicLibrary::Adding element Webradio Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Initializing BBC Radios Dec 20 16:47:45 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:45.394+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:47:45 jbl-4312 sudo[12007]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 20 16:47:45 jbl-4312 sudo[12007]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 sudo[12007]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 20 16:47:45 jbl-4312 volumio[11822]: info: [1766216865509] CoreMusicLibrary::Adding element YouTube Music Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 20 16:47:45 jbl-4312 volumio[11822]: Cannot find translation for source YouTube Music Dec 20 16:47:45 jbl-4312 volumio[11822]: error: Hi Res Audio Failed Login: Missing Login Data Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Adding HIGHRESAUDIO REST API Endpoints Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Initializing Serial Communication on port /dev/ttyS3 Dec 20 16:47:45 jbl-4312 kernel: meson_uart ffd22000.serial: ttyS3 use xtal(24M) 24000000 change 115200 to 115200 Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Touch Event Listener Process Starting Dec 20 16:47:45 jbl-4312 sudo[12024]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xinput --test-xi2 --root Dec 20 16:47:45 jbl-4312 sudo[12024]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 sudo[12024]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:45 jbl-4312 sudo[12029]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cset -f -y 4 0x18 0x25 0x0 Dec 20 16:47:45 jbl-4312 sudo[12029]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 sudo[12029]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:45 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:45.695+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 Dec 20 16:47:45 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:45.695+09:00 level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble addr=10 chunks=1 index=0 Dec 20 16:47:45 jbl-4312 sudo[12032]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cset -f -y 4 0x18 0x28 0x0 Dec 20 16:47:45 jbl-4312 sudo[12032]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 sudo[12032]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:45 jbl-4312 sudo[12035]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cset -f -y 4 0x18 0x29 0x1 Dec 20 16:47:45 jbl-4312 sudo[12035]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 sudo[12035]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:45 jbl-4312 sudo[12038]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cset -f -y 4 0x18 0x33 0x1 Dec 20 16:47:45 jbl-4312 sudo[12038]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 sudo[12038]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Apply VIM3L Onboard LEDs Settings Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Turning On Onboard LEDs Dec 20 16:47:45 jbl-4312 sudo[12042]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/tee /sys/class/leds/sys_led/trigger Dec 20 16:47:45 jbl-4312 sudo[12042]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 sudo[12042]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Starting CEC Event listener Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Loading i18n strings for locale ja Dec 20 16:47:45 jbl-4312 sudo[12046]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/tee /sys/class/leds/red_red/trigger Dec 20 16:47:45 jbl-4312 sudo[12046]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 20 16:47:45 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:45 jbl-4312 volumio[11822]: info: FusionDsp - mixtype--------------------- undefined Dec 20 16:47:45 jbl-4312 volumio[11822]: info: Volumio Calling Home Dec 20 16:47:45 jbl-4312 sudo[12046]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:46 jbl-4312 volumio[11822]: info: Preparing to generate the ALSA configuration file Dec 20 16:47:46 jbl-4312 volumio[11822]: info: Stopping AccessToken refresher cron for QOBUZ Dec 20 16:47:46 jbl-4312 volumio[11822]: info: AccessToken refresher cron started for QOBUZ Dec 20 16:47:46 jbl-4312 volumio[11822]: info: Adding TIDAL REST API Endpoints Dec 20 16:47:46 jbl-4312 volumio[11822]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal Dec 20 16:47:46 jbl-4312 volumio[11822]: info: Adding QOBUZ REST API Endpoints Dec 20 16:47:46 jbl-4312 volumio[11822]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz Dec 20 16:47:46 jbl-4312 volumio[11822]: info: Serial port opened successfully Dec 20 16:47:46 jbl-4312 volumio[11822]: info: Sending serial start messages Dec 20 16:47:46 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:46 jbl-4312 volumio[11822]: info: Reporting MCU Network Status: 1 Dec 20 16:47:46 jbl-4312 volumio[11822]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Dec 20 16:47:46 jbl-4312 volumio[11822]: info: Reading ALSA contributions from plugins. Dec 20 16:47:46 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Dec 20 16:47:46 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Dec 20 16:47:46 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:47:46 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 20 16:47:46 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Dec 20 16:47:46 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Dec 20 16:47:46 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:47:46 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 20 16:47:46 jbl-4312 volumio[11822]: error: Failed to initialize COMTRUE with silence: Error: Command failed: /usr/bin/aplay -D plughw:Device /volumio/app/silence.wav Dec 20 16:47:46 jbl-4312 volumio[11822]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Dec 20 16:47:46 jbl-4312 volumio[11822]: aplay: main:828: audio open error: No such device Dec 20 16:47:46 jbl-4312 volumio[11822]: info: Touch Event Listener Process Closed Dec 20 16:47:46 jbl-4312 volumio[11822]: error: Cannot start Volumio Streaming Daemon Dec 20 16:47:46 jbl-4312 volumio[11822]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 20 16:47:46 jbl-4312 volumio[11822]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 20 16:47:46 jbl-4312 volumio[11822]: info: MPD Permissions set Dec 20 16:47:46 jbl-4312 volumio[11822]: info: MPD Permissions set Dec 20 16:47:46 jbl-4312 volumio[11822]: info: MP1 GPIO: Signalled system ready via GPIO Dec 20 16:47:46 jbl-4312 volumio[11822]: Invalid card number. Dec 20 16:47:46 jbl-4312 volumio[11822]: amixer -c 5 info | grep "SMSL USB AUDIO" Dec 20 16:47:46 jbl-4312 volumio[11822]: Invalid card number. Dec 20 16:47:46 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:46.958+09:00 level=WARN msg="active output device not found in available devices" component=volumio/socket activeDeviceId=5 Dec 20 16:47:46 jbl-4312 volumio[11822]: Invalid card number. Dec 20 16:47:46 jbl-4312 volumio[11822]: amixer -c 5 info | grep "SMSL USB AUDIO" Dec 20 16:47:47 jbl-4312 volumio[11822]: Invalid card number. Dec 20 16:47:47 jbl-4312 volumio[11822]: info: Volumio called home Dec 20 16:47:47 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:47 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:47 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:47 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:47 jbl-4312 volumio[11822]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:47 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:47.343+09:00 level=INFO msg="continue navigation request" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.3.13:50983 @ 0x1c0c510" latency=-12.477146ms timeout=10s from=APP_PAGE_ROOT Dec 20 16:47:47 jbl-4312 volumio[11822]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:47 jbl-4312 volumio[11822]: info: Asound.conf file unchanged, so no further update is needed Dec 20 16:47:47 jbl-4312 volumio[11822]: info: Output device has changed, restarting MPD Dec 20 16:47:47 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:47.631+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:47 jbl-4312 sudo[12088]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 20 16:47:47 jbl-4312 sudo[12088]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 sudo[12088]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:47 jbl-4312 sudo[12091]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 20 16:47:47 jbl-4312 sudo[12091]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:47 jbl-4312 mpd[12022]: Dec 20 16:47 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 20 16:47:47 jbl-4312 systemd[1]: Started Music Player Daemon. Dec 20 16:47:47 jbl-4312 sudo[11993]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:47 jbl-4312 sudo[11984]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:47 jbl-4312 systemd[1]: Stopping Music Player Daemon... Dec 20 16:47:47 jbl-4312 volumio[11822]: info: MPD Permissions set Dec 20 16:47:47 jbl-4312 systemd[1]: mpd.service: Succeeded. Dec 20 16:47:47 jbl-4312 systemd[1]: Stopped Music Player Daemon. Dec 20 16:47:47 jbl-4312 systemd[1]: Starting Music Player Daemon... Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Dec 20 16:47:47 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:47 jbl-4312 volumio[11822]: error: Cannot initialize MPD Connection: MPD is not running Dec 20 16:47:47 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:47.931+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:47 jbl-4312 sudo[12097]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 20 16:47:47 jbl-4312 sudo[12097]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:47 jbl-4312 sudo[12097]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:48 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12115, instance 1, run: true Dec 20 16:47:48 jbl-4312 volumio[11822]: info: camilladsp service started and running in background, instance 1 Dec 20 16:47:48 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:47:48 jbl-4312 volumio[11822]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Dec 20 16:47:48 jbl-4312 volumio[11822]: cannot open device 'volumioHw': No such device Dec 20 16:47:48 jbl-4312 volumio[11822]: error: FusionDsp - ----Hw detection failed :Error: Command failed: /data/plugins/audio_interface/fusiondsp/hw_params volumioHw >/data/configuration/audio_interface/fusiondsp/hwinfo.json Dec 20 16:47:48 jbl-4312 volumio[11822]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Dec 20 16:47:48 jbl-4312 volumio[11822]: cannot open device 'volumioHw': No such device Dec 20 16:47:48 jbl-4312 volumio[11822]: info: FusionDsp loaded Dec 20 16:47:48 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:48 jbl-4312 sudo[12126]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Dec 20 16:47:48 jbl-4312 sudo[12126]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:48 jbl-4312 volumio[11822]: info: FusionDsp - Reporting Fusion DSP Enabled Dec 20 16:47:48 jbl-4312 volumio[11822]: info: Adding Signal Path Element [object Object] Dec 20 16:47:48 jbl-4312 volumio[11822]: info: Adding fusiondspeq DSP Signal Path Element Dec 20 16:47:48 jbl-4312 volumio[11822]: info: FusionDsp - ---- installed callbackRead Dec 20 16:47:48 jbl-4312 volumio[11822]: info: FusionDsp - If filter freq >samplerate/2 then disable it Dec 20 16:47:48 jbl-4312 systemd[1]: Started FusionDsp Daemon. Dec 20 16:47:48 jbl-4312 sudo[12126]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:48 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:48.231+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:48 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12129, instance 1, run: true Dec 20 16:47:48 jbl-4312 volumio[11822]: error: FusionDsp - WebSocket error: [object Object] Dec 20 16:47:48 jbl-4312 volumio[11822]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 20 16:47:48 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12150, instance 1, run: true Dec 20 16:47:48 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:48.532+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:48 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12161, instance 1, run: true Dec 20 16:47:48 jbl-4312 sudo[12169]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 20 16:47:48 jbl-4312 sudo[12169]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:48 jbl-4312 volumio[11822]: info: Turning Off Onboard LEDs Dec 20 16:47:48 jbl-4312 sudo[12169]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:48 jbl-4312 sudo[12172]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 20 16:47:48 jbl-4312 sudo[12172]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:48 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:48.832+09:00 level=INFO msg="new address was allocated" component=conn/ble old=11 new=12 Dec 20 16:47:48 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:48.832+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:48 jbl-4312 sudo[12172]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:48 jbl-4312 sudo[12177]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/tee /sys/class/leds/sys_led/trigger Dec 20 16:47:48 jbl-4312 sudo[12177]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:48 jbl-4312 sudo[12177]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:48 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12183, instance 1, run: true Dec 20 16:47:48 jbl-4312 volumio[11822]: verbose: New Socket.io Connection to 192.168.3.4 from 192.168.3.13 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Dec 20 16:47:48 jbl-4312 sudo[12182]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/tee /sys/class/leds/red_red/trigger Dec 20 16:47:48 jbl-4312 sudo[12182]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:48 jbl-4312 sudo[12182]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 20 16:47:49 jbl-4312 volumio[11822]: info: Onboard LEDs initialized Dec 20 16:47:49 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12191, instance 1, run: true Dec 20 16:47:49 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:49.133+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:49 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12198, instance 1, run: true Dec 20 16:47:49 jbl-4312 sudo[12207]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 20 16:47:49 jbl-4312 sudo[12207]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:49 jbl-4312 sudo[12207]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:49 jbl-4312 sudo[12211]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 20 16:47:49 jbl-4312 sudo[12211]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:49 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12214, instance 1, run: true Dec 20 16:47:49 jbl-4312 sudo[12211]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:49 jbl-4312 volumio[11822]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Dec 20 16:47:49 jbl-4312 dbus-daemon[2844]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.12" (uid=0 pid=3453 comm="/usr/bin/volumio5-onboarding " label="kernel") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.5" (uid=0 pid=3195 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn" label="kernel") Dec 20 16:47:49 jbl-4312 volumio[11822]: verbose: New Socket.io Connection to 192.168.3.4 from 192.168.3.13 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 11 Dec 20 16:47:49 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:49.434+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetVisibleSources Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 20 16:47:49 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:49 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:49 jbl-4312 volumio[11822]: info: Listing playlists Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 20 16:47:49 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12221, instance 1, run: true Dec 20 16:47:49 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:49 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12228, instance 1, run: true Dec 20 16:47:49 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:49.735+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:50 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:50.035+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:50 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12237, instance 1, run: true Dec 20 16:47:50 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:50.182+09:00 level=INFO msg="new address was allocated" component=conn/ble old=12 new=13 Dec 20 16:47:50 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12244, instance 1, run: true Dec 20 16:47:50 jbl-4312 volumio[11822]: info: [yt-cast-receiver] DIAL server listening on port 8098 Dec 20 16:47:50 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioRetrievevolume Dec 20 16:47:50 jbl-4312 mpd[12112]: Dec 20 16:47 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 20 16:47:50 jbl-4312 systemd[1]: Started Music Player Daemon. Dec 20 16:47:50 jbl-4312 sudo[12091]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:50 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:50.336+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:50 jbl-4312 volumio[11822]: error: MPD error: The expression evaluated to a falsy value: Dec 20 16:47:50 jbl-4312 volumio[11822]: assert.ok(self.idling) Dec 20 16:47:50 jbl-4312 volumio[11822]: error: The expression evaluated to a falsy value: Dec 20 16:47:50 jbl-4312 volumio[11822]: assert.ok(self.idling) Dec 20 16:47:50 jbl-4312 volumio[11822]: error: updateQueue error: null Dec 20 16:47:50 jbl-4312 volumio[11822]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: Invalid card number. Dec 20 16:47:50 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12258, instance 1, run: true Dec 20 16:47:50 jbl-4312 volumio[11822]: info: VolumeController:: Volume=undefined Mute =false Dec 20 16:47:50 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:50 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:50 jbl-4312 volumio[11822]: info: CoreStateMachine::pushState Dec 20 16:47:50 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:50 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioPushState Dec 20 16:47:50 jbl-4312 volumio[11822]: error: updateQueue error: null Dec 20 16:47:50 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:50.636+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:50 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:50.637+09:00 level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble addr=8 chunks=1 index=0 Dec 20 16:47:50 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:50.638+09:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%08 @ 0x1acc030" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Dec 20 16:47:50 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12265, instance 1, run: true Dec 20 16:47:50 jbl-4312 sudo[12274]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 20 16:47:50 jbl-4312 sudo[12274]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:50 jbl-4312 systemd[1]: Stopping MPD Monitor Service... Dec 20 16:47:50 jbl-4312 systemd[1]: mpd_monitor.service: Main process exited, code=killed, status=15/TERM Dec 20 16:47:50 jbl-4312 systemd[1]: mpd_monitor.service: Succeeded. Dec 20 16:47:50 jbl-4312 systemd[1]: Stopped MPD Monitor Service. Dec 20 16:47:50 jbl-4312 sudo[12277]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 20 16:47:50 jbl-4312 sudo[12277]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:50 jbl-4312 systemd[1]: Started MPD Monitor Service. Dec 20 16:47:50 jbl-4312 sudo[12274]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:50 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12278, instance 1, run: true Dec 20 16:47:50 jbl-4312 mpd_monitor.sh[12279]: MPD Monitor Service: Starting MPD Monitor Service Dec 20 16:47:50 jbl-4312 systemd[1]: Stopping MPD Monitor Service... Dec 20 16:47:50 jbl-4312 systemd[1]: mpd_monitor.service: Main process exited, code=killed, status=15/TERM Dec 20 16:47:50 jbl-4312 systemd[1]: mpd_monitor.service: Succeeded. Dec 20 16:47:50 jbl-4312 systemd[1]: Stopped MPD Monitor Service. Dec 20 16:47:50 jbl-4312 systemd[1]: Started MPD Monitor Service. Dec 20 16:47:50 jbl-4312 sudo[12277]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:50 jbl-4312 volumio[11822]: info: Completed starting Core Plugins Dec 20 16:47:50 jbl-4312 volumio[11822]: info: ------------------------------------------- Dec 20 16:47:50 jbl-4312 volumio[11822]: info: ----- MyVolumio plugins startup ---- Dec 20 16:47:50 jbl-4312 volumio[11822]: info: ------------------------------------------- Dec 20 16:47:50 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 20 16:47:50 jbl-4312 volumio[11822]: info: Successfully started MPD Monitor Dec 20 16:47:50 jbl-4312 volumio[11822]: info: Successfully started MPD Monitor Dec 20 16:47:50 jbl-4312 mpd_monitor.sh[12289]: MPD Monitor Service: Starting MPD Monitor Service Dec 20 16:47:50 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:50.938+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:50 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12292, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12301, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12308, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 20 16:47:51 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 20 16:47:51 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:51 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:51 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:51 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:51 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:51 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:51 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12315, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:51.238+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12322, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12329, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12336, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12343, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:51.539+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12350, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12357, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12364, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12371, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:51.841+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12378, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12385, instance 1, run: true Dec 20 16:47:51 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12392, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12399, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:52.141+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12406, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12413, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12420, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 20 16:47:52 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:52 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:52 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:52 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:52 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:52 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:52 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12427, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:52.442+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12434, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12441, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12448, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12455, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:52.743+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12462, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12469, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12476, instance 1, run: true Dec 20 16:47:52 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12483, instance 1, run: true Dec 20 16:47:53 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12490, instance 1, run: true Dec 20 16:47:53 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:53.043+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:53 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12497, instance 1, run: true Dec 20 16:47:53 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12504, instance 1, run: true Dec 20 16:47:53 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12511, instance 1, run: true Dec 20 16:47:53 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12518, instance 1, run: true Dec 20 16:47:53 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:53.344+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:53 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12525, instance 1, run: true Dec 20 16:47:53 jbl-4312 sudo[12533]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 20 16:47:53 jbl-4312 sudo[12533]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:53 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12534, instance 1, run: true Dec 20 16:47:53 jbl-4312 systemd[1]: Stopping MPD Monitor Service... Dec 20 16:47:53 jbl-4312 systemd[1]: mpd_monitor.service: Main process exited, code=killed, status=15/TERM Dec 20 16:47:53 jbl-4312 systemd[1]: mpd_monitor.service: Succeeded. Dec 20 16:47:53 jbl-4312 systemd[1]: Stopped MPD Monitor Service. Dec 20 16:47:53 jbl-4312 systemd[1]: Started MPD Monitor Service. Dec 20 16:47:53 jbl-4312 sudo[12533]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:53 jbl-4312 volumio[11822]: info: Successfully started MPD Monitor Dec 20 16:47:53 jbl-4312 mpd_monitor.sh[12542]: MPD Monitor Service: Starting MPD Monitor Service Dec 20 16:47:53 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12546, instance 1, run: true Dec 20 16:47:53 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:53.644+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:53 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12553, instance 1, run: true Dec 20 16:47:53 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 20 16:47:53 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:53 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:53.945+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 Dec 20 16:47:53 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:53.945+09:00 level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble addr=8 chunks=1 index=0 Dec 20 16:47:53 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:53.945+09:00 level=ERROR msg="failed to send event" component=server dst="00:00:00:00:00:00%08 @ 0x1acc030" event=SERVER_EVENT_TYPE_PLAYER_STATE_CHANGED error="peer is gone" Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12560, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12567, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12574, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12581, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12588, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12595, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12602, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12609, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12616, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12623, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12630, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12637, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12644, instance 1, run: true Dec 20 16:47:54 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12651, instance 1, run: true Dec 20 16:47:55 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:55.014+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=12 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12658, instance 1, run: true Dec 20 16:47:55 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12665, instance 1, run: true Dec 20 16:47:55 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:55.176+09:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0c00 addr=12 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12672, instance 1, run: true Dec 20 16:47:55 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12679, instance 1, run: true Dec 20 16:47:55 jbl-4312 volumio[11822]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 20 16:47:55 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12686, instance 1, run: true Dec 20 16:47:55 jbl-4312 sudo[12694]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 20 16:47:55 jbl-4312 sudo[12694]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:55 jbl-4312 sudo[12694]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:55 jbl-4312 sudo[12700]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 20 16:47:55 jbl-4312 sudo[12700]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:55 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12701, instance 1, run: true Dec 20 16:47:55 jbl-4312 sudo[12700]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:55 jbl-4312 volumio[11822]: verbose: New Socket.io Connection to 192.168.3.4 from 192.168.3.13 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 12 Dec 20 16:47:55 jbl-4312 sudo[12711]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 20 16:47:55 jbl-4312 sudo[12711]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:55 jbl-4312 sudo[12711]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetVisibleSources Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 20 16:47:55 jbl-4312 sudo[12715]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:55 jbl-4312 sudo[12715]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 sudo[12715]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Listing playlists Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 20 16:47:55 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12718, instance 1, run: true Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:55 jbl-4312 volumio[11822]: verbose: New Socket.io Connection to 192.168.3.4 from 192.168.3.13 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 12 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetVisibleSources Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Listing playlists Dec 20 16:47:55 jbl-4312 volumio[11822]: info: Checking for updated MCU Firmware Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 20 16:47:55 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12725, instance 1, run: true Dec 20 16:47:55 jbl-4312 volumio[11822]: info: VolumeController::SetAlsaVolume0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreStateMachine::pushState Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 20 16:47:55 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioPushState Dec 20 16:47:56 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:56 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:56 jbl-4312 volumio[11822]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: Invalid card number. Dec 20 16:47:56 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12733, instance 1, run: true Dec 20 16:47:56 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:56.489+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=12 Dec 20 16:47:56 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12740, instance 1, run: true Dec 20 16:47:56 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:47:56.729+09:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0c00 addr=12 Dec 20 16:47:56 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12747, instance 1, run: true Dec 20 16:47:56 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12754, instance 1, run: true Dec 20 16:47:56 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12761, instance 1, run: true Dec 20 16:47:57 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12768, instance 1, run: true Dec 20 16:47:57 jbl-4312 sudo[12776]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 20 16:47:57 jbl-4312 sudo[12776]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:57 jbl-4312 sudo[12776]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:57 jbl-4312 sudo[12780]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 20 16:47:57 jbl-4312 sudo[12780]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:47:57 jbl-4312 sudo[12780]: pam_unix(sudo:session): session closed for user root Dec 20 16:47:57 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12783, instance 1, run: true Dec 20 16:47:57 jbl-4312 volumio[11822]: verbose: New Socket.io Connection to 192.168.3.4 from 192.168.3.13 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 12 Dec 20 16:47:57 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12790, instance 1, run: true Dec 20 16:47:57 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:57 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetVisibleSources Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 20 16:47:57 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:57 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:57 jbl-4312 volumio[11822]: info: Listing playlists Dec 20 16:47:57 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:57 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:57 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12797, instance 1, run: true Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:57 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:47:57 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12804, instance 1, run: true Dec 20 16:47:59 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 20 16:47:59 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:47:59 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:47:59 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:47:59 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:47:59 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:47:59 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:47:59 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:47:59 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 20 16:47:59 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 20 16:48:00 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12828, instance 1, run: true Dec 20 16:48:00 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12835, instance 1, run: true Dec 20 16:48:00 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:48:00 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:48:00 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:48:00 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12842, instance 1, run: true Dec 20 16:48:00 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 20 16:48:01 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 20 16:48:02 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 20 16:48:02 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 20 16:48:02 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:02 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:02 jbl-4312 volumio[11822]: info: Starting MyVolumio Remote Streaming Endpoints Dec 20 16:48:02 jbl-4312 volumio[11822]: info: MyVolumio login type: Token Dec 20 16:48:02 jbl-4312 volumio[11822]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 20 16:48:02 jbl-4312 volumio[11822]: error: [MyVolumio PluginManager] Could not read package.json file: Error: /myvolumio/plugins/music_service/streaming_services//package.json: ENOENT: no such file or directory, open '/myvolumio/plugins/music_service/streaming_services//package.json' Dec 20 16:48:02 jbl-4312 volumio[11822]: info: CoreCommandRouter::Close All Modals sent Dec 20 16:48:02 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12849, instance 1, run: true Dec 20 16:48:02 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12856, instance 1, run: true Dec 20 16:48:02 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12863, instance 1, run: true Dec 20 16:48:02 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12870, instance 1, run: true Dec 20 16:48:02 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12877, instance 1, run: true Dec 20 16:48:02 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12884, instance 1, run: true Dec 20 16:48:02 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12891, instance 1, run: true Dec 20 16:48:03 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12898, instance 1, run: true Dec 20 16:48:03 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12905, instance 1, run: true Dec 20 16:48:03 jbl-4312 volumio[11822]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 20 16:48:03 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12912, instance 1, run: true Dec 20 16:48:03 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12919, instance 1, run: true Dec 20 16:48:03 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12926, instance 1, run: true Dec 20 16:48:03 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12933, instance 1, run: true Dec 20 16:48:03 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12940, instance 1, run: true Dec 20 16:48:03 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12947, instance 1, run: true Dec 20 16:48:03 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12956, instance 1, run: true Dec 20 16:48:03 jbl-4312 volumio[11822]: info: MyVolumio token set successfully Dec 20 16:48:03 jbl-4312 volumio[11822]: info: MYVOLUMIO: Adding device Dec 20 16:48:03 jbl-4312 volumio[11822]: info: MYVOLUMIO: Evaluating Server Dec 20 16:48:03 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12963, instance 1, run: true Dec 20 16:48:03 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 12970, instance 1, run: true Dec 20 16:48:04 jbl-4312 volumio[11822]: info: MyVolumio status changed Dec 20 16:48:04 jbl-4312 volumio[11822]: info: Streaming services startup Dec 20 16:48:04 jbl-4312 volumio[11822]: info: Starting Streaming Daemon Dec 20 16:48:04 jbl-4312 volumio[11822]: info: Removing browser output: myVolumio user plan is not superstar Dec 20 16:48:04 jbl-4312 volumio[11822]: info: Removing audio output: Dec 20 16:48:04 jbl-4312 volumio[11822]: info: Stoppping Tunnel 1 Dec 20 16:48:04 jbl-4312 sudo[13002]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 20 16:48:04 jbl-4312 sudo[13002]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:48:04 jbl-4312 sudo[13002]: pam_unix(sudo:session): session closed for user root Dec 20 16:48:04 jbl-4312 sudo[13005]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 20 16:48:04 jbl-4312 sudo[13005]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:48:04 jbl-4312 volumio[11822]: error: Cannot start Volumio Streaming Daemon Dec 20 16:48:04 jbl-4312 volumio[11822]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 20 16:48:04 jbl-4312 volumio[11822]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 20 16:48:04 jbl-4312 sudo[13005]: pam_unix(sudo:session): session closed for user root Dec 20 16:48:04 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13007, instance 1, run: true Dec 20 16:48:04 jbl-4312 volumio[11822]: info: Remote SSH Stopped Dec 20 16:48:05 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13014, instance 1, run: true Dec 20 16:48:05 jbl-4312 volumio[11822]: info: Setting Geolocation for MyVolumio to as1 Dec 20 16:48:05 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:05 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:05 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:05 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13021, instance 1, run: true Dec 20 16:48:05 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13028, instance 1, run: true Dec 20 16:48:05 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13035, instance 1, run: true Dec 20 16:48:05 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13042, instance 1, run: true Dec 20 16:48:05 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13049, instance 1, run: true Dec 20 16:48:05 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13056, instance 1, run: true Dec 20 16:48:05 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 20 16:48:05 jbl-4312 volumio[11822]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 20 16:48:05 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13063, instance 1, run: true Dec 20 16:48:05 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13070, instance 1, run: true Dec 20 16:48:05 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 20 16:48:05 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13077, instance 1, run: true Dec 20 16:48:05 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13084, instance 1, run: true Dec 20 16:48:05 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13091, instance 1, run: true Dec 20 16:48:06 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13098, instance 1, run: true Dec 20 16:48:06 jbl-4312 volumio[11822]: info: Updating MyVolumio device info Dec 20 16:48:06 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:06 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13105, instance 1, run: true Dec 20 16:48:06 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13112, instance 1, run: true Dec 20 16:48:06 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13119, instance 1, run: true Dec 20 16:48:06 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13126, instance 1, run: true Dec 20 16:48:06 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13133, instance 1, run: true Dec 20 16:48:06 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13140, instance 1, run: true Dec 20 16:48:06 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13147, instance 1, run: true Dec 20 16:48:06 jbl-4312 volumio[11822]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 20 16:48:06 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13154, instance 1, run: true Dec 20 16:48:06 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13161, instance 1, run: true Dec 20 16:48:06 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13168, instance 1, run: true Dec 20 16:48:06 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13175, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13182, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13189, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13196, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13203, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13210, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13217, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13224, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13231, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13238, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13245, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13252, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13259, instance 1, run: true Dec 20 16:48:07 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13266, instance 1, run: true Dec 20 16:48:08 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13273, instance 1, run: true Dec 20 16:48:08 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13280, instance 1, run: true Dec 20 16:48:08 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13287, instance 1, run: true Dec 20 16:48:08 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13294, instance 1, run: true Dec 20 16:48:08 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13301, instance 1, run: true Dec 20 16:48:08 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 20 16:48:08 jbl-4312 volumio[11822]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 20 16:48:08 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 20 16:48:08 jbl-4312 volumio[11822]: info: Received Get System Version Dec 20 16:48:08 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 20 16:48:08 jbl-4312 volumio[11822]: info: Received Get System Info Dec 20 16:48:08 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 20 16:48:08 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 20 16:48:08 jbl-4312 volumio[11822]: info: Discovery: Getting this device information Dec 20 16:48:08 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:48:08 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:48:08 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 20 16:48:08 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13308, instance 1, run: true Dec 20 16:48:08 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13320, instance 1, run: true Dec 20 16:48:08 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13339, instance 1, run: true Dec 20 16:48:08 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13346, instance 1, run: true Dec 20 16:48:08 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13353, instance 1, run: true Dec 20 16:48:08 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13360, instance 1, run: true Dec 20 16:48:08 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13380, instance 1, run: true Dec 20 16:48:09 jbl-4312 volumiologrotate[2841]: ls: cannot access '/var/log/samba/log.wb-JBL': No such file or directory Dec 20 16:48:09 jbl-4312 volumiologrotate[2841]: ls: cannot access '4312': No such file or directory Dec 20 16:48:09 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13405, instance 1, run: true Dec 20 16:48:09 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13422, instance 1, run: true Dec 20 16:48:09 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13429, instance 1, run: true Dec 20 16:48:09 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13436, instance 1, run: true Dec 20 16:48:09 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13443, instance 1, run: true Dec 20 16:48:09 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13450, instance 1, run: true Dec 20 16:48:09 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13457, instance 1, run: true Dec 20 16:48:09 jbl-4312 volumio[11822]: info: MYVOLUMIO: Adding device Dec 20 16:48:09 jbl-4312 volumio[11822]: info: MYVOLUMIO: Evaluating Server Dec 20 16:48:09 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13464, instance 1, run: true Dec 20 16:48:09 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13471, instance 1, run: true Dec 20 16:48:10 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13503, instance 1, run: true Dec 20 16:48:10 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13510, instance 1, run: true Dec 20 16:48:10 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13517, instance 1, run: true Dec 20 16:48:10 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13524, instance 1, run: true Dec 20 16:48:10 jbl-4312 volumio[11822]: info: Setting Geolocation for MyVolumio to as1 Dec 20 16:48:10 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:10 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:10 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:10 jbl-4312 volumio[11822]: error: MyVolumio Plugin failed to start in a timely fashion Dec 20 16:48:10 jbl-4312 volumio[11822]: [Metrics] CommandRouter: 44s 937.89ms Dec 20 16:48:10 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumiosetStartupVolume Dec 20 16:48:10 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:48:10 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:10 jbl-4312 volumio[11822]: info: CoreCommandRouter::Close All Modals sent Dec 20 16:48:11 jbl-4312 volumio[11822]: info: CoreCommandRouter::Close All Modals sent Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13534, instance 1, run: true Dec 20 16:48:11 jbl-4312 volumio[11822]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Dec 20 16:48:11 jbl-4312 volumio[11822]: info: FusionDsp - ---- read samplerate from file: 44100 Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp stopping service pid 13534... Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp service terminated, instance 1 Dec 20 16:48:11 jbl-4312 volumio[11822]: info: FusionDsp - If filter freq >samplerate/2 then disable it Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp service started and running in background, instance 1 Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13540, instance 1, run: true Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13547, instance 1, run: true Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13554, instance 1, run: true Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13561, instance 1, run: true Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13568, instance 1, run: true Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13575, instance 1, run: true Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13582, instance 1, run: true Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13589, instance 1, run: true Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13596, instance 1, run: true Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13603, instance 1, run: true Dec 20 16:48:11 jbl-4312 volumio[11822]: info: Updating MyVolumio device info Dec 20 16:48:11 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:11 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:11 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:11 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13610, instance 1, run: true Dec 20 16:48:12 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13617, instance 1, run: true Dec 20 16:48:12 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 20 16:48:12 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 20 16:48:12 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: raat , onStop Dec 20 16:48:12 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 20 16:48:12 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13626, instance 1, run: true Dec 20 16:48:12 jbl-4312 volumio[11822]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 20 16:48:12 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13633, instance 1, run: true Dec 20 16:48:12 jbl-4312 volumio[11822]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 20 16:48:12 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13640, instance 1, run: true Dec 20 16:48:12 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13647, instance 1, run: true Dec 20 16:48:12 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13654, instance 1, run: true Dec 20 16:48:12 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13661, instance 1, run: true Dec 20 16:48:12 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13668, instance 1, run: true Dec 20 16:48:12 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13675, instance 1, run: true Dec 20 16:48:12 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13682, instance 1, run: true Dec 20 16:48:12 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13689, instance 1, run: true Dec 20 16:48:12 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13696, instance 1, run: true Dec 20 16:48:13 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13703, instance 1, run: true Dec 20 16:48:13 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13710, instance 1, run: true Dec 20 16:48:13 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13717, instance 1, run: true Dec 20 16:48:13 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13724, instance 1, run: true Dec 20 16:48:13 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13731, instance 1, run: true Dec 20 16:48:13 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13738, instance 1, run: true Dec 20 16:48:13 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13745, instance 1, run: true Dec 20 16:48:13 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13753, instance 1, run: true Dec 20 16:48:13 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13762, instance 1, run: true Dec 20 16:48:13 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13769, instance 1, run: true Dec 20 16:48:13 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13776, instance 1, run: true Dec 20 16:48:13 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13783, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13790, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13797, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13804, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13811, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13818, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13825, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13832, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13839, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13846, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13853, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13860, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13867, instance 1, run: true Dec 20 16:48:14 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13874, instance 1, run: true Dec 20 16:48:15 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13881, instance 1, run: true Dec 20 16:48:15 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13888, instance 1, run: true Dec 20 16:48:15 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13895, instance 1, run: true Dec 20 16:48:15 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13903, instance 1, run: true Dec 20 16:48:15 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13910, instance 1, run: true Dec 20 16:48:15 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13917, instance 1, run: true Dec 20 16:48:15 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13924, instance 1, run: true Dec 20 16:48:15 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13931, instance 1, run: true Dec 20 16:48:15 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13938, instance 1, run: true Dec 20 16:48:15 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13945, instance 1, run: true Dec 20 16:48:15 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13952, instance 1, run: true Dec 20 16:48:15 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 20 16:48:15 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 20 16:48:15 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 20 16:48:15 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13961, instance 1, run: true Dec 20 16:48:16 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13968, instance 1, run: true Dec 20 16:48:16 jbl-4312 volumio-remote-updater[2842]: No test mode Dec 20 16:48:16 jbl-4312 volumio-remote-updater[2842]: No alpha test mode Dec 20 16:48:16 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 20 16:48:16 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13976, instance 1, run: true Dec 20 16:48:16 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13983, instance 1, run: true Dec 20 16:48:16 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13990, instance 1, run: true Dec 20 16:48:16 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 13997, instance 1, run: true Dec 20 16:48:16 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14004, instance 1, run: true Dec 20 16:48:16 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14011, instance 1, run: true Dec 20 16:48:16 jbl-4312 volumio[11822]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Dec 20 16:48:16 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 20 16:48:16 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14018, instance 1, run: true Dec 20 16:48:16 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14025, instance 1, run: true Dec 20 16:48:16 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14032, instance 1, run: true Dec 20 16:48:16 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14039, instance 1, run: true Dec 20 16:48:16 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14046, instance 1, run: true Dec 20 16:48:17 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14053, instance 1, run: true Dec 20 16:48:17 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14060, instance 1, run: true Dec 20 16:48:17 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14067, instance 1, run: true Dec 20 16:48:17 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14074, instance 1, run: true Dec 20 16:48:17 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 20 16:48:17 jbl-4312 volumio[11822]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Dec 20 16:48:17 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:48:17 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:48:17 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14081, instance 1, run: true Dec 20 16:48:17 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14088, instance 1, run: true Dec 20 16:48:17 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14095, instance 1, run: true Dec 20 16:48:17 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14102, instance 1, run: true Dec 20 16:48:17 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14109, instance 1, run: true Dec 20 16:48:17 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14116, instance 1, run: true Dec 20 16:48:17 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14123, instance 1, run: true Dec 20 16:48:17 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14130, instance 1, run: true Dec 20 16:48:18 jbl-4312 volumio[11822]: info: BOOT COMPLETED Dec 20 16:48:18 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14137, instance 1, run: true Dec 20 16:48:18 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14144, instance 1, run: true Dec 20 16:48:18 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14151, instance 1, run: true Dec 20 16:48:18 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14158, instance 1, run: true Dec 20 16:48:18 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14165, instance 1, run: true Dec 20 16:48:18 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14172, instance 1, run: true Dec 20 16:48:18 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14179, instance 1, run: true Dec 20 16:48:18 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14186, instance 1, run: true Dec 20 16:48:18 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14203, instance 1, run: true Dec 20 16:48:18 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14217, instance 1, run: true Dec 20 16:48:18 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14224, instance 1, run: true Dec 20 16:48:18 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14231, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14238, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14245, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14252, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14259, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14266, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14273, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14280, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14287, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14294, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14301, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14308, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14315, instance 1, run: true Dec 20 16:48:19 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14322, instance 1, run: true Dec 20 16:48:20 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14329, instance 1, run: true Dec 20 16:48:20 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14336, instance 1, run: true Dec 20 16:48:20 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14343, instance 1, run: true Dec 20 16:48:20 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14350, instance 1, run: true Dec 20 16:48:20 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14357, instance 1, run: true Dec 20 16:48:20 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14364, instance 1, run: true Dec 20 16:48:20 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14371, instance 1, run: true Dec 20 16:48:20 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14378, instance 1, run: true Dec 20 16:48:20 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14385, instance 1, run: true Dec 20 16:48:20 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14392, instance 1, run: true Dec 20 16:48:20 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14399, instance 1, run: true Dec 20 16:48:20 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14406, instance 1, run: true Dec 20 16:48:21 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14413, instance 1, run: true Dec 20 16:48:21 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14420, instance 1, run: true Dec 20 16:48:21 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14427, instance 1, run: true Dec 20 16:48:21 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14434, instance 1, run: true Dec 20 16:48:21 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14441, instance 1, run: true Dec 20 16:48:21 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14448, instance 1, run: true Dec 20 16:48:21 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:48:21.512+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=12 Dec 20 16:48:21 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14455, instance 1, run: true Dec 20 16:48:21 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14462, instance 1, run: true Dec 20 16:48:21 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14469, instance 1, run: true Dec 20 16:48:21 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14476, instance 1, run: true Dec 20 16:48:21 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:48:21.839+09:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0c00 addr=12 Dec 20 16:48:21 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14483, instance 1, run: true Dec 20 16:48:21 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14490, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14497, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14504, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14511, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14518, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:48:22 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:48:22 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 20 16:48:22 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 20 16:48:22 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 20 16:48:22 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetBrowseSources Dec 20 16:48:22 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14525, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14532, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14539, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14546, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14553, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14560, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14567, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14574, instance 1, run: true Dec 20 16:48:22 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14581, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14588, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14595, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14602, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14609, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14616, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14623, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14630, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14637, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14644, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14651, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14658, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14665, instance 1, run: true Dec 20 16:48:23 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14672, instance 1, run: true Dec 20 16:48:24 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14679, instance 1, run: true Dec 20 16:48:24 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14686, instance 1, run: true Dec 20 16:48:24 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14693, instance 1, run: true Dec 20 16:48:24 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14700, instance 1, run: true Dec 20 16:48:24 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14707, instance 1, run: true Dec 20 16:48:24 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14714, instance 1, run: true Dec 20 16:48:24 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14721, instance 1, run: true Dec 20 16:48:24 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14728, instance 1, run: true Dec 20 16:48:24 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14735, instance 1, run: true Dec 20 16:48:24 jbl-4312 volumio[11822]: info: Enabling plugin spop Dec 20 16:48:24 jbl-4312 volumio[11822]: info: Loading plugin "spop"... Dec 20 16:48:25 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:48:25.202+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=12 Dec 20 16:48:25 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:48:25.619+09:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0c00 addr=12 Dec 20 16:48:25 jbl-4312 volumio[11822]: info: PLUGIN START: spop Dec 20 16:48:25 jbl-4312 volumio[11822]: info: Creating Spotify config file Dec 20 16:48:25 jbl-4312 volumio[11822]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 20 16:48:25 jbl-4312 volumio[11822]: info: Done. Dec 20 16:48:25 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:48:25 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14742, instance 1, run: true Dec 20 16:48:25 jbl-4312 volumio[11822]: info: Spotify config file written Dec 20 16:48:26 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:48:26 jbl-4312 volumio[11822]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 20 16:48:26 jbl-4312 volumio[11822]: info: No need to fix Spotify hosts Dec 20 16:48:26 jbl-4312 sudo[14750]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 20 16:48:26 jbl-4312 sudo[14750]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 20 16:48:26 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14752, instance 1, run: true Dec 20 16:48:26 jbl-4312 systemd[1]: Started go-librespot Daemon. Dec 20 16:48:26 jbl-4312 sudo[14750]: pam_unix(sudo:session): session closed for user root Dec 20 16:48:26 jbl-4312 go-librespot[14757]: go-librespot daemon starting... Dec 20 16:48:26 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:26+09:00" level=info msg="running go-librespot 0.4.0" Dec 20 16:48:26 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:26+09:00" level=debug msg="app state loaded" Dec 20 16:48:26 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:26+09:00" level=debug msg="stored credentials not found" Dec 20 16:48:26 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:26+09:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 20 16:48:26 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:26+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-gew4.spotify.com:80]" Dec 20 16:48:26 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:26+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 20 16:48:26 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:26+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 20 16:48:26 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:26+09:00" level=info msg="zeroconf server listening on port 39073" Dec 20 16:48:26 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14774, instance 1, run: true Dec 20 16:48:26 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14781, instance 1, run: true Dec 20 16:48:27 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14788, instance 1, run: true Dec 20 16:48:27 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14795, instance 1, run: true Dec 20 16:48:27 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14802, instance 1, run: true Dec 20 16:48:27 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14809, instance 1, run: true Dec 20 16:48:27 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14816, instance 1, run: true Dec 20 16:48:27 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14823, instance 1, run: true Dec 20 16:48:27 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14830, instance 1, run: true Dec 20 16:48:27 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14837, instance 1, run: true Dec 20 16:48:27 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14844, instance 1, run: true Dec 20 16:48:27 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14851, instance 1, run: true Dec 20 16:48:27 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14858, instance 1, run: true Dec 20 16:48:27 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14865, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14872, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14879, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14886, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14893, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14900, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14907, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14914, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14921, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14928, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14935, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14959, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14966, instance 1, run: true Dec 20 16:48:28 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14973, instance 1, run: true Dec 20 16:48:29 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14980, instance 1, run: true Dec 20 16:48:29 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14987, instance 1, run: true Dec 20 16:48:29 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 14994, instance 1, run: true Dec 20 16:48:29 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15001, instance 1, run: true Dec 20 16:48:29 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15008, instance 1, run: true Dec 20 16:48:29 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15015, instance 1, run: true Dec 20 16:48:29 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15022, instance 1, run: true Dec 20 16:48:29 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15029, instance 1, run: true Dec 20 16:48:29 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15036, instance 1, run: true Dec 20 16:48:29 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15043, instance 1, run: true Dec 20 16:48:29 jbl-4312 volumio[11822]: info: go-librespot daemon successfully initialized Dec 20 16:48:29 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15050, instance 1, run: true Dec 20 16:48:29 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15057, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15064, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15071, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15078, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:48:30.209+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=12 Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15085, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15092, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15099, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15106, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15113, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:48:30.613+09:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0c00 addr=12 Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15120, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15127, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15134, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15141, instance 1, run: true Dec 20 16:48:30 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15148, instance 1, run: true Dec 20 16:48:31 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15155, instance 1, run: true Dec 20 16:48:31 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15162, instance 1, run: true Dec 20 16:48:31 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15169, instance 1, run: true Dec 20 16:48:31 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15176, instance 1, run: true Dec 20 16:48:31 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15183, instance 1, run: true Dec 20 16:48:31 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15190, instance 1, run: true Dec 20 16:48:31 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15197, instance 1, run: true Dec 20 16:48:31 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15204, instance 1, run: true Dec 20 16:48:31 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15211, instance 1, run: true Dec 20 16:48:31 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15218, instance 1, run: true Dec 20 16:48:31 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15225, instance 1, run: true Dec 20 16:48:31 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15232, instance 1, run: true Dec 20 16:48:32 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15239, instance 1, run: true Dec 20 16:48:32 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15246, instance 1, run: true Dec 20 16:48:32 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15253, instance 1, run: true Dec 20 16:48:32 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15260, instance 1, run: true Dec 20 16:48:32 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15267, instance 1, run: true Dec 20 16:48:32 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15274, instance 1, run: true Dec 20 16:48:32 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15281, instance 1, run: true Dec 20 16:48:32 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15288, instance 1, run: true Dec 20 16:48:32 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15295, instance 1, run: true Dec 20 16:48:32 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15302, instance 1, run: true Dec 20 16:48:32 jbl-4312 volumio[11822]: info: Initializing connection to go-librespot Websocket Dec 20 16:48:32 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:32+09:00" level=debug msg="new websocket client" Dec 20 16:48:32 jbl-4312 volumio[11822]: info: Connection to go-librespot Websocket established Dec 20 16:48:32 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15309, instance 1, run: true Dec 20 16:48:32 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15316, instance 1, run: true Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15323, instance 1, run: true Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15330, instance 1, run: true Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15337, instance 1, run: true Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15344, instance 1, run: true Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15351, instance 1, run: true Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15358, instance 1, run: true Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15365, instance 1, run: true Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15372, instance 1, run: true Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15382, instance 1, run: true Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15389, instance 1, run: true Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15396, instance 1, run: true Dec 20 16:48:33 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:33+09:00" level=debug msg="obtained new client token: AACkFzJToxCLXp1SKrHN1UOSd1HgNeaKUN07pZalsnEVVRKcLwuyvLUxm58b+xEeJzK3EmIyZUOnZz4RPtlz1ytDQ0hEBNkILE2U7S29xUPBGqZuabrnJyZEVYVUdd4Z84BFHqLYlcAZEmmWY2falahKIOakegEJUpicgAvGuy12BSdN3mBbJYHkb5Wl1xD8Fd/EZRnOWXN0L8ok3KD/PeOe2AL1yBOTqP28pTQKAfCppi6Mop+u5+E1Ow==" Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15403, instance 1, run: true Dec 20 16:48:33 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:33+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Dec 20 16:48:33 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15410, instance 1, run: true Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="completed keyexchange" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="completed challenge" Dec 20 16:48:34 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15417, instance 1, run: true Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=info msg="authenticated AP" username="mn*********************mt" Dec 20 16:48:34 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15424, instance 1, run: true Dec 20 16:48:34 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15431, instance 1, run: true Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=info msg="authenticated Login5" username="mn*********************mt" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=info msg="accepted zeroconf from iPhone" username="mn*********************mt" Dec 20 16:48:34 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15438, instance 1, run: true Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="dealer connection opened" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=trace msg="starting accesspoint recv loop" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=trace msg="starting dealer recv loop" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=trace msg="received accesspoint ping" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="received connection id: NWZiZWUwOTktODM2...OEVBRTQyMDExNQ==" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=trace msg="received accesspoint pong ack" Dec 20 16:48:34 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15445, instance 1, run: true Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="put connect state because NEW_DEVICE" Dec 20 16:48:34 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15452, instance 1, run: true Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="handling transfer player command from ae9fa72e7bdf601bfefe1272a12caf7caaed7321" Dec 20 16:48:34 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15459, instance 1, run: true Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DZ06evO2fAoGH" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=trace msg="fetched new page 0 with 46 items (list: 46)" uri="spotify:playlist:37i9dQZF1DZ06evO2fAoGH" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="loading track (paused: false, position: 114261ms)" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:34 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15466, instance 1, run: true Dec 20 16:48:34 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15473, instance 1, run: true Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=trace msg="emitting websocket event: will_play" Dec 20 16:48:34 jbl-4312 volumio[11822]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1DZ06evO2fAoGH","uri":"spotify:track:0JL9TZip7mL7iwC5EOkALS","play_origin":"playlist/ondemand"}} Dec 20 16:48:34 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15480, instance 1, run: true Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="selected format OGG_VORBIS_320 (8e27c7626f1f784c45d48689907d2c73d9266e61)" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=debug msg="requested aes key for file 8e27c7626f1f784c45d48689907d2c73d9266e61, gid: 0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:34 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15487, instance 1, run: true Dec 20 16:48:34 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:34+09:00" level=trace msg="found 3 cdn urls" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:34 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15494, instance 1, run: true Dec 20 16:48:35 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15501, instance 1, run: true Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="fetched first chunk of 17, total size is 8880424 bytes" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:35 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15508, instance 1, run: true Dec 20 16:48:35 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:48:35.262+09:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=12 Dec 20 16:48:35 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15516, instance 1, run: true Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:35 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15523, instance 1, run: true Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:35 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15530, instance 1, run: true Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="fetched chunk 12/16, size: 524288" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="fetched chunk 10/16, size: 524288" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="fetched chunk 9/16, size: 524288" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="fetched chunk 11/16, size: 524288" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=trace msg="seek to 114261ms (diff: 41ms, samples: 5038910, bytes: 5153097)" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="created new output device" Dec 20 16:48:35 jbl-4312 volumio5-onboarding[3453]: time=2025-12-20T16:48:35.541+09:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0c00 addr=12 Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=info msg="loaded track \"Lady Brown (feat. Cise Starr from CYNE)\" (paused: false, position: 114261ms, duration: 199160ms, prefetched: false)" uri="spotify:track:0JL9TZip7mL7iwC5EOkALS" Dec 20 16:48:35 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15539, instance 1, run: true Dec 20 16:48:35 jbl-4312 volumio[11822]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Dec 20 16:48:35 jbl-4312 volumio[11822]: info: FusionDsp - ---- read samplerate from file: 44100 Dec 20 16:48:35 jbl-4312 volumio[11822]: info: FusionDsp - If filter freq >samplerate/2 then disable it Dec 20 16:48:35 jbl-4312 volumio[11822]: info: FusionDsp - {"Reload":{"result":"Ok"}} Dec 20 16:48:35 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15547, instance 1, run: true Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=trace msg="scheduling prefetch in 55s" Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=trace msg="emitting websocket event: metadata" Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=trace msg="emitting websocket event: active" Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="sending successful reply for dealer request" Dec 20 16:48:35 jbl-4312 volumio[11822]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0JL9TZip7mL7iwC5EOkALS","name":"Lady Brown (feat. Cise Starr from CYNE)","artist_names":["Nujabes","Cise Starr"],"album_name":"Metaphorical Music","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a1a897ee5e642da6d945bcd7","position":114261,"duration":199160,"release_date":"year:2003 month:8 day:21","track_number":3,"disc_number":1}} Dec 20 16:48:35 jbl-4312 volumio[11822]: SPOTIFY: received: {"type":"active","data":null} Dec 20 16:48:35 jbl-4312 volumio[11822]: info: Aligning Spotify Volume to Volumio Volume Dec 20 16:48:35 jbl-4312 volumio[11822]: info: CoreCommandRouter::volumioGetState Dec 20 16:48:35 jbl-4312 volumio[11822]: info: CorePlayQueue::getTrack 0 Dec 20 16:48:35 jbl-4312 volumio[11822]: info: camilladsp spawned new process with pid 15554, instance 1, run: true Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 20 16:48:35 jbl-4312 go-librespot[14757]: time="2025-12-20T16:48:35+09:00" level=trace msg="emitting websocket event: playing" Dec 20 16:48:35 jbl-4312 volumio[11822]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1DZ06evO2fAoGH","uri":"spotify:track:0JL9TZip7mL7iwC5EOkALS","resume":false,"play_origin":"playlist/ondemand"}} Dec 20 16:48:35 jbl-4312 volumio[11822]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 20 16:48:35 jbl-4312 volumio[11822]: TypeError: Cannot read property 'service' of undefined Dec 20 16:48:35 jbl-4312 volumio[11822]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Dec 20 16:48:35 jbl-4312 volumio[11822]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Dec 20 16:48:35 jbl-4312 volumio[11822]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Dec 20 16:48:35 jbl-4312 volumio[11822]: at WebSocket.emit (events.js:400:28) Dec 20 16:48:35 jbl-4312 volumio[11822]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Dec 20 16:48:35 jbl-4312 volumio[11822]: at Receiver.emit (events.js:400:28) Dec 20 16:48:35 jbl-4312 volumio[11822]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Dec 20 16:48:35 jbl-4312 volumio[11822]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Dec 20 16:48:35 jbl-4312 volumio[11822]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Dec 20 16:48:35 jbl-4312 volumio[11822]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Dec 20 16:48:35 jbl-4312 volumio[11822]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 20 16:48:36 jbl-4312 sudo[15570]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-20 16:47 Dec 20 16:48:36 jbl-4312 sudo[15570]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="b43c85cc0006d3f1efecba101311ec96e334d1fd" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="2f25e1a98e53e2dbc4f3878604e250b0379f3ea4" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 11 Dec 2025 06:47:33 PM CET" VOLUMIO_VERSION="3.886" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo Plus" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo Plus" VOLUMIO_HASH="9e8aa5d6afb5e5d87a87bafae7aa5647"