Aug 25 19:37:00 volumio volumio[9999]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Aug 25 19:37:00 volumio volumio[9999]: info: Initializing connection to go-librespot Websocket Aug 25 19:37:00 volumio volumio[9999]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 19:37:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Aug 25 19:37:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:37:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:37:00 volumio go-librespot[10376]: go-librespot daemon starting... Aug 25 19:37:00 volumio go-librespot[10377]: time="2026-08-25T19:37:00+08:00" level=info msg="running go-librespot 0.4.0" Aug 25 19:37:00 volumio go-librespot[10377]: time="2026-08-25T19:37:00+08:00" level=debug msg="app state loaded" Aug 25 19:37:00 volumio go-librespot[10377]: time="2026-08-25T19:37:00+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 19:37:01 volumio go-librespot[10377]: time="2026-08-25T19:37:01+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 19:37:01 volumio go-librespot[10377]: time="2026-08-25T19:37:01+08: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]" Aug 25 19:37:01 volumio go-librespot[10377]: time="2026-08-25T19:37:01+08: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]" Aug 25 19:37:01 volumio go-librespot[10377]: time="2026-08-25T19:37:01+08:00" level=info msg="zeroconf server listening on port 35459" Aug 25 19:37:01 volumio go-librespot[10377]: time="2026-08-25T19:37:01+08:00" level=debug msg="obtained new client token: AAFtttgcKQUx0sU8p7xSjTAV7oselmtMUOhyEAzU5CECnBeHFt8APF+mWoZsOGpCwQUrxALCLlIcR7SBGdJxu9zpv7Ff5S4jwBNzxtLnOZ8mXkClcxkD7ZfYHkmC0oVVg6Dr05gWdV4/lIqzL4/34DMzuiuPcLAkg/wbnojMeQLDEWRvnNqgyeKs3SzXKzi94EhbC4SWaSJWllENprplZNUIRafvmhD7mX8d9lvcJxC2WyVgOLEemw==" Aug 25 19:37:01 volumio go-librespot[10377]: time="2026-08-25T19:37:01+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 25 19:37:01 volumio go-librespot[10377]: time="2026-08-25T19:37:01+08:00" level=debug msg="completed keyexchange" Aug 25 19:37:01 volumio go-librespot[10377]: time="2026-08-25T19:37:01+08:00" level=debug msg="completed challenge" Aug 25 19:37:01 volumio go-librespot[10377]: time="2026-08-25T19:37:01+08:00" level=info msg="authenticated AP" username="le*********ng" Aug 25 19:37:01 volumio go-librespot[10377]: time="2026-08-25T19:37:01+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 19:37:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 19:37:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 19:37:03 volumio volumio[9999]: info: Initializing connection to go-librespot Websocket Aug 25 19:37:03 volumio volumio[9999]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 19:37:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Aug 25 19:37:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:37:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:37:04 volumio go-librespot[10386]: go-librespot daemon starting... Aug 25 19:37:04 volumio go-librespot[10387]: time="2026-08-25T19:37:04+08:00" level=info msg="running go-librespot 0.4.0" Aug 25 19:37:04 volumio go-librespot[10387]: time="2026-08-25T19:37:04+08:00" level=debug msg="app state loaded" Aug 25 19:37:04 volumio go-librespot[10387]: time="2026-08-25T19:37:04+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 19:37:04 volumio go-librespot[10387]: time="2026-08-25T19:37:04+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 19:37:04 volumio go-librespot[10387]: time="2026-08-25T19:37:04+08: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]" Aug 25 19:37:04 volumio go-librespot[10387]: time="2026-08-25T19:37:04+08: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]" Aug 25 19:37:04 volumio go-librespot[10387]: time="2026-08-25T19:37:04+08:00" level=info msg="zeroconf server listening on port 37237" Aug 25 19:37:04 volumio go-librespot[10387]: time="2026-08-25T19:37:04+08:00" level=debug msg="obtained new client token: AAEM3ev31RIfFrGiwwQ17IyS1yTedA1dCWSwCCBmsTbbA9P4mVq75MvcUrshQ7pfXpz50JrflrT7fofPokwzwxzBq7abU0Ae3tf+n+6Jd00E8p8wut1h3FrOgrFquU0BmH+0WnBq1KB6Raw0Mc2wIneizisfwn16y+ditekkdKtqgU72ZOghiz1pb+V+ZrSCTD+AtdEKXY2ceNrB2ISGBPsLHhbyZxK3MdFTQ3WZxHTtSNuDhdD1q2sy" Aug 25 19:37:05 volumio go-librespot[10387]: time="2026-08-25T19:37:05+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 25 19:37:05 volumio go-librespot[10387]: time="2026-08-25T19:37:05+08:00" level=debug msg="completed keyexchange" Aug 25 19:37:05 volumio go-librespot[10387]: time="2026-08-25T19:37:05+08:00" level=debug msg="completed challenge" Aug 25 19:37:05 volumio go-librespot[10387]: time="2026-08-25T19:37:05+08:00" level=info msg="authenticated AP" username="le*********ng" Aug 25 19:37:05 volumio kernel: hwmon hwmon3: Undervoltage detected! Aug 25 19:37:05 volumio go-librespot[10387]: time="2026-08-25T19:37:05+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 19:37:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 19:37:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 19:37:05 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 25 19:37:05 volumio volumio[9999]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Aug 25 19:37:05 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:05 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:06 volumio volumio[9999]: info: Initializing connection to go-librespot Websocket Aug 25 19:37:06 volumio volumio[9999]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 19:37:07 volumio kernel: hwmon hwmon3: Voltage normalised Aug 25 19:37:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Aug 25 19:37:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:37:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:37:08 volumio go-librespot[10403]: go-librespot daemon starting... Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08:00" level=info msg="running go-librespot 0.4.0" Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08:00" level=debug msg="app state loaded" Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08: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]" Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08: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]" Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08:00" level=info msg="zeroconf server listening on port 38737" Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08:00" level=debug msg="obtained new client token: AAHsCHlXedzF/xgrm5iMAtcUsnJPAitus8yo2s4+At9e3linLIeQ3Uehk31sxO7K7ZInrRurv/s4fdobQ9EgFMFYqaCLxW9VHAi54OvehkTkiEiqSMIvgjh19lsXAhFUB+SfvpE6jhexduK0aVuNyDPI6zPqJaia5gq7gipKd4/KxPN6pYe4fy1llCwbq1HQFyNzXG/8XyramChobNlMYjV15Sbu/14Y8M+Tr8JT7jWqO0awGHd2Bi05" Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08:00" level=debug msg="completed keyexchange" Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08:00" level=debug msg="completed challenge" Aug 25 19:37:08 volumio go-librespot[10404]: time="2026-08-25T19:37:08+08:00" level=info msg="authenticated AP" username="le*********ng" Aug 25 19:37:09 volumio go-librespot[10404]: time="2026-08-25T19:37:09+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 19:37:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 19:37:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 19:37:09 volumio volumio[9999]: info: Initializing connection to go-librespot Websocket Aug 25 19:37:09 volumio volumio[9999]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 19:37:10 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 19:37:10 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 19:37:10 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 25 19:37:10 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 25 19:37:10 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 25 19:37:10 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 25 19:37:10 volumio volumio[9999]: info: CoreCommandRouter::volumioGetBrowseSources Aug 25 19:37:10 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 19:37:11 volumio volumio[9999]: error: MyVolumio Plugin failed to authenticate in a timely fashion Aug 25 19:37:11 volumio volumio[9999]: info: Completed starting MyVolumio Plugin Aug 25 19:37:11 volumio volumio[9999]: [Metrics] CommandRouter: 31s 514.42ms Aug 25 19:37:11 volumio volumio[9999]: info: CoreCommandRouter::volumiosetStartupVolume Aug 25 19:37:11 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 25 19:37:11 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 19:37:11 volumio volumio[9999]: info: CoreCommandRouter::Close All Modals sent Aug 25 19:37:11 volumio volumio[9999]: info: CoreCommandRouter::Close All Modals sent Aug 25 19:37:11 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 19:37:11 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 19:37:11 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 25 19:37:11 volumio volumio-remote-updater[957]: Test mode disabled Aug 25 19:37:11 volumio volumio-remote-updater[957]: Alpha mode disabled Aug 25 19:37:11 volumio volumio-remote-updater[957]: Alpha legacy test mode disabled Aug 25 19:37:11 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Aug 25 19:37:12 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Aug 25 19:37:12 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 25 19:37:12 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Aug 25 19:37:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Aug 25 19:37:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:37:12 volumio volumio[9999]: info: Initializing connection to go-librespot Websocket Aug 25 19:37:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:37:12 volumio volumio[9999]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 19:37:12 volumio go-librespot[10432]: go-librespot daemon starting... Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=info msg="running go-librespot 0.4.0" Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=debug msg="app state loaded" Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 19:37:12 volumio volumio[9999]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 25 19:37:12 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=info msg="zeroconf server listening on port 33121" Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=debug msg="obtained new client token: AAFVRPiR34+n1VLpSIvRxmVWPNyRAN9CsCDHf3GgLaqhJk1SGzn95bhuHda4bp4HeYT8JDd56vXgupAkAnGyaU2TEhElcVu1/30XWcA3WtF60OsfVwrKyMm2/38R7fA5T8WohgTPrt4kWdbjuwwQOxRrPVGYcMi/SntgZIOu0GBThpPYW7wWo4Td7X3DvyaHGqpS7r3BSLWt567AuiOYL0cJfQjpKnuJJL/QV+xLa9umt8BnD2niA0LZ" Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=debug msg="completed keyexchange" Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=debug msg="completed challenge" Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=info msg="authenticated AP" username="le*********ng" Aug 25 19:37:12 volumio go-librespot[10433]: time="2026-08-25T19:37:12+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 19:37:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 19:37:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 19:37:14 volumio bluealsa[1067]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_41_03_D3_78_DC_02, ...) Aug 25 19:37:15 volumio volumio[9999]: info: Initializing connection to go-librespot Websocket Aug 25 19:37:15 volumio volumio[9999]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 19:37:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Aug 25 19:37:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:37:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:37:15 volumio go-librespot[10440]: go-librespot daemon starting... Aug 25 19:37:15 volumio go-librespot[10441]: time="2026-08-25T19:37:15+08:00" level=info msg="running go-librespot 0.4.0" Aug 25 19:37:15 volumio go-librespot[10441]: time="2026-08-25T19:37:15+08:00" level=debug msg="app state loaded" Aug 25 19:37:15 volumio go-librespot[10441]: time="2026-08-25T19:37:15+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 19:37:16 volumio go-librespot[10441]: time="2026-08-25T19:37:16+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 25 19:37:16 volumio go-librespot[10441]: time="2026-08-25T19:37:16+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 25 19:37:16 volumio go-librespot[10441]: time="2026-08-25T19:37:16+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 25 19:37:16 volumio go-librespot[10441]: time="2026-08-25T19:37:16+08:00" level=info msg="zeroconf server listening on port 36499" Aug 25 19:37:16 volumio go-librespot[10441]: time="2026-08-25T19:37:16+08:00" level=debug msg="obtained new client token: AAFIfqmZ/olVyZ3MRfeY5NbiUEHB5irio7sBOUy+P5lOAo44adfWYa2p2VpisjwZVt+X8cNCaRwK3S6BD3RBqx9DbIb/lACb9VcAh8e58rlRfwZZiphrawSEPHrl89QtXUTYulqgDlEPEL0gu1s/TpgZ2I9vwNLZG+6FTQgIwpWOKpLX3fvMJB36oE2BwA90adBz734L/b+LwHj0rDYdV+c6JIL8ESK1be2j2P+qUVRyWmX91V9yiQ==" Aug 25 19:37:16 volumio go-librespot[10441]: time="2026-08-25T19:37:16+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 25 19:37:16 volumio go-librespot[10441]: time="2026-08-25T19:37:16+08:00" level=debug msg="completed keyexchange" Aug 25 19:37:16 volumio go-librespot[10441]: time="2026-08-25T19:37:16+08:00" level=debug msg="completed challenge" Aug 25 19:37:16 volumio go-librespot[10441]: time="2026-08-25T19:37:16+08:00" level=info msg="authenticated AP" username="le*********ng" Aug 25 19:37:16 volumio go-librespot[10441]: time="2026-08-25T19:37:16+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 25 19:37:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 19:37:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 19:37:18 volumio volumio[9999]: info: BOOT COMPLETED Aug 25 19:37:18 volumio volumio[9999]: info: Initializing connection to go-librespot Websocket Aug 25 19:37:18 volumio volumio[9999]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 19:37:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Aug 25 19:37:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:37:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:37:19 volumio go-librespot[10449]: go-librespot daemon starting... Aug 25 19:37:19 volumio go-librespot[10450]: time="2026-08-25T19:37:19+08:00" level=info msg="running go-librespot 0.4.0" Aug 25 19:37:19 volumio go-librespot[10450]: time="2026-08-25T19:37:19+08:00" level=debug msg="app state loaded" Aug 25 19:37:19 volumio go-librespot[10450]: time="2026-08-25T19:37:19+08:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 25 19:37:19 volumio go-librespot[10450]: time="2026-08-25T19:37:19+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 19:37:19 volumio go-librespot[10450]: time="2026-08-25T19:37:19+08: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]" Aug 25 19:37:19 volumio go-librespot[10450]: time="2026-08-25T19:37:19+08: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]" Aug 25 19:37:19 volumio go-librespot[10450]: time="2026-08-25T19:37:19+08:00" level=info msg="zeroconf server listening on port 45145" Aug 25 19:37:19 volumio go-librespot[10450]: time="2026-08-25T19:37:19+08:00" level=debug msg="obtained new client token: AAFx7TtS2bcqhXOau6AFWKDBdRAU+F2sXhVQhXcbItbWnFMxBABC7DXdMR8XoCaJvhgsrZlbx/tfpnZDel+PmCZkeaI0YjOSg5aujGv1McHqpqm1WJ8YLODeaG3/cX1V7d1qXbUnjFX3+02ei8f2gzsx8fcrpRF8OacZqXw21n86fq2LwuqQZjFzeAX6V1HXCE92YOyHicgXWQ89cuAOvgisqxEqW8OX0XDSUNtlqOX5RqTsmDsFT97B" Aug 25 19:37:20 volumio go-librespot[10450]: time="2026-08-25T19:37:20+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 25 19:37:21 volumio volumio[9999]: info: Initializing connection to go-librespot Websocket Aug 25 19:37:21 volumio go-librespot[10450]: time="2026-08-25T19:37:21+08:00" level=debug msg="new websocket client" Aug 25 19:37:21 volumio volumio[9999]: info: Connection to go-librespot Websocket established Aug 25 19:37:24 volumio volumio[9999]: info: Getting Spotify volume Aug 25 19:37:24 volumio volumio[9999]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:24 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:24 volumio volumio[9999]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Aug 25 19:37:24 volumio volumio[9999]: SPOTIFY: SPOTIFY VOLUME undefined Aug 25 19:37:24 volumio volumio[9999]: SPOTIFY: VOLUMIO VOLUME 54 Aug 25 19:37:24 volumio volumio[9999]: info: Aligning Spotify Volume to Volumio Volume Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:24 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:24 volumio volumio[9999]: info: Setting Spotify Volume from Volumio: 54 Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.412+08:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.82:59074 Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.458+08:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-31.750233ms platform=PLATFORM_ANDROID version=6.260807.0 Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.458+08:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.1.82:59074 @ 0x325e1e0" latency=-32.68164ms timeout=20s Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.458+08:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" Aug 25 19:37:24 volumio volumio[9999]: info: Received Get System Info Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:37:24 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:24 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.460+08:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" name=Volumio Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.461+08:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" language=en Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.462+08:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" timezone=Asia/Kuala_Lumpur Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.462+08:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" available=true connected=true macAddress=2c:cf:67:bd:53:0b ip4Address=192.168.1.52/24 ip6Address= Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.463+08:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.463+08:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" setupComplete=true Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 25 19:37:24 volumio volumio[9999]: amixer -c 0 info | grep "vc4-hdmi-0" Aug 25 19:37:24 volumio volumio[9999]: Card sysdefault:0 'vc4hdmi0'/'vc4-hdmi-0' Aug 25 19:37:24 volumio volumio[9999]: amixer -c 1 info | grep "vc4-hdmi-1" Aug 25 19:37:24 volumio volumio[9999]: Card sysdefault:1 'vc4hdmi1'/'vc4-hdmi-1' Aug 25 19:37:24 volumio volumio[9999]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 2 Aug 25 19:37:24 volumio volumio[9999]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 25 19:37:24 volumio volumio[9999]: {"cmd":"/usr/local/bin/alsacap -C 2","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 2\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Aug 25 19:37:24 volumio volumio[9999]: amixer -c 2 info | grep "RPi DAC+" Aug 25 19:37:24 volumio volumio[9999]: Card sysdefault:2 'DAC'/'RPi DAC+' Aug 25 19:37:24 volumio volumio[9999]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 2 Aug 25 19:37:24 volumio volumio[9999]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 25 19:37:24 volumio volumio[9999]: {"cmd":"/usr/local/bin/alsacap -C 2","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 2\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Aug 25 19:37:24 volumio volumio[9999]: amixer -c 2 info | grep "Raspberry Pi DAC+" Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.518+08:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" selectedOutputId=2 Aug 25 19:37:24 volumio volumio[9999]: info: Received Get System Info Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:37:24 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:24 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.524+08:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" currentVersion=4.119 latestVersion=4.119 Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.524+08:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" status=UPDATE_STATUS_NONE progress=0 Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.524+08:00 level=INFO msg="emitting user changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" userId=ldeFqmOXI0R66j8gjQJ139DJ4IM2 Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.525+08:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" providers=9 Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.525+08:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" plugins=82 Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:24 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.526+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" state=STATUS_STOPPED positionMs=0 volume=54 Aug 25 19:37:24 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:24.526+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.82:59074 @ 0x325e1e0" id="mnt/NAS/Music/Kitaro/The Best of Kitaro/01 Orochi.flac" title=Orochi Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:37:24 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:24 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:37:24 volumio volumio[9999]: verbose: New Socket.io Connection to 192.168.1.52:3000 from 192.168.1.82 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 25 19:37:24 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 25 19:37:25 volumio volumio[9999]: SPOTIFY: SETTING SPOTIFY VOLUME 54 Aug 25 19:37:25 volumio volumio[9999]: info: Sending Spotify command with payload to local API: /player/volume Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.399+08:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.1.82:59074 @ 0x325e1e0" latency=-30.503228ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.424+08:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.440+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=13.469589ms Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.460+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=https://google.com duration=34.965553ms Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.478+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=53.843578ms Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.531+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=https://www.googleapis.com duration=105.940387ms Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.539+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=111.34699ms Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.601+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=http://pushupdates.volumio.org duration=173.781723ms Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.641+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=https://securetoken.googleapis.com duration=215.94672ms Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.683+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=https://functions.volumio.cloud duration=255.898059ms Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.690+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=https://functions.volumio.cloud duration=261.885831ms Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.899+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=https://database.volumio.cloud duration=470.664219ms Aug 25 19:37:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:26.906+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=480.403603ms Aug 25 19:37:26 volumio sudo[10496]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 19:37:26 volumio sudo[10496]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 19:37:26 volumio sudo[10496]: pam_unix(sudo:session): session closed for user root Aug 25 19:37:26 volumio sudo[10498]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 19:37:26 volumio sudo[10498]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 19:37:26 volumio sudo[10498]: pam_unix(sudo:session): session closed for user root Aug 25 19:37:26 volumio volumio[9999]: verbose: New Socket.io Connection to 192.168.1.52 from 192.168.1.82 UA: Mozilla/5.0 (Linux; Android 16; SM-S918B Build/BP4A.251205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.83 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Aug 25 19:37:27 volumio sudo[10502]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 19:37:27 volumio sudo[10502]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 19:37:27 volumio sudo[10504]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 19:37:27 volumio sudo[10504]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 19:37:27 volumio sudo[10502]: pam_unix(sudo:session): session closed for user root Aug 25 19:37:27 volumio sudo[10504]: pam_unix(sudo:session): session closed for user root Aug 25 19:37:27 volumio volumio[9999]: verbose: New Socket.io Connection to 192.168.1.52 from 192.168.1.82 UA: Mozilla/5.0 (Linux; Android 16; SM-S918B Build/BP4A.251205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.83 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Aug 25 19:37:27 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:27.169+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=http://plugins.volumio.org duration=741.560689ms Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::volumioGetVisibleSources Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:27 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 25 19:37:27 volumio volumio[9999]: info: Received Get System Info Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:37:27 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:27 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:27 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:27 volumio volumio[9999]: info: Listing playlists Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 25 19:37:27 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:27.372+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:59074 @ 0x325e1e0" latency=-33.67685ms timeout=10s endpoint=http://cddb.volumio.org duration=945.467737ms Aug 25 19:37:27 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 25 19:37:28 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 25 19:37:29 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 19:37:29 volumio volumio[9999]: info: Received Get System Info Aug 25 19:37:29 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:37:29 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:37:29 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:37:29 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:29 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:29 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:37:29 volumio volumio[9999]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 25 19:37:29 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 25 19:37:29 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 25 19:37:29 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 25 19:37:29 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Aug 25 19:37:30 volumio volumio[9999]: info: Received Get System Version Aug 25 19:37:30 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 19:37:30 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 19:37:30 volumio volumio[9999]: info: Received Get System Info Aug 25 19:37:30 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:37:30 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:37:30 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:37:30 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:30 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:30 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:37:30 volumio bluealsa[1067]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_60_A1_EE_D7_5A_94, ...) Aug 25 19:37:31 volumio kernel: hwmon hwmon3: Undervoltage detected! Aug 25 19:37:32 volumio volumio5-onboarding[1583]: time=2026-08-25T19:37:32.508+08:00 level=INFO msg="new address was allocated" component=ble/conn old=4 new=5 Aug 25 19:37:32 volumio dbus-daemon[928]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.13" (uid=0 pid=1583 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.3" (uid=0 pid=924 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 25 19:37:33 volumio kernel: hwmon hwmon3: Voltage normalised Aug 25 19:37:35 volumio volumio-remote-updater[957]: Test mode disabled Aug 25 19:37:35 volumio volumio-remote-updater[957]: Alpha mode disabled Aug 25 19:37:35 volumio volumio-remote-updater[957]: Alpha legacy test mode disabled Aug 25 19:37:36 volumio volumio[9999]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 25 19:37:36 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 25 19:37:37 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 25 19:37:39 volumio volumio[9999]: info: CoreCommandRouter::Close All Modals sent Aug 25 19:37:45 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 25 19:37:45 volumio volumio[9999]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 25 19:37:45 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 25 19:37:45 volumio volumio[9999]: info: Received Get System Version Aug 25 19:37:45 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 25 19:37:45 volumio volumio[9999]: info: Received Get System Info Aug 25 19:37:45 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:37:45 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:37:45 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:37:45 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:37:45 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:37:45 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:38:06 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:06.288+08:00 level=ERROR msg="failed to read message" component=conn/ws remoteAddr=192.168.1.82:59074 error="read tcp 192.168.1.52:7331->192.168.1.82:59074: read: connection reset by peer" Aug 25 19:38:06 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:06.288+08:00 level=INFO msg="WebSocket connection closed" component=conn/ws remoteAddr=192.168.1.82:59074 Aug 25 19:38:06 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:06.288+08:00 level=INFO msg="connection to address closed" component=conn/multi addr=192.168.1.82:59074 Aug 25 19:38:08 volumio bluetoothd[924]: src/device.c:new_auth() No agent available for request type 2 Aug 25 19:38:08 volumio bluetoothd[924]: device_confirm_passkey: Operation not permitted Aug 25 19:38:10 volumio dbus-daemon[928]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.13" (uid=0 pid=1583 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.3" (uid=0 pid=924 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 25 19:38:10 volumio bluetoothd[924]: No matching connection for device Aug 25 19:38:11 volumio bluealsa[1067]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_4F_10_87_65_0B_BE, ...) Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.398+08:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.82:45310 Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.420+08:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.1.82:36168 Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.425+08:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.427+08:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-33.358874ms timeout=20s Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.427+08:00 level=INFO msg="emitting device capabilities changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" Aug 25 19:38:19 volumio volumio[9999]: info: Received Get System Info Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:38:19 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:38:19 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.430+08:00 level=INFO msg="emitting device name changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" name=Volumio Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.430+08:00 level=INFO msg="emitting device language changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" language=en Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.431+08:00 level=INFO msg="emitting device timezone changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" timezone=Asia/Kuala_Lumpur Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.432+08:00 level=INFO msg="emitting ethernet info changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" available=true connected=true macAddress=2c:cf:67:bd:53:0b ip4Address=192.168.1.52/24 ip6Address= Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.435+08:00 level=INFO msg="emitting wifi info changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.436+08:00 level=INFO msg="emitting device setup status changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" setupComplete=true Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.437+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=10.816112ms Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.439+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=12.512029ms Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 25 19:38:19 volumio volumio[9999]: amixer -c 0 info | grep "vc4-hdmi-0" Aug 25 19:38:19 volumio volumio[9999]: Card sysdefault:0 'vc4hdmi0'/'vc4-hdmi-0' Aug 25 19:38:19 volumio volumio[9999]: amixer -c 1 info | grep "vc4-hdmi-1" Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.461+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=https://google.com duration=35.460222ms Aug 25 19:38:19 volumio volumio[9999]: Card sysdefault:1 'vc4hdmi1'/'vc4-hdmi-1' Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.470+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=44.472084ms Aug 25 19:38:19 volumio volumio[9999]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 2 Aug 25 19:38:19 volumio volumio[9999]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 25 19:38:19 volumio volumio[9999]: {"cmd":"/usr/local/bin/alsacap -C 2","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 2\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Aug 25 19:38:19 volumio volumio[9999]: amixer -c 2 info | grep "Raspberry Pi DAC+" Aug 25 19:38:19 volumio volumio[9999]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 2 Aug 25 19:38:19 volumio volumio[9999]: /bin/sh: 1: /usr/local/bin/alsacap: not found Aug 25 19:38:19 volumio volumio[9999]: {"cmd":"/usr/local/bin/alsacap -C 2","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 2\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Aug 25 19:38:19 volumio volumio[9999]: amixer -c 2 info | grep "RPi DAC+" Aug 25 19:38:19 volumio volumio[9999]: Card sysdefault:2 'DAC'/'RPi DAC+' Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.495+08:00 level=INFO msg="emitting audio outputs changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" selectedOutputId=2 Aug 25 19:38:19 volumio volumio[9999]: info: Received Get System Info Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:38:19 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:38:19 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.501+08:00 level=INFO msg="emitting software info changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" currentVersion=4.119 latestVersion=4.119 Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.501+08:00 level=INFO msg="emitting software update progress event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" status=UPDATE_STATUS_NONE progress=0 Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.501+08:00 level=INFO msg="emitting user changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" userId=ldeFqmOXI0R66j8gjQJ139DJ4IM2 Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.501+08:00 level=INFO msg="emitting music providers changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" providers=9 Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.501+08:00 level=INFO msg="emitting plugins changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" plugins=82 Aug 25 19:38:19 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:38:19 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.503+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" state=STATUS_STOPPED positionMs=0 volume=54 Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.503+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" id="mnt/NAS/Music/Kitaro/The Best of Kitaro/01 Orochi.flac" title=Orochi Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.531+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=https://www.googleapis.com duration=105.787313ms Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.599+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=http://pushupdates.volumio.org duration=172.978886ms Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.650+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=https://securetoken.googleapis.com duration=224.472747ms Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.653+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=227.309392ms Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.685+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=https://database.volumio.cloud duration=258.396165ms Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.711+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=https://functions.volumio.cloud duration=284.676358ms Aug 25 19:38:19 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:19.716+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=https://functions.volumio.cloud duration=290.193795ms Aug 25 19:38:20 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:20.170+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=http://cddb.volumio.org duration=743.758536ms Aug 25 19:38:20 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:20.190+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="00:00:00:00:00:00%04,192.168.1.82:45310 @ 0x325e1e0" latency=-31.257069ms timeout=10s endpoint=http://plugins.volumio.org duration=764.00055ms Aug 25 19:38:20 volumio volumio[9999]: verbose: New Socket.io Connection to 192.168.1.52 from 192.168.1.82 UA: Mozilla/5.0 (Linux; Android 16; SM-S918B Build/BP4A.251205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.83 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Aug 25 19:38:20 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 25 19:38:20 volumio volumio[9999]: info: CoreCommandRouter::volumioGetVisibleSources Aug 25 19:38:20 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 19:38:20 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:38:20 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:38:20 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 25 19:38:20 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 25 19:38:20 volumio volumio[9999]: info: Received Get System Info Aug 25 19:38:20 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:38:20 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:38:20 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:38:20 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:38:20 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:38:20 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:38:20 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:38:20 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:38:20 volumio volumio[9999]: info: Listing playlists Aug 25 19:38:20 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 25 19:38:22 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:22.726+08:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=4 chunks=1 index=0 tries=11 Aug 25 19:38:26 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:26.032+08:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=4 chunks=1 index=0 tries=11 Aug 25 19:38:29 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:29.338+08:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=4 chunks=1 index=0 tries=11 Aug 25 19:38:32 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:32.645+08:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=4 chunks=1 index=0 tries=11 Aug 25 19:38:35 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:35.951+08:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=4 chunks=1 index=0 tries=11 Aug 25 19:38:38 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:38.500+08:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s Aug 25 19:38:38 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:38.512+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=11.469764ms Aug 25 19:38:38 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:38.513+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=13.032401ms Aug 25 19:38:38 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:38.534+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=https://google.com duration=33.448472ms Aug 25 19:38:38 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:38.547+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=47.52336ms Aug 25 19:38:38 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:38.606+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=https://www.googleapis.com duration=106.09024ms Aug 25 19:38:38 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:38.674+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=http://pushupdates.volumio.org duration=173.536518ms Aug 25 19:38:38 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:38:38 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:38:38 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:38:38 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:38:38 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:38:38 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:38:38 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:38.726+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=225.363956ms Aug 25 19:38:38 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:38.727+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=https://securetoken.googleapis.com duration=226.756352ms Aug 25 19:38:38 volumio volumio[9999]: verbose: New Socket.io Connection to 192.168.1.52:3000 from 192.168.1.82 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Aug 25 19:38:38 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 25 19:38:38 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 25 19:38:38 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:38.740+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=https://functions.volumio.cloud duration=239.584457ms Aug 25 19:38:38 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:38.747+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=https://functions.volumio.cloud duration=246.329269ms Aug 25 19:38:38 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:38.757+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=https://database.volumio.cloud duration=256.59799ms Aug 25 19:38:39 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:39.128+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=http://cddb.volumio.org duration=626.839241ms Aug 25 19:38:39 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:39.234+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-32.839861ms timeout=10s endpoint=http://plugins.volumio.org duration=733.060315ms Aug 25 19:38:39 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:39.258+08:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=4 chunks=1 index=0 tries=11 Aug 25 19:38:40 volumio bluealsa[1067]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_60_A1_EE_D7_5A_94, ...) Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.064+08:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.1.82:45310 @ 0x325e1e0" latency=-33.251811ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.095+08:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.105+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=10.365943ms Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.108+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=12.635251ms Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.140+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=45.480645ms Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.147+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=https://google.com duration=52.217144ms Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.201+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=https://www.googleapis.com duration=106.075443ms Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.269+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=http://pushupdates.volumio.org duration=173.247628ms Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.321+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=225.539161ms Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.326+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=https://securetoken.googleapis.com duration=230.273945ms Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.337+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=https://database.volumio.cloud duration=241.281724ms Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.339+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=https://functions.volumio.cloud duration=244.137332ms Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.348+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=https://functions.volumio.cloud duration=252.459043ms Aug 25 19:38:41 volumio sudo[10693]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 19:38:41 volumio sudo[10693]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 19:38:41 volumio sudo[10695]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 19:38:41 volumio sudo[10695]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 19:38:41 volumio sudo[10693]: pam_unix(sudo:session): session closed for user root Aug 25 19:38:41 volumio sudo[10695]: pam_unix(sudo:session): session closed for user root Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.513+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=http://cddb.volumio.org duration=417.578072ms Aug 25 19:38:41 volumio volumio[9999]: verbose: New Socket.io Connection to 192.168.1.52 from 192.168.1.82 UA: Mozilla/5.0 (Linux; Android 16; SM-S918B Build/BP4A.251205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.83 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Aug 25 19:38:41 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:41.575+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.1.82:45310 @ 0x325e1e0" latency=-31.659143ms timeout=10s endpoint=http://plugins.volumio.org duration=479.480285ms Aug 25 19:38:41 volumio sudo[10699]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 25 19:38:41 volumio sudo[10699]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 19:38:41 volumio sudo[10701]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 25 19:38:41 volumio sudo[10701]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 19:38:41 volumio sudo[10699]: pam_unix(sudo:session): session closed for user root Aug 25 19:38:41 volumio sudo[10701]: pam_unix(sudo:session): session closed for user root Aug 25 19:38:41 volumio volumio[9999]: verbose: New Socket.io Connection to 192.168.1.52 from 192.168.1.82 UA: Mozilla/5.0 (Linux; Android 16; SM-S918B Build/BP4A.251205.006; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.83 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::volumioGetVisibleSources Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:38:41 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 25 19:38:41 volumio volumio[9999]: info: Received Get System Info Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:38:41 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:38:41 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:38:41 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:38:41 volumio volumio[9999]: info: Listing playlists Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 25 19:38:41 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 25 19:38:42 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 25 19:38:42 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:42.564+08:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=4 chunks=1 index=0 tries=11 Aug 25 19:38:43 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:43.099+08:00 level=INFO msg="new address was allocated" component=ble/conn old=5 new=6 Aug 25 19:38:43 volumio dbus-daemon[928]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.13" (uid=0 pid=1583 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.3" (uid=0 pid=924 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Aug 25 19:38:43 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 25 19:38:43 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 19:38:43 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 25 19:38:43 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 19:38:43 volumio volumio[9999]: info: Received Get System Info Aug 25 19:38:43 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:38:43 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:38:43 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:38:43 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:38:43 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:38:43 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:38:44 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 25 19:38:44 volumio volumio[9999]: info: Received Get System Info Aug 25 19:38:44 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 25 19:38:44 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 25 19:38:44 volumio volumio[9999]: info: Discovery: Getting this device information Aug 25 19:38:44 volumio volumio[9999]: info: CoreCommandRouter::volumioGetState Aug 25 19:38:44 volumio volumio[9999]: info: CorePlayQueue::getTrack 0 Aug 25 19:38:44 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 25 19:38:45 volumio volumio5-onboarding[1583]: time=2026-08-25T19:38:45.921+08:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=4 chunks=1 index=0 tries=11 Aug 25 19:38:46 volumio go-librespot[10450]: time="2026-08-25T19:38:46+08:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Aug 25 19:38:46 volumio volumio[9999]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Aug 25 19:38:46 volumio volumio[9999]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 25 19:38:46 volumio volumio[9999]: info: Disabling plugin spop Aug 25 19:38:46 volumio volumio[9999]: info: Done. Aug 25 19:38:46 volumio volumio[9999]: info: Connection to go-librespot Websocket closed Aug 25 19:38:46 volumio sudo[10706]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service Aug 25 19:38:46 volumio sudo[10706]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 25 19:38:46 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 25 19:38:46 volumio volumio[9999]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Aug 25 19:38:46 volumio volumio[9999]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 19:38:46 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 25 19:38:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 25 19:38:46 volumio volumio[9999]: Error: socket hang up Aug 25 19:38:46 volumio volumio[9999]: at connResetException (node:internal/errors:720:14) Aug 25 19:38:46 volumio volumio[9999]: at Socket.socketOnEnd (node:_http_client:519:23) Aug 25 19:38:46 volumio volumio[9999]: at Socket.emit (node:events:526:35) Aug 25 19:38:46 volumio volumio[9999]: at endReadableNT (node:internal/streams/readable:1376:12) Aug 25 19:38:46 volumio volumio[9999]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Aug 25 19:38:46 volumio volumio[9999]: code: 'ECONNRESET', Aug 25 19:38:46 volumio volumio[9999]: response: undefined Aug 25 19:38:46 volumio volumio[9999]: } Aug 25 19:38:46 volumio volumio[9999]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 19:38:46 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 19:38:46 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 19:38:46 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 19:38:46 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 25 19:38:46 volumio sudo[10706]: pam_unix(sudo:session): session closed for user root Aug 25 19:38:46 volumio sudo[10722]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-25 19:37' Aug 25 19:38:46 volumio sudo[10722]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"