Dec 12 13:26:00 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 158. Dec 12 13:26:00 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:00 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:00 gbvpi-bedroom go-librespot[17002]: go-librespot daemon starting... Dec 12 13:26:00 gbvpi-bedroom go-librespot[17003]: time="2025-12-12T13:26:00-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:00 gbvpi-bedroom go-librespot[17003]: time="2025-12-12T13:26:00-05:00" level=debug msg="app state loaded" Dec 12 13:26:00 gbvpi-bedroom go-librespot[17003]: time="2025-12-12T13:26:00-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:00 gbvpi-bedroom go-librespot[17003]: time="2025-12-12T13:26:00-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:26:00 gbvpi-bedroom go-librespot[17003]: time="2025-12-12T13:26:00-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:26:00 gbvpi-bedroom go-librespot[17003]: time="2025-12-12T13:26:00-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:26:00 gbvpi-bedroom go-librespot[17003]: time="2025-12-12T13:26:00-05:00" level=info msg="zeroconf server listening on port 41699" Dec 12 13:26:01 gbvpi-bedroom go-librespot[17003]: time="2025-12-12T13:26:01-05:00" level=debug msg="obtained new client token: AAA5/VUNK7htyj1lbXzoWDPCXZvyuFXoKd+zNCaWVoJx6oISvzKqM82dfLIs3qcuOTPEKOOKflyicgY1w/Q2l41SiNU9715D11qZLjPrMmElrJjok6MWfIoaVRCa4Rihauho8Az67YQWIT+qdxQbi5HezdQmRvfoKvHk6goY6oC4YVCtaGvaK0tfpVn7xymSoQIrNmANgCZcB5U3JG14WvtrRTWkZPTFZwknxOLvrV86rJ5oyAxbwu4=" Dec 12 13:26:01 gbvpi-bedroom go-librespot[17003]: time="2025-12-12T13:26:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:01 gbvpi-bedroom go-librespot[17003]: time="2025-12-12T13:26:01-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:01 gbvpi-bedroom go-librespot[17003]: time="2025-12-12T13:26:01-05:00" level=debug msg="completed challenge" Dec 12 13:26:01 gbvpi-bedroom go-librespot[17003]: time="2025-12-12T13:26:01-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:01 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:01 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: Initializing connection to go-librespot Websocket Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: TidalConnect service started! Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: [Metrics] CommandRouter: 29s 323.87ms Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::volumiosetStartupVolume Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::Close All Modals sent Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::Close All Modals sent Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: Listing playlists Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: Listing playlists Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: Listing playlists Dec 12 13:26:02 gbvpi-bedroom volumio[16447]: info: Listing playlists Dec 12 13:26:03 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 12 13:26:03 gbvpi-bedroom volumio[16447]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 12 13:26:03 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:03 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 12 13:26:03 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 12 13:26:03 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 12 13:26:04 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 159. Dec 12 13:26:04 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:04 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:04 gbvpi-bedroom go-librespot[17027]: go-librespot daemon starting... Dec 12 13:26:04 gbvpi-bedroom go-librespot[17028]: time="2025-12-12T13:26:04-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:04 gbvpi-bedroom go-librespot[17028]: time="2025-12-12T13:26:04-05:00" level=debug msg="app state loaded" Dec 12 13:26:04 gbvpi-bedroom go-librespot[17028]: time="2025-12-12T13:26:04-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:04 gbvpi-bedroom go-librespot[17028]: time="2025-12-12T13:26:04-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 12 13:26:04 gbvpi-bedroom go-librespot[17028]: time="2025-12-12T13:26:04-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 12 13:26:04 gbvpi-bedroom go-librespot[17028]: time="2025-12-12T13:26:04-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 12 13:26:04 gbvpi-bedroom go-librespot[17028]: time="2025-12-12T13:26:04-05:00" level=info msg="zeroconf server listening on port 33653" Dec 12 13:26:04 gbvpi-bedroom go-librespot[17028]: time="2025-12-12T13:26:04-05:00" level=debug msg="obtained new client token: AACsfh4Qka+w/VG5OlXcsqVF8qVlnQpT+Cju5h1+o+nlxtzl0Bn7hD/4AdirBOMb+40uQImB08CEZ5p+7qzUY5qrakucfMhvOA9EeYFWfQAmtfCJ2yV7Fbpp32vrjbwt/urHSGEJ8+xESZsJU7kT2sskmUucWcRU26vKRNEmyxsy6kySiIe1UfmZ4W752ThJuoJqXnalSQFKEBtSTHVfQpx+B7fvSyBxsDOQqtdAptYYAsMM+lWXs8XVQw==" Dec 12 13:26:04 gbvpi-bedroom go-librespot[17028]: time="2025-12-12T13:26:04-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:05 gbvpi-bedroom go-librespot[17028]: time="2025-12-12T13:26:05-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:05 gbvpi-bedroom go-librespot[17028]: time="2025-12-12T13:26:05-05:00" level=debug msg="completed challenge" Dec 12 13:26:05 gbvpi-bedroom go-librespot[17028]: time="2025-12-12T13:26:05-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:05 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:05 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:05 gbvpi-bedroom volumio[16447]: info: Initializing connection to go-librespot Websocket Dec 12 13:26:05 gbvpi-bedroom volumio[16447]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:26:07 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 13:26:07 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:07 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 12 13:26:07 gbvpi-bedroom volumio-remote-updater[775]: Test mode enabled Dec 12 13:26:07 gbvpi-bedroom volumio-remote-updater[775]: Alpha mode disabled Dec 12 13:26:07 gbvpi-bedroom volumio-remote-updater[775]: Alpha legacy test mode disabled Dec 12 13:26:07 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 12 13:26:07 gbvpi-bedroom volumio[16447]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

CAUTION

\n
    \n
  • This build may break your network
    • \n
\n

FIX

\n
    \n
  • Wireless and network handling
    • \n
\n","title":"Update v4.080","updateavailable":true} Dec 12 13:26:07 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 12 13:26:08 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:08 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:08 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 12 13:26:08 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 12 13:26:08 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 12 13:26:08 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::volumioGetBrowseSources Dec 12 13:26:08 gbvpi-bedroom volumio[16447]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 13:26:08 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 160. Dec 12 13:26:08 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:08 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:08 gbvpi-bedroom go-librespot[17039]: go-librespot daemon starting... Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=debug msg="app state loaded" Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:08 gbvpi-bedroom volumio[16447]: info: Initializing connection to go-librespot Websocket Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=debug msg="new websocket client" Dec 12 13:26:08 gbvpi-bedroom volumio[16447]: info: Connection to go-librespot Websocket established Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=info msg="zeroconf server listening on port 45187" Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=debug msg="obtained new client token: AAAzHK+RKNeDzQSU+VtmXGF45dPF8o/WraFrUc3+PD1MxoI+p1rpBTdIMurypASiuibt91LZ4Qv+2nG0rvueLOKVHpmKMh8V+p2lf+5nXtVk3HKoKqkgL0Z9V2sID/6Nse2yNzzOeyXILN8Urf9C+NzOyQNYs1Yz9oKH5nEmERS04EONYu+ISwPTQ1qVRxxtUBQ1ovToblGlE/4kNceRi5r4oR/aKek7nKsfNUzOAxBVRbuq1DOJkiUMbQ==" Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=debug msg="completed challenge" Dec 12 13:26:08 gbvpi-bedroom go-librespot[17040]: time="2025-12-12T13:26:08-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:08 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:08 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:08 gbvpi-bedroom volumio[16447]: info: Connection to go-librespot Websocket closed Dec 12 13:26:09 gbvpi-bedroom volumio[16447]: info: BOOT COMPLETED Dec 12 13:26:11 gbvpi-bedroom volumio[16447]: info: Getting Spotify volume Dec 12 13:26:11 gbvpi-bedroom volumio[16447]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 13:26:11 gbvpi-bedroom volumio[16447]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:26:11 gbvpi-bedroom volumio[16447]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 12 13:26:11 gbvpi-bedroom volumio[16447]: errno: -111, Dec 12 13:26:11 gbvpi-bedroom volumio[16447]: code: 'ECONNREFUSED', Dec 12 13:26:11 gbvpi-bedroom volumio[16447]: syscall: 'connect', Dec 12 13:26:11 gbvpi-bedroom volumio[16447]: address: '127.0.0.1', Dec 12 13:26:11 gbvpi-bedroom volumio[16447]: port: 9879, Dec 12 13:26:11 gbvpi-bedroom volumio[16447]: response: undefined Dec 12 13:26:11 gbvpi-bedroom volumio[16447]: } Dec 12 13:26:11 gbvpi-bedroom volumio[16447]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 13:26:11 gbvpi-bedroom sudo[17062]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-12 13:25' Dec 12 13:26:11 gbvpi-bedroom sudo[17062]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:11 gbvpi-bedroom sudo[17062]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:11 gbvpi-bedroom volumio-remote-updater[775]: [2025-12-12 13:26:11] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 12 13:26:11 gbvpi-bedroom volumio-remote-updater[775]: [2025-12-12 13:26:11] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 12 13:26:11 gbvpi-bedroom vtcs[16982]: [2025-12-12 13:26:11.929] [tisoc] [error] [SpkconServer.cpp:375] recv error. socket disconnected Dec 12 13:26:11 gbvpi-bedroom qobuz-connect[16961]: 20251212 13:26:11.931 [16961.16961] INFO SampleApp: Socket closed Dec 12 13:26:11 gbvpi-bedroom systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:11 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 161. Dec 12 13:26:11 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:12 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:12 gbvpi-bedroom go-librespot[17067]: go-librespot daemon starting... Dec 12 13:26:12 gbvpi-bedroom systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 12 13:26:12 gbvpi-bedroom systemd[1]: volumio.service: Consumed 20.346s CPU time. Dec 12 13:26:12 gbvpi-bedroom systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 12 13:26:12 gbvpi-bedroom go-librespot[17069]: time="2025-12-12T13:26:12-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:12 gbvpi-bedroom go-librespot[17069]: time="2025-12-12T13:26:12-05:00" level=debug msg="app state loaded" Dec 12 13:26:12 gbvpi-bedroom go-librespot[17069]: time="2025-12-12T13:26:12-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:12 gbvpi-bedroom systemd[1]: dynamicswap.service: Deactivated successfully. Dec 12 13:26:12 gbvpi-bedroom go-librespot[17069]: time="2025-12-12T13:26:12-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:26:12 gbvpi-bedroom go-librespot[17069]: time="2025-12-12T13:26:12-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:26:12 gbvpi-bedroom go-librespot[17069]: time="2025-12-12T13:26:12-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:26:12 gbvpi-bedroom go-librespot[17069]: time="2025-12-12T13:26:12-05:00" level=info msg="zeroconf server listening on port 38575" Dec 12 13:26:12 gbvpi-bedroom systemd[1]: volumio.service: Scheduled restart job, restart counter is at 3062. Dec 12 13:26:12 gbvpi-bedroom systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 12 13:26:12 gbvpi-bedroom systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 12 13:26:12 gbvpi-bedroom systemd[1]: volumio.service: Consumed 20.346s CPU time. Dec 12 13:26:12 gbvpi-bedroom go-librespot[17069]: time="2025-12-12T13:26:12-05:00" level=debug msg="obtained new client token: AAC7Ze/O/FqXzHqDIlPprwO1Uib7NqK4Pcchauj1AqD31s71SSAEHHCkzINGdisnejM2Xg1ht6RDHiCz3ttlJdMeCuAF11i0uASSMEGbm1C/UnC5cbTcI8o+uItOcuIHCOPhWpG6550Xf7Dk83/qUaBFuU0EwlUN47KHkfS3NVQJnYmjYaH5wzI0thK4LgSuApZ5melPM92F8mxvtacVJInjlL+cBDJyCsT2qnLWKni8kW6vmDkcdDfJIw==" Dec 12 13:26:12 gbvpi-bedroom systemd[1]: Started volumio.service - Volumio Backend Module. Dec 12 13:26:12 gbvpi-bedroom systemd[1]: dynamicswap.service: Deactivated successfully. Dec 12 13:26:12 gbvpi-bedroom go-librespot[17069]: time="2025-12-12T13:26:12-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:12 gbvpi-bedroom go-librespot[17069]: time="2025-12-12T13:26:12-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:12 gbvpi-bedroom go-librespot[17069]: time="2025-12-12T13:26:12-05:00" level=debug msg="completed challenge" Dec 12 13:26:12 gbvpi-bedroom go-librespot[17069]: time="2025-12-12T13:26:12-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:12 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:12 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: ------------------------------------------- Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: ----- Volumio3 ---- Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: ------------------------------------------- Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: ----- System startup ---- Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: ------------------------------------------- Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: MYVOLUMIO Environment detected Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Plugin folders cleanup Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Scanning into folder /volumio/app/plugins/ Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Scanning category audio_interface Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Scanning category miscellanea Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Scanning category music_service Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Scanning category plugins.json Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Scanning category system_controller Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Scanning category user_interface Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Scanning into folder /data/plugins/ Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Scanning category music_service Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Plugin folders cleanup completed Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: ------------------------------------------- Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: ----- Core plugins startup ---- Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: ------------------------------------------- Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Loading plugins from folder /volumio/app/plugins/ Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Adding plugin upnp to MyMusic Plugins Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Loading plugins from folder /data/plugins/ Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Loading plugin "system"... Dec 12 13:26:13 gbvpi-bedroom volumio[17083]: info: Loading plugin "appearance"... Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Loading plugin "network"... Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Refreshing Cached IP Addresses Dec 12 13:26:14 gbvpi-bedroom sudo[17111]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 12 13:26:14 gbvpi-bedroom sudo[17111]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:14 gbvpi-bedroom sudo[17113]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 12 13:26:14 gbvpi-bedroom sudo[17113]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Loading plugin "services"... Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Loading plugin "alsa_controller"... Dec 12 13:26:14 gbvpi-bedroom sudo[17111]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:14 gbvpi-bedroom sudo[17113]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:14 gbvpi-bedroom sudo[17121]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 12 13:26:14 gbvpi-bedroom sudo[17121]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Loading plugin "wizard"... Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Loading plugin "networkfs"... Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Starting Udev Watcher for removable devices Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Ignoring mount for partition: boot Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Ignoring mount for partition: volumio Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Ignoring mount for partition: volumio_data Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Loading plugin "volumio_command_line_client"... Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Loading plugin "upnp"... Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: [1765563974548] Starting Upmpd Daemon Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Loading plugin "my_music"... Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Loading plugin "mpd"... Dec 12 13:26:14 gbvpi-bedroom volumio[17083]: info: Loading plugin "upnp_browser"... Dec 12 13:26:15 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 162. Dec 12 13:26:15 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: Starting UPNP Browser Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: Loading plugin "alarm-clock"... Dec 12 13:26:15 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:15 gbvpi-bedroom go-librespot[17144]: go-librespot daemon starting... Dec 12 13:26:15 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:15-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:15 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:15-05:00" level=debug msg="app state loaded" Dec 12 13:26:15 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:15-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: Loading plugin "airplay_emulation"... Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: Starting Shairport Sync Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: Loading plugin "last_100"... Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: Loading plugin "webradio"... Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: Loading plugin "i2s_dacs"... Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: I2S DAC not set, start Auto-detection Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: Loading plugin "volumiodiscovery"... Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: *** WARNING *** For more information see Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: *** WARNING *** For more information see Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 12 13:26:15 gbvpi-bedroom node[17083]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 12 13:26:15 gbvpi-bedroom node[17083]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 13:26:15 gbvpi-bedroom node[17083]: *** WARNING *** For more information see Dec 12 13:26:15 gbvpi-bedroom node[17083]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 12 13:26:15 gbvpi-bedroom node[17083]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 13:26:15 gbvpi-bedroom node[17083]: *** WARNING *** For more information see Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: Discovery: Started advertising with name: GBVPi-Bedroom Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 12 13:26:15 gbvpi-bedroom volumio[17083]: info: Loading plugin "jellyfin"... Dec 12 13:26:15 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:15-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 12 13:26:15 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:15-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 12 13:26:15 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:15-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 12 13:26:15 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:15-05:00" level=info msg="zeroconf server listening on port 39755" Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Loading plugin "spop"... Dec 12 13:26:16 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:16-05:00" level=debug msg="obtained new client token: AAB/IwC7nfGqT8O0F8bsKpbjNtBA6lhb+DfYnx689QAgXCVFOutiOo9afjhZK9AQAsjEyLdpOFtUuf+Fw09bFH6/l4iEDFLOEm0unDyEONdVQ7jW8Uwck/wrHdudNrWTNpe+5enhsu4pRlSoGaAqDPPff6fZ2NWsRSKPcbZ9zCYKfnIHWyN+pIv8eBaTB1nEGOWo7CB0ndoT5SpAl8F1IxKxnwGnF+I/T2Mtslm9mmlTvAdxzmZfsps=" Dec 12 13:26:16 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:16-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Dec 12 13:26:16 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Loading plugin "outputs"... Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Loading plugin "albumart"... Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Plugin example_plugin is not enabled Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Loading plugin "inputs"... Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Loading plugin "updater_comm"... Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Plugin mpdemulation is not enabled Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Loading plugin "rest_api"... Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Loading plugin "websocket"... Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Starting Socket.io Server version 1.7.4 Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Loading i18n strings for locale en Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: Updating browse sources language Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 13:26:16 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:16-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:16 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:16-05:00" level=debug msg="completed challenge" Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::initPlayerControls Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: Express server listening on port 3000 Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: [Metrics] WebUI: 3s 788.24ms Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::resetVolumioState Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::getcurrentVolume Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioRetrievevolume Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Volumio Network Manager: Network status updated: 2 Dec 12 13:26:16 gbvpi-bedroom volumio-remote-updater[775]: [2025-12-12 13:26:16] [connect] Successful connection Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: VolumeController:: Volume=91 Mute =false Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::pushState Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 13:26:16 gbvpi-bedroom volumio[17154]: Forking 3 albumart workers Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioPushState Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::updateTrackBlock Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrackBlock Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioRetrievevolume Dec 12 13:26:16 gbvpi-bedroom go-librespot[17145]: time="2025-12-12T13:26:16-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:16 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:16 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:16 gbvpi-bedroom volumio[17083]: info: Reloading queue from file Dec 12 13:26:17 gbvpi-bedroom volumio-remote-updater[775]: [2025-12-12 13:26:17] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765563976 101 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::setRepeat true single undefined Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::pushState Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioPushState Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::setRandom null Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::pushState Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioPushState Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Setting Device type: Raspberry PI Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: VolumeController:: Volume=91 Mute =false Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::pushState Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioPushState Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Completed loading Core Plugins Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Preparing to generate the ALSA configuration file Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Discovery: adding 74ce6260-2045-48bb-acbd-0b75ccb5d93e Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Discovery: Found device GBVPi-Bedroom Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Asound.conf file written Dec 12 13:26:17 gbvpi-bedroom sudo[17211]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 12 13:26:17 gbvpi-bedroom sudo[17211]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:17 gbvpi-bedroom sudo[17211]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Output device has changed, restarting MPD Dec 12 13:26:17 gbvpi-bedroom sudo[17217]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 12 13:26:17 gbvpi-bedroom sudo[17217]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Output device has changed, restarting Shairport Sync Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:17 gbvpi-bedroom sudo[17217]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:17 gbvpi-bedroom sudo[17219]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 12 13:26:17 gbvpi-bedroom sudo[17219]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: ___________ START PLUGINS ___________ Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: ControllerMpd::onStart: Initializing MPD Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Creating MPD Configuration file Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 12 13:26:17 gbvpi-bedroom systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: [1765563977346] CoreMusicLibrary::Adding element Media Servers Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 13:26:17 gbvpi-bedroom sudo[17228]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 12 13:26:17 gbvpi-bedroom sudo[17228]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:17 gbvpi-bedroom sudo[17228]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:17 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 12 13:26:17 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 12 13:26:17 gbvpi-bedroom systemd[1]: mpd.service: Consumed 1.275s CPU time. Dec 12 13:26:17 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 12 13:26:17 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 12 13:26:17 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: UPNP Browser: Client initialized successfully Dec 12 13:26:17 gbvpi-bedroom sudo[17229]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 12 13:26:17 gbvpi-bedroom sudo[17229]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:17 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 12 13:26:17 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:17 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 12 13:26:17 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 12 13:26:17 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 12 13:26:17 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 12 13:26:17 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 12 13:26:17 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 12 13:26:17 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: [1765563977545] CoreMusicLibrary::Adding element Last_100 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: [1765563977551] CoreMusicLibrary::Adding element Webradio Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Initializing BBC Radios Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:17 gbvpi-bedroom sudo[17241]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 12 13:26:17 gbvpi-bedroom sudo[17241]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Discovery: Getting this device information Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 12 13:26:17 gbvpi-bedroom sudo[17241]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: [1765563977674] CoreMusicLibrary::Adding element Jellyfin Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: Cannot find translation for source Jellyfin Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: [jellyfin] Initialized plugin with device info: {"host":"http://192.168.1.97","id":"74ce6260-2045-48bb-acbd-0b75ccb5d93e","name":"GBVPi-Bedroom","serviceName":"Volumio","state":{"albumart":"http://cdn-profiles.tunein.com/s28808/images/logoq.jpg?t=1","mute":false,"status":"stop","track":"WFMU","volume":91},"type":"device"} Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Creating Spotify config file Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:17 gbvpi-bedroom volumio[17173]: Starting albumart workers Dec 12 13:26:17 gbvpi-bedroom volumio[17177]: Starting albumart workers Dec 12 13:26:17 gbvpi-bedroom volumio[17083]: info: Volumio Calling Home Dec 12 13:26:18 gbvpi-bedroom volumio[17171]: Starting albumart workers Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: Discovery: this is already registered, 74ce6260-2045-48bb-acbd-0b75ccb5d93e Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: Discovery: Found device GBVPi-Bedroom Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: MPD Permissions set Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: MPD Permissions set Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: Spotify config file written Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom sudo[17263]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 12 13:26:18 gbvpi-bedroom sudo[17263]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: No need to fix Spotify hosts Dec 12 13:26:18 gbvpi-bedroom go-librespot[17275]: go-librespot daemon starting... Dec 12 13:26:18 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:18 gbvpi-bedroom sudo[17263]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:18 gbvpi-bedroom go-librespot[17276]: time="2025-12-12T13:26:18-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:18 gbvpi-bedroom go-librespot[17276]: time="2025-12-12T13:26:18-05:00" level=debug msg="app state loaded" Dec 12 13:26:18 gbvpi-bedroom go-librespot[17276]: time="2025-12-12T13:26:18-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: Volumio called home Dec 12 13:26:18 gbvpi-bedroom sudo[17121]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: Starting Shairport Sync Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: Starting Shairport Sync Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: Starting Shairport Sync Dec 12 13:26:18 gbvpi-bedroom sudo[17283]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 13:26:18 gbvpi-bedroom sudo[17283]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:18 gbvpi-bedroom sudo[17285]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 13:26:18 gbvpi-bedroom sudo[17285]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:18 gbvpi-bedroom volumio[17083]: info: [jellyfin-poller] Polled HTTPS://jellyfin.lukeaurio.net: online Dec 12 13:26:18 gbvpi-bedroom sudo[17288]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 13:26:18 gbvpi-bedroom sudo[17288]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:18 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 12 13:26:18 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 12 13:26:18 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 13:26:18 gbvpi-bedroom systemd[1]: shairport-sync.service: Consumed 1.652s CPU time. Dec 12 13:26:18 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 13:26:18 gbvpi-bedroom sudo[17288]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:18 gbvpi-bedroom sudo[17283]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:18 gbvpi-bedroom sudo[17285]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:18 gbvpi-bedroom go-librespot[17276]: time="2025-12-12T13:26:18-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:26:18 gbvpi-bedroom go-librespot[17276]: time="2025-12-12T13:26:18-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:26:18 gbvpi-bedroom go-librespot[17276]: time="2025-12-12T13:26:18-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:26:18 gbvpi-bedroom go-librespot[17276]: time="2025-12-12T13:26:18-05:00" level=info msg="zeroconf server listening on port 33987" Dec 12 13:26:18 gbvpi-bedroom go-librespot[17276]: time="2025-12-12T13:26:18-05:00" level=debug msg="obtained new client token: AABzC7vyAG9QSK7haFHe20N6nwE3/yfdktyrxEwBmr2VZw6nyO4mMFe5xnUxFr6CzmWZQ5b7acJ0ZNt/15XYqL1X78iOhykGfeMC4UbF3pywK5lfUkvlClIri0NkdfW57KGmNGE1ZOzwRouVRvisA+1nCqI0gbxv2IWN4uqf00aQS1zpjIQiQEB2c1jnD+794jI7gmlpYpQRiTqyBgblkmcNDgB/62vOmrK8YyCvKApRzD+Awpo4rLKKaQ==" Dec 12 13:26:18 gbvpi-bedroom go-librespot[17276]: time="2025-12-12T13:26:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: info: Shairport-Sync Started Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: Error adding Membership: Error: addMembership EINVAL Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: info: Shairport-Sync Started Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: info: Shairport-Sync Started Dec 12 13:26:19 gbvpi-bedroom go-librespot[17276]: time="2025-12-12T13:26:19-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:19 gbvpi-bedroom go-librespot[17276]: time="2025-12-12T13:26:19-05:00" level=debug msg="completed challenge" Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:19 gbvpi-bedroom go-librespot[17276]: time="2025-12-12T13:26:19-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:19 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:19 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:19 gbvpi-bedroom mpd[17258]: 2025-12-12T13:26:19 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 12 13:26:19 gbvpi-bedroom systemd[1]: Started mpd.service - Music Player Daemon. Dec 12 13:26:19 gbvpi-bedroom sudo[17219]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:19 gbvpi-bedroom sudo[17229]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: info: Completed starting Core Plugins Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: info: ------------------------------------------- Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: info: ----- MyVolumio plugins startup ---- Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: info: ------------------------------------------- Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: error: MPD error: The expression evaluated to a falsy value: Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: assert.ok(self.idling) Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: error: The expression evaluated to a falsy value: Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: assert.ok(self.idling) Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: error: updateQueue error: null Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: info: MPD running with PID17258 Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: ,establishing connection Dec 12 13:26:19 gbvpi-bedroom volumio[17083]: error: updateQueue error: null Dec 12 13:26:21 gbvpi-bedroom volumio[17083]: info: go-librespot daemon successfully initialized Dec 12 13:26:22 gbvpi-bedroom volumio[17083]: info: Discovery: Browse raised the following error Error: dns service error: unknown Dec 12 13:26:22 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 163. Dec 12 13:26:22 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:22 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:22 gbvpi-bedroom go-librespot[17335]: go-librespot daemon starting... Dec 12 13:26:22 gbvpi-bedroom go-librespot[17336]: time="2025-12-12T13:26:22-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:22 gbvpi-bedroom go-librespot[17336]: time="2025-12-12T13:26:22-05:00" level=debug msg="app state loaded" Dec 12 13:26:22 gbvpi-bedroom go-librespot[17336]: time="2025-12-12T13:26:22-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:22 gbvpi-bedroom go-librespot[17336]: time="2025-12-12T13:26:22-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:26:22 gbvpi-bedroom go-librespot[17336]: time="2025-12-12T13:26:22-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:26:22 gbvpi-bedroom go-librespot[17336]: time="2025-12-12T13:26:22-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:26:22 gbvpi-bedroom go-librespot[17336]: time="2025-12-12T13:26:22-05:00" level=info msg="zeroconf server listening on port 45993" Dec 12 13:26:22 gbvpi-bedroom go-librespot[17336]: time="2025-12-12T13:26:22-05:00" level=debug msg="obtained new client token: AADP5sYB7n55wQ3NLeM4eNzO5aAPunPtlKx/UBIP4TUGbskvUUNEY6vkKqSp5cDGwurWIDGAEIgf5PKdTTmeykr4YaIJgK6f/2gyDK9CcxPKdWvrBPqRYIsyykadk0lIoj1r0OsPbi+1v8LxZXsWBNWqmMKGvswnIgX+RMMqQKenpkEDEVFJmPMGYP2ZPH5sURFJeKrYggOHHTUSECiM58lDsLtQAfdtfnayVDbwMYtK7zRyUfOe0yva+A==" Dec 12 13:26:22 gbvpi-bedroom go-librespot[17336]: time="2025-12-12T13:26:22-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:22 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:22 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:22 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:22 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:22 gbvpi-bedroom volumio[17083]: info: Listing playlists Dec 12 13:26:22 gbvpi-bedroom volumio[17083]: info: Listing playlists Dec 12 13:26:22 gbvpi-bedroom volumio[17083]: info: Listing playlists Dec 12 13:26:22 gbvpi-bedroom volumio[17083]: info: Listing playlists Dec 12 13:26:22 gbvpi-bedroom sudo[17344]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 12 13:26:22 gbvpi-bedroom sudo[17344]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:22 gbvpi-bedroom sudo[17346]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 12 13:26:22 gbvpi-bedroom sudo[17346]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:22 gbvpi-bedroom go-librespot[17336]: time="2025-12-12T13:26:22-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:22 gbvpi-bedroom go-librespot[17336]: time="2025-12-12T13:26:22-05:00" level=debug msg="completed challenge" Dec 12 13:26:22 gbvpi-bedroom systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 12 13:26:22 gbvpi-bedroom systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 12 13:26:22 gbvpi-bedroom systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 12 13:26:22 gbvpi-bedroom go-librespot[17336]: time="2025-12-12T13:26:22-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:22 gbvpi-bedroom systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 12 13:26:22 gbvpi-bedroom sudo[17344]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:22 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:22 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:22 gbvpi-bedroom mpd_monitor.sh[17349]: MPD Monitor Service: Starting MPD Monitor Service Dec 12 13:26:22 gbvpi-bedroom sudo[17346]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:22 gbvpi-bedroom volumio[17083]: info: Successfully started MPD Monitor Dec 12 13:26:22 gbvpi-bedroom volumio[17083]: info: Successfully started MPD Monitor Dec 12 13:26:24 gbvpi-bedroom volumio[17083]: info: Initializing connection to go-librespot Websocket Dec 12 13:26:24 gbvpi-bedroom volumio[17083]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:26:24 gbvpi-bedroom sudo[17369]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 12 13:26:24 gbvpi-bedroom sudo[17369]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:24 gbvpi-bedroom sudo[17369]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:24 gbvpi-bedroom sudo[17371]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 12 13:26:24 gbvpi-bedroom sudo[17371]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:24 gbvpi-bedroom sudo[17371]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:24 gbvpi-bedroom sudo[17374]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 12 13:26:24 gbvpi-bedroom sudo[17374]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:24 gbvpi-bedroom sudo[17374]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:24 gbvpi-bedroom volumio[17083]: info: Upmpdcli Daemon Started Dec 12 13:26:24 gbvpi-bedroom volumio[17083]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 12 13:26:25 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 164. Dec 12 13:26:25 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:26 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:26 gbvpi-bedroom go-librespot[17377]: go-librespot daemon starting... Dec 12 13:26:26 gbvpi-bedroom go-librespot[17378]: time="2025-12-12T13:26:26-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:26 gbvpi-bedroom go-librespot[17378]: time="2025-12-12T13:26:26-05:00" level=debug msg="app state loaded" Dec 12 13:26:26 gbvpi-bedroom go-librespot[17378]: time="2025-12-12T13:26:26-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:26 gbvpi-bedroom go-librespot[17378]: time="2025-12-12T13:26:26-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:26:26 gbvpi-bedroom go-librespot[17378]: time="2025-12-12T13:26:26-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:26:26 gbvpi-bedroom go-librespot[17378]: time="2025-12-12T13:26:26-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:26:26 gbvpi-bedroom go-librespot[17378]: time="2025-12-12T13:26:26-05:00" level=info msg="zeroconf server listening on port 40681" Dec 12 13:26:26 gbvpi-bedroom go-librespot[17378]: time="2025-12-12T13:26:26-05:00" level=debug msg="obtained new client token: AABtGA6D7zsIdYe7Y9ypouOEWPaATbWOZ12Tp+npwmfMUEUbKu8UlRwxT29FniMX4x/zsFCwBUTW1jOhUB1hNps0tVtQsGfPUSSyCkXC13N2AISRa2dDQZjOfRwsWF43h2qAp9/h4T6mf3KBCITokbcanEhWWfX50x7r/GbW3+SzdwnBcjkX3qH7MOLIpNwAb2vvS2LOoZlF040VVZHnnRucjg7HnpYDHx11nIXGzC4lenr5tBklnTSRpA==" Dec 12 13:26:26 gbvpi-bedroom go-librespot[17378]: time="2025-12-12T13:26:26-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:26 gbvpi-bedroom go-librespot[17378]: time="2025-12-12T13:26:26-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:26 gbvpi-bedroom go-librespot[17378]: time="2025-12-12T13:26:26-05:00" level=debug msg="completed challenge" Dec 12 13:26:26 gbvpi-bedroom go-librespot[17378]: time="2025-12-12T13:26:26-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:26 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:26 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: Initializing connection to go-librespot Websocket Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: Adding plugin bluetooth to MyMusic Plugins Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: Adding plugin multiroom to MyMusic Plugins Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: Adding plugin metavolumio to MyMusic Plugins Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: Adding plugin cd_controller to MyMusic Plugins Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 12 13:26:27 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: Starting MyVolumio Remote Streaming Endpoints Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: MyVolumio login type: Token Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: Streaming services startup Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: Starting Streaming Daemon Dec 12 13:26:28 gbvpi-bedroom sudo[17386]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 12 13:26:28 gbvpi-bedroom sudo[17386]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:28 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 12 13:26:28 gbvpi-bedroom sudo[17386]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: error: Cannot start Volumio Streaming Daemon Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 12 13:26:29 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 165. Dec 12 13:26:29 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:29 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:29 gbvpi-bedroom go-librespot[17393]: go-librespot daemon starting... Dec 12 13:26:29 gbvpi-bedroom go-librespot[17394]: time="2025-12-12T13:26:29-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:29 gbvpi-bedroom go-librespot[17394]: time="2025-12-12T13:26:29-05:00" level=debug msg="app state loaded" Dec 12 13:26:29 gbvpi-bedroom go-librespot[17394]: time="2025-12-12T13:26:29-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: info: MyVolumio token set successfully Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: info: MYVOLUMIO: Adding device Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: info: MYVOLUMIO: Evaluating Server Dec 12 13:26:29 gbvpi-bedroom go-librespot[17394]: time="2025-12-12T13:26:29-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:26:29 gbvpi-bedroom go-librespot[17394]: time="2025-12-12T13:26:29-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:26:29 gbvpi-bedroom go-librespot[17394]: time="2025-12-12T13:26:29-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:26:29 gbvpi-bedroom go-librespot[17394]: time="2025-12-12T13:26:29-05:00" level=info msg="zeroconf server listening on port 45559" Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: info: MyVolumio Plan changed: premium Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: info: Removing browser output: myVolumio user plan is not superstar Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: info: Removing audio output: Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: info: MYVOLUMIO: Adding device Dec 12 13:26:29 gbvpi-bedroom volumio[17083]: info: MYVOLUMIO: Evaluating Server Dec 12 13:26:30 gbvpi-bedroom go-librespot[17394]: time="2025-12-12T13:26:30-05:00" level=debug msg="obtained new client token: AABh5BpnNSskhOosaBsAqGF3YEeMta8cRgX+4C2PTbPtXS28kIooGSP6ZpV+1ZIAaDsG8rYed1FS2FjrMYiYmkfYLMkxx5Y+1mRDN9VYDFGVlVCd2D0BtfoSlgYqyrYNgRa1QlibSE6ompcUYuQ4xrfrMaJAJAAPBhyStKqK+s8oxrCmIB4+sa3f2IeXfRBiFd2TNp90wY+7coh1vx3aANrxbQR7Jm6DGDS5Ahp8W8wPAoNQv8FD7dU=" Dec 12 13:26:30 gbvpi-bedroom go-librespot[17394]: time="2025-12-12T13:26:30-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: Remote config written successfully Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: Starting Tunnel 1 Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: Starting Tunnel Connection Checker Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: Completed starting MyVolumio Plugin Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: MYVolumio Device enabled Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: MyVolumio status changed Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: Streaming services startup Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: Starting Streaming Daemon Dec 12 13:26:30 gbvpi-bedroom sudo[17440]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 12 13:26:30 gbvpi-bedroom sudo[17440]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: Setting Geolocation for MyVolumio to us1 Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:30 gbvpi-bedroom sudo[17440]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: error: Cannot start Volumio Streaming Daemon Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Dec 12 13:26:30 gbvpi-bedroom go-librespot[17394]: time="2025-12-12T13:26:30-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:30 gbvpi-bedroom go-librespot[17394]: time="2025-12-12T13:26:30-05:00" level=debug msg="completed challenge" Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Dec 12 13:26:30 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Dec 12 13:26:30 gbvpi-bedroom go-librespot[17394]: time="2025-12-12T13:26:30-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:30 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:30 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Dec 12 13:26:31 gbvpi-bedroom sudo[17445]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Dec 12 13:26:31 gbvpi-bedroom sudo[17445]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:31 gbvpi-bedroom sudo[17445]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: /usr/bin/mkdir: cannot create directory ‘/tmp/hls’: File exists Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: MRS: MultiRoom plugin initialized Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: MRS: STOPPING SNAPCLIENT Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: MRS: Snap server stop Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: MRS: STOPPING volumioStreaming Dec 12 13:26:31 gbvpi-bedroom sudo[17462]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Dec 12 13:26:31 gbvpi-bedroom sudo[17462]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:31 gbvpi-bedroom sudo[17464]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Dec 12 13:26:31 gbvpi-bedroom sudo[17464]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Dec 12 13:26:31 gbvpi-bedroom sudo[17466]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Dec 12 13:26:31 gbvpi-bedroom sudo[17466]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:31 gbvpi-bedroom sudo[17470]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Dec 12 13:26:31 gbvpi-bedroom sudo[17470]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:31 gbvpi-bedroom sudo[17470]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Dec 12 13:26:31 gbvpi-bedroom sudo[17462]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Dec 12 13:26:31 gbvpi-bedroom sudo[17464]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:31 gbvpi-bedroom sudo[17466]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Preparing to generate the ALSA configuration file Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Initializing connection to go-librespot Websocket Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Updating MyVolumio device info Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Setting Geolocation for MyVolumio to us4 Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Successfully Added MyVolumio device Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Reading ALSA contributions from plugins. Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: MRS: Removed streaming files Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: MRS: volumioStreaming STOPPED Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: MRS: SNAPSERVER STOPPED Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: MRS: SNAPCLIENT STOPPED Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Asound.conf file written Dec 12 13:26:31 gbvpi-bedroom sudo[17475]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 12 13:26:31 gbvpi-bedroom sudo[17475]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:31 gbvpi-bedroom sudo[17475]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Output device has changed, restarting MPD Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Output device has changed, restarting Shairport Sync Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:31 gbvpi-bedroom sudo[17481]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 12 13:26:31 gbvpi-bedroom sudo[17481]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:31 gbvpi-bedroom sudo[17481]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:31 gbvpi-bedroom sudo[17483]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 12 13:26:31 gbvpi-bedroom sudo[17483]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: ------------------------------------ BT MESSAGE: [FUNC] onStart Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Dec 12 13:26:31 gbvpi-bedroom systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: MRS: Pushing multiroomSync output for this device Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: MRS: Pushing multiroomSync output Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Adding audio output: Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Adding audio output: Dec 12 13:26:31 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 12 13:26:31 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 12 13:26:31 gbvpi-bedroom systemd[1]: mpd.service: Consumed 1.884s CPU time. Dec 12 13:26:31 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 12 13:26:31 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 12 13:26:31 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Dec 12 13:26:31 gbvpi-bedroom bluetoothd[763]: Path / reserved for Adv Monitor app :1.46393 Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Adding METAVOLUMIO REST API Endpoints Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Preparing CD Folders Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Adding CD REST API Endpoints Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Starting UDEV Watcher for CD Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: Detecting CD presence with UDEV Dec 12 13:26:31 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Dec 12 13:26:31 gbvpi-bedroom bluetoothd[763]: Adv Monitor app :1.46393 disconnected from D-Bus Dec 12 13:26:31 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 12 13:26:31 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 12 13:26:31 gbvpi-bedroom sudo[17502]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 12 13:26:31 gbvpi-bedroom sudo[17502]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 12 13:26:31 gbvpi-bedroom sudo[17502]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:33 gbvpi-bedroom mpd[17504]: 2025-12-12T13:26:33 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 12 13:26:33 gbvpi-bedroom systemd[1]: Started mpd.service - Music Player Daemon. Dec 12 13:26:33 gbvpi-bedroom sudo[17483]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:33 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 166. Dec 12 13:26:33 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:33 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:33 gbvpi-bedroom go-librespot[17507]: go-librespot daemon starting... Dec 12 13:26:33 gbvpi-bedroom go-librespot[17508]: time="2025-12-12T13:26:33-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:33 gbvpi-bedroom go-librespot[17508]: time="2025-12-12T13:26:33-05:00" level=debug msg="app state loaded" Dec 12 13:26:33 gbvpi-bedroom go-librespot[17508]: time="2025-12-12T13:26:33-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:33 gbvpi-bedroom go-librespot[17508]: time="2025-12-12T13:26:33-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 12 13:26:33 gbvpi-bedroom go-librespot[17508]: time="2025-12-12T13:26:33-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 12 13:26:33 gbvpi-bedroom go-librespot[17508]: time="2025-12-12T13:26:33-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 12 13:26:33 gbvpi-bedroom go-librespot[17508]: time="2025-12-12T13:26:33-05:00" level=info msg="zeroconf server listening on port 36125" Dec 12 13:26:34 gbvpi-bedroom go-librespot[17508]: time="2025-12-12T13:26:34-05:00" level=debug msg="obtained new client token: AADbTf1hg4+bpUbSK/A8SXulr9grT8lWOKjHVNLKOWvgte48UF6RQ6kDekVBVj1SiCmV915KX7muZZX6CVqmduyio3NiHpnEylTD5mrvZZW72xysO1eymwAoqa4d1ZmEJ309gD9cd/FLlXZRUsGUHK8Phrai1QFBtnJ8lYmF8BeTheNL6gogSjHqbUzj4+tFvEpB2vS5EVCBFAFjZ7Jzyx9w1CZoNjd40iv3X3qjVgotuv3AnOBFZI4=" Dec 12 13:26:34 gbvpi-bedroom go-librespot[17508]: time="2025-12-12T13:26:34-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:34 gbvpi-bedroom go-librespot[17508]: time="2025-12-12T13:26:34-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:34 gbvpi-bedroom go-librespot[17508]: time="2025-12-12T13:26:34-05:00" level=debug msg="completed challenge" Dec 12 13:26:34 gbvpi-bedroom go-librespot[17508]: time="2025-12-12T13:26:34-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:34 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:34 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: warn: [cd-plugin] cdspeedctl: device or media not ready Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Adding inputs REST Endpoints Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Scanning Audio Inputs Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Checking against Known Cards name Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Adding Server instance for streaming Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: error: Hi Res Audio Failed Login: Missing Login Data Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Adding HIGHRESAUDIO REST API Endpoints Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Dec 12 13:26:36 gbvpi-bedroom sudo[17533]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: QobuzConnect: Starting Qobuz Connect socket and service Dec 12 13:26:36 gbvpi-bedroom sudo[17533]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:36 gbvpi-bedroom sudo[17540]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Dec 12 13:26:36 gbvpi-bedroom sudo[17540]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Dec 12 13:26:36 gbvpi-bedroom systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Dec 12 13:26:36 gbvpi-bedroom systemd[1]: vtcs.service: Killing process 17001 (vtcs) with signal SIGKILL. Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Adding TIDAL REST API Endpoints Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Stopping AccessToken refresher cron for QOBUZ Dec 12 13:26:36 gbvpi-bedroom systemd[1]: vtcs.service: Deactivated successfully. Dec 12 13:26:36 gbvpi-bedroom systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Dec 12 13:26:36 gbvpi-bedroom sudo[17533]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: AccessToken refresher cron started for QOBUZ Dec 12 13:26:36 gbvpi-bedroom sudo[17540]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Adding QOBUZ REST API Endpoints Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Updating MyVolumio device info Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: MRS: Getting audio outputs on start Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: MRS: Requesting all other devices output Dec 12 13:26:36 gbvpi-bedroom sudo[17543]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Dec 12 13:26:36 gbvpi-bedroom sudo[17543]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Initializing connection to go-librespot Websocket Dec 12 13:26:36 gbvpi-bedroom systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Dec 12 13:26:36 gbvpi-bedroom qobuz-connect[16961]: 20251212 13:26:36.950 [16961.16961] INFO SampleApp: Stopping Local configuration server Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Successfully Updated MyVolumio device Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: Successfully Added MyVolumio device Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Dec 12 13:26:36 gbvpi-bedroom volumio[17083]: info: MPD Permissions set Dec 12 13:26:36 gbvpi-bedroom sudo[17547]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Dec 12 13:26:36 gbvpi-bedroom sudo[17547]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:37 gbvpi-bedroom sudo[17547]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: error: updateQueue error: null Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioStop Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::stop Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: Starting Shairport Sync Dec 12 13:26:37 gbvpi-bedroom sudo[17562]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Dec 12 13:26:37 gbvpi-bedroom sudo[17562]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:37 gbvpi-bedroom sudo[17564]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 13:26:37 gbvpi-bedroom sudo[17564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:37 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 12 13:26:37 gbvpi-bedroom autossh[16934]: received signal to exit (15) Dec 12 13:26:37 gbvpi-bedroom systemd[1]: Stopping sshtunnel.service - MyVolumio SSH Tunnel... Dec 12 13:26:37 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 12 13:26:37 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 13:26:37 gbvpi-bedroom systemd[1]: shairport-sync.service: Consumed 1.567s CPU time. Dec 12 13:26:37 gbvpi-bedroom systemd[1]: sshtunnel.service: Deactivated successfully. Dec 12 13:26:37 gbvpi-bedroom systemd[1]: Stopped sshtunnel.service - MyVolumio SSH Tunnel. Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: MRS: Found cast device: Google-Home-Mini-f209fa314cb426d40a59bcf66354ddc9 Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: Adding audio output: Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: MRS: Found cast device: SmartTV-4K-fe72c264393a59c76d38e27b8168114d Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: Adding audio output: Dec 12 13:26:37 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 13:26:37 gbvpi-bedroom sudo[17564]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:37 gbvpi-bedroom systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Dec 12 13:26:37 gbvpi-bedroom sudo[17562]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:37 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 167. Dec 12 13:26:37 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:37 gbvpi-bedroom autossh[17569]: port set to 0, monitoring disabled Dec 12 13:26:37 gbvpi-bedroom autossh[17569]: starting ssh (count 1) Dec 12 13:26:37 gbvpi-bedroom autossh[17569]: ssh child pid is 17572 Dec 12 13:26:37 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: Remote SSH Started Dec 12 13:26:37 gbvpi-bedroom go-librespot[17573]: go-librespot daemon starting... Dec 12 13:26:37 gbvpi-bedroom go-librespot[17574]: time="2025-12-12T13:26:37-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:37 gbvpi-bedroom go-librespot[17574]: time="2025-12-12T13:26:37-05:00" level=debug msg="app state loaded" Dec 12 13:26:37 gbvpi-bedroom go-librespot[17574]: time="2025-12-12T13:26:37-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:37 gbvpi-bedroom systemd[1]: qobuz-connect.service: Deactivated successfully. Dec 12 13:26:37 gbvpi-bedroom systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: Shairport-Sync Started Dec 12 13:26:37 gbvpi-bedroom volumiossh-tunnel[17572]: Warning: Permanently added '[us4.myvolumio.org]:2222' (ED25519) to the list of known hosts. Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 12 13:26:37 gbvpi-bedroom systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Dec 12 13:26:37 gbvpi-bedroom sudo[17543]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: Executing endpoint qc_getconfig Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Dec 12 13:26:37 gbvpi-bedroom go-librespot[17574]: time="2025-12-12T13:26:37-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:26:37 gbvpi-bedroom go-librespot[17574]: time="2025-12-12T13:26:37-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:26:37 gbvpi-bedroom go-librespot[17574]: time="2025-12-12T13:26:37-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:26:37 gbvpi-bedroom go-librespot[17574]: time="2025-12-12T13:26:37-05:00" level=info msg="zeroconf server listening on port 33885" Dec 12 13:26:37 gbvpi-bedroom qobuz-connect[17594]: 20251212 13:26:37.563 [17594.17594] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Dec 12 13:26:37 gbvpi-bedroom qobuz-connect[17594]: 20251212 13:26:37.567 [17594.17594] INFO VolumeManager: [0x2af588]: Setting new playback volume: 75 Dec 12 13:26:37 gbvpi-bedroom qobuz-connect[17594]: 20251212 13:26:37.567 [17594.17594] INFO VolumeManager: [0x2af588]: Setting new mute state: 0 Dec 12 13:26:37 gbvpi-bedroom qobuz-connect[17594]: 20251212 13:26:37.567 [17594.17594] INFO QobuzConnect: [0x2aff58]: Client initialized! Dec 12 13:26:37 gbvpi-bedroom qobuz-connect[17594]: 20251212 13:26:37.567 [17594.17594] INFO SampleApp: Starting Avahi advertising, name: GBVPi-Bedroom, service name: _qobuz-connect._tcp Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: QobuzConnect: QOBUZ Connect daemon connected Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:37 gbvpi-bedroom qobuz-connect[17594]: 20251212 13:26:37.583 [17594.17594] INFO LocalConfigManager: [0x2aee68]: Starting Local Configuration server Dec 12 13:26:37 gbvpi-bedroom qobuz-connect[17594]: 20251212 13:26:37.584 [17594.17594] INFO SampleApp: Starting Local configuration server Dec 12 13:26:37 gbvpi-bedroom qobuz-connect[17594]: 20251212 13:26:37.584 [17594.17594] INFO SampleApp: Connected to UNIX socket client 0x299818 Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.KgLfU6XUUlR7svHZAvNpgZIq9af1.66712a116082b2e6ca4ffe3109a843e6.state.status' Dec 12 13:26:37 gbvpi-bedroom qobuz-connect[17594]: 20251212 13:26:37.713 [17594.17594] INFO SampleApp: Playback volume changed: 75 Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:37 gbvpi-bedroom go-librespot[17574]: time="2025-12-12T13:26:37-05:00" level=debug msg="obtained new client token: AACATcKVmb/8BMuD/4mlT3L3TWKX32T5HxmF35PUPIbEH1HZ7m3uyiNDPj788D1Zybd4GepB2P5+7R18Vce28gx+az20p8LHoSSFv9Uu1duCqPokWEctS2AsXgemv3/xTnbgl9vbb3kwx/9ovK9X1QtuXhpC2xejE6civpYRm35fVp8exIAjg+jNGvvtkufljiQ3ute+UtPJu4B9sHsxczgjciOCVOBcbJWxP17d+phVmfAD4VUMyUhSbw==" Dec 12 13:26:37 gbvpi-bedroom go-librespot[17574]: time="2025-12-12T13:26:37-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:37 gbvpi-bedroom volumio[17083]: info: Successfully Updated MyVolumio device Dec 12 13:26:37 gbvpi-bedroom go-librespot[17574]: time="2025-12-12T13:26:37-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:37 gbvpi-bedroom go-librespot[17574]: time="2025-12-12T13:26:37-05:00" level=debug msg="completed challenge" Dec 12 13:26:37 gbvpi-bedroom go-librespot[17574]: time="2025-12-12T13:26:37-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:37 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:37 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:39 gbvpi-bedroom volumio[17083]: info: TidalConnect service stoped! Dec 12 13:26:39 gbvpi-bedroom volumio[17083]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Dec 12 13:26:39 gbvpi-bedroom volumio[17083]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Dec 12 13:26:39 gbvpi-bedroom sudo[17610]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Dec 12 13:26:39 gbvpi-bedroom sudo[17610]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:40 gbvpi-bedroom systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Dec 12 13:26:40 gbvpi-bedroom sudo[17614]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 12 13:26:40 gbvpi-bedroom sudo[17614]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:40 gbvpi-bedroom sudo[17610]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: Initializing connection to go-librespot Websocket Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:26:40 gbvpi-bedroom systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 12 13:26:40 gbvpi-bedroom systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 12 13:26:40 gbvpi-bedroom systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 12 13:26:40 gbvpi-bedroom systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 12 13:26:40 gbvpi-bedroom sudo[17614]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:40 gbvpi-bedroom mpd_monitor.sh[17618]: MPD Monitor Service: Starting MPD Monitor Service Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: Successfully started MPD Monitor Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: Executing endpoint tc_getconfig Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Dec 12 13:26:40 gbvpi-bedroom vtcs[17615]: STARTING TidalConnect services, version: 1.5.2.56 Dec 12 13:26:40 gbvpi-bedroom vtcs[17615]: STARTED TidalConnect services. Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: Executing endpoint tc_connect Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: Connecting to TidalConnect Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::servicePushState Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::pushState Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioPushState Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: MRS: Pushing multiroomSync output update for this device Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: MRS: Pushing multiroomSync output Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received tidalconnect Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::servicePushState Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CoreStateMachine::pushState Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioPushState Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: MRS: Pushing multiroomSync output update for this device Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: MRS: Pushing multiroomSync output Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received tidalconnect Dec 12 13:26:40 gbvpi-bedroom volumio[17083]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.KgLfU6XUUlR7svHZAvNpgZIq9af1.66712a116082b2e6ca4ffe3109a843e6.state.status' Dec 12 13:26:40 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 168. Dec 12 13:26:40 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:41 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:41 gbvpi-bedroom go-librespot[17636]: go-librespot daemon starting... Dec 12 13:26:41 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:41-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:41 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:41-05:00" level=debug msg="app state loaded" Dec 12 13:26:41 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:41-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:41 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:41-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 12 13:26:41 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:41-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 12 13:26:41 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:41-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 12 13:26:41 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:41-05:00" level=info msg="zeroconf server listening on port 43029" Dec 12 13:26:42 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:42 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:42 gbvpi-bedroom volumio[17083]: info: Listing playlists Dec 12 13:26:42 gbvpi-bedroom volumio[17083]: info: Listing playlists Dec 12 13:26:42 gbvpi-bedroom volumio[17083]: info: Listing playlists Dec 12 13:26:42 gbvpi-bedroom volumio[17083]: info: Listing playlists Dec 12 13:26:43 gbvpi-bedroom volumio[17083]: info: TidalConnect service started! Dec 12 13:26:43 gbvpi-bedroom volumio[17083]: [Metrics] CommandRouter: 29s 673.45ms Dec 12 13:26:43 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumiosetStartupVolume Dec 12 13:26:43 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:43 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:43 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::Close All Modals sent Dec 12 13:26:43 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::Close All Modals sent Dec 12 13:26:43 gbvpi-bedroom volumio[17083]: info: Initializing connection to go-librespot Websocket Dec 12 13:26:43 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:43-05:00" level=debug msg="new websocket client" Dec 12 13:26:43 gbvpi-bedroom volumio[17083]: info: Connection to go-librespot Websocket established Dec 12 13:26:43 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 12 13:26:43 gbvpi-bedroom volumio[17083]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 12 13:26:43 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:44 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 12 13:26:44 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 12 13:26:44 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: info: Getting Spotify volume Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: SPOTIFY: SPOTIFY VOLUME undefined Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: SPOTIFY: VOLUMIO VOLUME 91 Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: info: Aligning Spotify Volume to Volumio Volume Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: info: Setting Spotify Volume from Volumio: 91 Dec 12 13:26:46 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:46-05:00" level=debug msg="obtained new client token: AAAdkkrEiQcOjbbmWmd9l1zhe80sSSryR6xdf7Bq7DCU4DSJjizLweOx4f7P4siEEWUDT3U4IGB3laEjpEO9otRtKFGGvQlgqW5Zf8mY6Bfr2MeUzmrJHzdzF3UssI6odsl9pK+L9qZ+G4hSGUwMLjMoAvHQt1EgtBZJ1E6RLegPWMOamClVXCE1zHSH3SBaFsiaOkeY+zojpf7PvRBz/pxRsQgFM3oUZpcA0K01HHG9UlMTOjW1urTF+Q==" Dec 12 13:26:46 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:46-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:46 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:46-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:46 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:46-05:00" level=debug msg="completed challenge" Dec 12 13:26:46 gbvpi-bedroom go-librespot[17637]: time="2025-12-12T13:26:46-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:46 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:46 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: Error: socket hang up Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: at connResetException (node:internal/errors:720:14) Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: at Socket.emit (node:events:526:35) Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: code: 'ECONNRESET', Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: response: undefined Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: } Dec 12 13:26:46 gbvpi-bedroom volumio[17083]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 13:26:46 gbvpi-bedroom sudo[17675]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-12 13:25' Dec 12 13:26:46 gbvpi-bedroom sudo[17675]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:47 gbvpi-bedroom sudo[17675]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:47 gbvpi-bedroom qobuz-connect[17594]: 20251212 13:26:47.769 [17594.17594] INFO SampleApp: Socket closed Dec 12 13:26:47 gbvpi-bedroom vtcs[17615]: [2025-12-12 13:26:47.769] [tisoc] [error] [SpkconServer.cpp:375] recv error. socket disconnected Dec 12 13:26:47 gbvpi-bedroom volumio-remote-updater[775]: [2025-12-12 13:26:47] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 12 13:26:47 gbvpi-bedroom volumio-remote-updater[775]: [2025-12-12 13:26:47] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 12 13:26:47 gbvpi-bedroom systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:47 gbvpi-bedroom systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 12 13:26:47 gbvpi-bedroom systemd[1]: volumio.service: Consumed 21.124s CPU time. Dec 12 13:26:47 gbvpi-bedroom systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 12 13:26:47 gbvpi-bedroom systemd[1]: dynamicswap.service: Deactivated successfully. Dec 12 13:26:47 gbvpi-bedroom systemd[1]: volumio.service: Scheduled restart job, restart counter is at 3063. Dec 12 13:26:48 gbvpi-bedroom systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 12 13:26:48 gbvpi-bedroom systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 12 13:26:48 gbvpi-bedroom systemd[1]: volumio.service: Consumed 21.124s CPU time. Dec 12 13:26:48 gbvpi-bedroom systemd[1]: Started volumio.service - Volumio Backend Module. Dec 12 13:26:48 gbvpi-bedroom systemd[1]: dynamicswap.service: Deactivated successfully. Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: ------------------------------------------- Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: ----- Volumio3 ---- Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: ------------------------------------------- Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: ----- System startup ---- Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: ------------------------------------------- Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: MYVOLUMIO Environment detected Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Plugin folders cleanup Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Scanning into folder /volumio/app/plugins/ Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Scanning category audio_interface Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Scanning category miscellanea Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Scanning category music_service Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Scanning category plugins.json Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Scanning category system_controller Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Scanning category user_interface Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Scanning into folder /data/plugins/ Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Scanning category music_service Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Plugin folders cleanup completed Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: ------------------------------------------- Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: ----- Core plugins startup ---- Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: ------------------------------------------- Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Loading plugins from folder /volumio/app/plugins/ Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Adding plugin upnp to MyMusic Plugins Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Loading plugins from folder /data/plugins/ Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Loading plugin "system"... Dec 12 13:26:49 gbvpi-bedroom volumio[17691]: info: Loading plugin "appearance"... Dec 12 13:26:49 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 169. Dec 12 13:26:49 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:49 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:49 gbvpi-bedroom go-librespot[17718]: go-librespot daemon starting... Dec 12 13:26:49 gbvpi-bedroom go-librespot[17719]: time="2025-12-12T13:26:49-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:49 gbvpi-bedroom go-librespot[17719]: time="2025-12-12T13:26:49-05:00" level=debug msg="app state loaded" Dec 12 13:26:49 gbvpi-bedroom go-librespot[17719]: time="2025-12-12T13:26:49-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:49 gbvpi-bedroom go-librespot[17719]: time="2025-12-12T13:26:49-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:26:49 gbvpi-bedroom go-librespot[17719]: time="2025-12-12T13:26:49-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:26:49 gbvpi-bedroom go-librespot[17719]: time="2025-12-12T13:26:49-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:26:49 gbvpi-bedroom go-librespot[17719]: time="2025-12-12T13:26:49-05:00" level=info msg="zeroconf server listening on port 40905" Dec 12 13:26:50 gbvpi-bedroom go-librespot[17719]: time="2025-12-12T13:26:50-05:00" level=debug msg="obtained new client token: AAAV8M2iFYaA1PsSK2aPc8rz29BQ2/fxWDIazI+UQivq0cGO5SGdYgoKhCdiBznw5tj4MJ5iKf0yw0SgbInWsmb4Pl5LS9iDFDQOT7ib4//bYuYOOqOMik4gOmcXjzbdxHRmnPT5c6EDrWMmxxOLwpKu0G6/2tUzTOEWx+qPgKmi514aC/dgQiWj34E0cGm7Wec60qmj/x2N8nNZo3krsGEDeJR1Fut3GPyn7VzYZkSjQSjQed7FIF4=" Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Loading plugin "network"... Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Refreshing Cached IP Addresses Dec 12 13:26:50 gbvpi-bedroom sudo[17727]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 12 13:26:50 gbvpi-bedroom sudo[17727]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:50 gbvpi-bedroom go-librespot[17719]: time="2025-12-12T13:26:50-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:50 gbvpi-bedroom sudo[17727]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:50 gbvpi-bedroom sudo[17729]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 12 13:26:50 gbvpi-bedroom sudo[17729]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Loading plugin "services"... Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Loading plugin "alsa_controller"... Dec 12 13:26:50 gbvpi-bedroom sudo[17729]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:50 gbvpi-bedroom sudo[17735]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 12 13:26:50 gbvpi-bedroom sudo[17735]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:50 gbvpi-bedroom go-librespot[17719]: time="2025-12-12T13:26:50-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:50 gbvpi-bedroom go-librespot[17719]: time="2025-12-12T13:26:50-05:00" level=debug msg="completed challenge" Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Loading plugin "wizard"... Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Loading plugin "networkfs"... Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Starting Udev Watcher for removable devices Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Ignoring mount for partition: boot Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Ignoring mount for partition: volumio Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Ignoring mount for partition: volumio_data Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Loading plugin "volumio_command_line_client"... Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Loading plugin "upnp"... Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: [1765564010316] Starting Upmpd Daemon Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Loading plugin "my_music"... Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Loading plugin "mpd"... Dec 12 13:26:50 gbvpi-bedroom go-librespot[17719]: time="2025-12-12T13:26:50-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:50 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:50 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:50 gbvpi-bedroom volumio[17691]: info: Loading plugin "upnp_browser"... Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: Starting UPNP Browser Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: Loading plugin "alarm-clock"... Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: Loading plugin "airplay_emulation"... Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: Starting Shairport Sync Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: Loading plugin "last_100"... Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: Loading plugin "webradio"... Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: Loading plugin "i2s_dacs"... Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: I2S DAC not set, start Auto-detection Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: Loading plugin "volumiodiscovery"... Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: *** WARNING *** For more information see Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 13:26:51 gbvpi-bedroom node[17691]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: *** WARNING *** For more information see Dec 12 13:26:51 gbvpi-bedroom node[17691]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 13:26:51 gbvpi-bedroom node[17691]: *** WARNING *** For more information see Dec 12 13:26:51 gbvpi-bedroom node[17691]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 12 13:26:51 gbvpi-bedroom node[17691]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 12 13:26:51 gbvpi-bedroom node[17691]: *** WARNING *** For more information see Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: Discovery: Started advertising with name: GBVPi-Bedroom Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: Loading plugin "jellyfin"... Dec 12 13:26:51 gbvpi-bedroom volumio[17691]: info: Loading plugin "spop"... Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Loading plugin "outputs"... Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Loading plugin "albumart"... Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Plugin example_plugin is not enabled Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Loading plugin "inputs"... Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Loading plugin "updater_comm"... Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Plugin mpdemulation is not enabled Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Loading plugin "rest_api"... Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Loading plugin "websocket"... Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Starting Socket.io Server version 1.7.4 Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Loading i18n strings for locale en Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: Updating browse sources language Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::initPlayerControls Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: Express server listening on port 3000 Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: [Metrics] WebUI: 3s 812.01ms Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::resetVolumioState Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::getcurrentVolume Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioRetrievevolume Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Volumio Network Manager: Network status updated: 2 Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: VolumeController:: Volume=91 Mute =false Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::pushState Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioPushState Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::updateTrackBlock Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrackBlock Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioRetrievevolume Dec 12 13:26:52 gbvpi-bedroom volumio[17764]: Forking 3 albumart workers Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Reloading queue from file Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::setRepeat true single undefined Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::pushState Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioPushState Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::setRandom null Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::pushState Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioPushState Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Setting Device type: Raspberry PI Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 12 13:26:52 gbvpi-bedroom volumio-remote-updater[775]: [2025-12-12 13:26:52] [connect] Successful connection Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: VolumeController:: Volume=91 Mute =false Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::pushState Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioPushState Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:52 gbvpi-bedroom volumio-remote-updater[775]: [2025-12-12 13:26:52] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765564012 101 Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Completed loading Core Plugins Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Preparing to generate the ALSA configuration file Dec 12 13:26:52 gbvpi-bedroom volumio[17691]: info: Asound.conf file written Dec 12 13:26:52 gbvpi-bedroom sudo[17821]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 12 13:26:52 gbvpi-bedroom sudo[17821]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:52 gbvpi-bedroom sudo[17821]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: Output device has changed, restarting MPD Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: Output device has changed, restarting Shairport Sync Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:53 gbvpi-bedroom sudo[17827]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 12 13:26:53 gbvpi-bedroom sudo[17829]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 12 13:26:53 gbvpi-bedroom sudo[17827]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:53 gbvpi-bedroom sudo[17829]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: ___________ START PLUGINS ___________ Dec 12 13:26:53 gbvpi-bedroom sudo[17827]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: ControllerMpd::onStart: Initializing MPD Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: Creating MPD Configuration file Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: [1765564013123] CoreMusicLibrary::Adding element Media Servers Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 13:26:53 gbvpi-bedroom systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 12 13:26:53 gbvpi-bedroom sudo[17837]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 12 13:26:53 gbvpi-bedroom sudo[17837]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:53 gbvpi-bedroom sudo[17839]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 12 13:26:53 gbvpi-bedroom sudo[17839]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: UPNP Browser: Client initialized successfully Dec 12 13:26:53 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 12 13:26:53 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 12 13:26:53 gbvpi-bedroom systemd[1]: mpd.service: Consumed 1.280s CPU time. Dec 12 13:26:53 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 12 13:26:53 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 12 13:26:53 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 12 13:26:53 gbvpi-bedroom sudo[17837]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:53 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 12 13:26:53 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: [1765564013303] CoreMusicLibrary::Adding element Last_100 Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: [1765564013306] CoreMusicLibrary::Adding element Webradio Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: Initializing BBC Radios Dec 12 13:26:53 gbvpi-bedroom sudo[17847]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 12 13:26:53 gbvpi-bedroom sudo[17847]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 12 13:26:53 gbvpi-bedroom sudo[17847]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: Discovery: Getting this device information Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 12 13:26:53 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 170. Dec 12 13:26:53 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: [1765564013445] CoreMusicLibrary::Adding element Jellyfin Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: Cannot find translation for source Jellyfin Dec 12 13:26:53 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:53 gbvpi-bedroom go-librespot[17867]: go-librespot daemon starting... Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: [jellyfin] Initialized plugin with device info: {"host":"http://192.168.1.97","id":"74ce6260-2045-48bb-acbd-0b75ccb5d93e","name":"GBVPi-Bedroom","serviceName":"Volumio","state":{"albumart":"http://cdn-profiles.tunein.com/s28808/images/logoq.jpg?t=1","mute":false,"status":"stop","track":"WFMU","volume":91},"type":"device"} Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: Creating Spotify config file Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:53 gbvpi-bedroom go-librespot[17868]: time="2025-12-12T13:26:53-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:53 gbvpi-bedroom go-librespot[17868]: time="2025-12-12T13:26:53-05:00" level=debug msg="app state loaded" Dec 12 13:26:53 gbvpi-bedroom go-librespot[17868]: time="2025-12-12T13:26:53-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:53 gbvpi-bedroom volumio[17783]: Starting albumart workers Dec 12 13:26:53 gbvpi-bedroom volumio[17786]: Starting albumart workers Dec 12 13:26:53 gbvpi-bedroom volumio[17788]: Starting albumart workers Dec 12 13:26:53 gbvpi-bedroom volumio[17691]: info: Volumio Calling Home Dec 12 13:26:53 gbvpi-bedroom go-librespot[17868]: time="2025-12-12T13:26:53-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 12 13:26:53 gbvpi-bedroom go-librespot[17868]: time="2025-12-12T13:26:53-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 12 13:26:53 gbvpi-bedroom go-librespot[17868]: time="2025-12-12T13:26:53-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 12 13:26:53 gbvpi-bedroom go-librespot[17868]: time="2025-12-12T13:26:53-05:00" level=info msg="zeroconf server listening on port 41059" Dec 12 13:26:54 gbvpi-bedroom go-librespot[17868]: time="2025-12-12T13:26:54-05:00" level=debug msg="obtained new client token: AABVDI8VsF4fgU3dET/DAJ2mWLAUUIacCz93Tg/RIVWB2uhZUIIEYvLxYuMn31a+CX+rPCxQURQNpqOP57f5c+jWC1byrq1dIbKtkwhOSS6y6JYJcwqYKdW+KNhtiHDJWnDq0T3I63mcx/1R90V1/rXmjQfmOHTR6qMCStVjib/EXyDW0tNq8dp3oz+SrEm7WSeNi4fQ70HKMWFiOS2a/076TuhTJASveoGkwK+QvxJiNZ7d+0VLXis=" Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: Discovery: adding 74ce6260-2045-48bb-acbd-0b75ccb5d93e Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: Discovery: Found device GBVPi-Bedroom Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: Discovery: this is already registered, 74ce6260-2045-48bb-acbd-0b75ccb5d93e Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: Discovery: Found device GBVPi-Bedroom Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:54 gbvpi-bedroom go-librespot[17868]: time="2025-12-12T13:26:54-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:54 gbvpi-bedroom sudo[17735]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: MPD Permissions set Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: MPD Permissions set Dec 12 13:26:54 gbvpi-bedroom go-librespot[17868]: time="2025-12-12T13:26:54-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:54 gbvpi-bedroom go-librespot[17868]: time="2025-12-12T13:26:54-05:00" level=debug msg="completed challenge" Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: Spotify config file written Dec 12 13:26:54 gbvpi-bedroom sudo[17886]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 12 13:26:54 gbvpi-bedroom sudo[17886]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: Volumio called home Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 12 13:26:54 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:26:54 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: No need to fix Spotify hosts Dec 12 13:26:54 gbvpi-bedroom go-librespot[17896]: go-librespot daemon starting... Dec 12 13:26:54 gbvpi-bedroom sudo[17886]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:54 gbvpi-bedroom go-librespot[17905]: time="2025-12-12T13:26:54-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:54 gbvpi-bedroom go-librespot[17905]: time="2025-12-12T13:26:54-05:00" level=debug msg="app state loaded" Dec 12 13:26:54 gbvpi-bedroom go-librespot[17905]: time="2025-12-12T13:26:54-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: Starting Shairport Sync Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: Starting Shairport Sync Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: Starting Shairport Sync Dec 12 13:26:54 gbvpi-bedroom sudo[17918]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 13:26:54 gbvpi-bedroom sudo[17918]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:54 gbvpi-bedroom sudo[17923]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 13:26:54 gbvpi-bedroom sudo[17923]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:54 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 12 13:26:54 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 12 13:26:54 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 13:26:54 gbvpi-bedroom systemd[1]: shairport-sync.service: Consumed 1.617s CPU time. Dec 12 13:26:54 gbvpi-bedroom sudo[17925]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 13:26:54 gbvpi-bedroom sudo[17925]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:54 gbvpi-bedroom go-librespot[17905]: time="2025-12-12T13:26:54-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:26:54 gbvpi-bedroom go-librespot[17905]: time="2025-12-12T13:26:54-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:26:54 gbvpi-bedroom go-librespot[17905]: time="2025-12-12T13:26:54-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:26:54 gbvpi-bedroom go-librespot[17905]: time="2025-12-12T13:26:54-05:00" level=info msg="zeroconf server listening on port 41587" Dec 12 13:26:54 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 12 13:26:54 gbvpi-bedroom sudo[17918]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: Shairport-Sync Started Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: Error adding Membership: Error: addMembership EINVAL Dec 12 13:26:54 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 12 13:26:54 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 12 13:26:54 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 13:26:54 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 13:26:54 gbvpi-bedroom sudo[17923]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: Shairport-Sync Started Dec 12 13:26:54 gbvpi-bedroom sudo[17925]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:54 gbvpi-bedroom volumio[17691]: info: Shairport-Sync Started Dec 12 13:26:55 gbvpi-bedroom go-librespot[17905]: time="2025-12-12T13:26:55-05:00" level=debug msg="obtained new client token: AACapeXjqBmKX6CVEpjy7/i/yx3M1c82Tz+NqZQXHokgAL6Kqq/kFCA+Z4uqLhukrjvlcdZPHidWNl6QnlDtayioubtnOkdsFrwiWAis4hhJubRR8YGQI9GbzfagqtyFlUcoWxd4zSO1dVu4JK8vh/LVQMadtHmAVtYUpNH5BjTTiOSB8chhCTnis0LPOPNK31VhXDFSJI0zCm65Dxh4Hi2aZSE/0brTik1V4lrpcpimOqSy94/7gkI=" Dec 12 13:26:55 gbvpi-bedroom go-librespot[17905]: time="2025-12-12T13:26:55-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:55 gbvpi-bedroom go-librespot[17905]: time="2025-12-12T13:26:55-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:55 gbvpi-bedroom go-librespot[17905]: time="2025-12-12T13:26:55-05:00" level=debug msg="completed challenge" Dec 12 13:26:55 gbvpi-bedroom go-librespot[17905]: time="2025-12-12T13:26:55-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:55 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:55 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:26:55 gbvpi-bedroom mpd[17858]: 2025-12-12T13:26:55 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 12 13:26:55 gbvpi-bedroom systemd[1]: Started mpd.service - Music Player Daemon. Dec 12 13:26:55 gbvpi-bedroom sudo[17829]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:55 gbvpi-bedroom sudo[17839]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: info: Completed starting Core Plugins Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: info: ------------------------------------------- Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: info: ----- MyVolumio plugins startup ---- Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: info: ------------------------------------------- Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: error: MPD error: The expression evaluated to a falsy value: Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: assert.ok(self.idling) Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: error: The expression evaluated to a falsy value: Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: assert.ok(self.idling) Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: error: updateQueue error: null Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: info: MPD running with PID17858 Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: ,establishing connection Dec 12 13:26:55 gbvpi-bedroom volumio[17691]: error: updateQueue error: null Dec 12 13:26:57 gbvpi-bedroom volumio[17691]: info: go-librespot daemon successfully initialized Dec 12 13:26:57 gbvpi-bedroom volumio[17691]: info: Discovery: Browse raised the following error Error: dns service error: unknown Dec 12 13:26:58 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 12 13:26:58 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:58 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:26:58 gbvpi-bedroom go-librespot[17958]: go-librespot daemon starting... Dec 12 13:26:58 gbvpi-bedroom go-librespot[17959]: time="2025-12-12T13:26:58-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:26:58 gbvpi-bedroom go-librespot[17959]: time="2025-12-12T13:26:58-05:00" level=debug msg="app state loaded" Dec 12 13:26:58 gbvpi-bedroom go-librespot[17959]: time="2025-12-12T13:26:58-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:26:58 gbvpi-bedroom sudo[17967]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 12 13:26:58 gbvpi-bedroom sudo[17967]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:58 gbvpi-bedroom sudo[17969]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 12 13:26:58 gbvpi-bedroom sudo[17969]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:26:58 gbvpi-bedroom systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 12 13:26:58 gbvpi-bedroom systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 12 13:26:58 gbvpi-bedroom systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 12 13:26:58 gbvpi-bedroom systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 12 13:26:58 gbvpi-bedroom sudo[17967]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:58 gbvpi-bedroom mpd_monitor.sh[17972]: MPD Monitor Service: Starting MPD Monitor Service Dec 12 13:26:58 gbvpi-bedroom systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 12 13:26:58 gbvpi-bedroom systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 12 13:26:58 gbvpi-bedroom systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 12 13:26:58 gbvpi-bedroom systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 12 13:26:58 gbvpi-bedroom sudo[17969]: pam_unix(sudo:session): session closed for user root Dec 12 13:26:58 gbvpi-bedroom volumio[17691]: info: Successfully started MPD Monitor Dec 12 13:26:58 gbvpi-bedroom volumio[17691]: info: Successfully started MPD Monitor Dec 12 13:26:58 gbvpi-bedroom go-librespot[17959]: time="2025-12-12T13:26:58-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 12 13:26:58 gbvpi-bedroom go-librespot[17959]: time="2025-12-12T13:26:58-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 12 13:26:58 gbvpi-bedroom go-librespot[17959]: time="2025-12-12T13:26:58-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 12 13:26:58 gbvpi-bedroom mpd_monitor.sh[17974]: MPD Monitor Service: Starting MPD Monitor Service Dec 12 13:26:58 gbvpi-bedroom go-librespot[17959]: time="2025-12-12T13:26:58-05:00" level=info msg="zeroconf server listening on port 39625" Dec 12 13:26:58 gbvpi-bedroom go-librespot[17959]: time="2025-12-12T13:26:58-05:00" level=debug msg="obtained new client token: AAAiowRZtj8AHiGzwNVJmM69j+0Qw9HUHOH4aX83x0AcELOEjDNY+Hjyp0azF9I47HLy52zaFEBYvtVrU/+3lBZAt8gZjzm3aS885H62STw3DC5XWHXzAXQGJrazLtk0LJuQV+kauM1WMdMibM476NNpr7qlESzE5LraiTGVIL0E6vSycY6PCA83sl6Ah383TUgHc98Ebq7VHhKyU7lUWMmAg211dKTE6nPg435eNp7xZKL7t22UCEYAUg==" Dec 12 13:26:58 gbvpi-bedroom go-librespot[17959]: time="2025-12-12T13:26:58-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:26:58 gbvpi-bedroom go-librespot[17959]: time="2025-12-12T13:26:58-05:00" level=debug msg="completed keyexchange" Dec 12 13:26:58 gbvpi-bedroom go-librespot[17959]: time="2025-12-12T13:26:58-05:00" level=debug msg="completed challenge" Dec 12 13:26:58 gbvpi-bedroom go-librespot[17959]: time="2025-12-12T13:26:58-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:26:58 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:26:58 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:27:00 gbvpi-bedroom sudo[17994]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 12 13:27:00 gbvpi-bedroom sudo[17994]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:00 gbvpi-bedroom sudo[17994]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:00 gbvpi-bedroom sudo[17996]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 12 13:27:00 gbvpi-bedroom sudo[17996]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:00 gbvpi-bedroom sudo[17996]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:00 gbvpi-bedroom sudo[17999]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 12 13:27:00 gbvpi-bedroom sudo[17999]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:00 gbvpi-bedroom volumio[17691]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 12 13:27:00 gbvpi-bedroom sudo[17999]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:00 gbvpi-bedroom volumio[17691]: info: Upmpdcli Daemon Started Dec 12 13:27:00 gbvpi-bedroom volumio[17691]: info: Initializing connection to go-librespot Websocket Dec 12 13:27:00 gbvpi-bedroom volumio[17691]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:27:01 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 12 13:27:01 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:02 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:02 gbvpi-bedroom go-librespot[18002]: go-librespot daemon starting... Dec 12 13:27:02 gbvpi-bedroom go-librespot[18003]: time="2025-12-12T13:27:02-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:27:02 gbvpi-bedroom go-librespot[18003]: time="2025-12-12T13:27:02-05:00" level=debug msg="app state loaded" Dec 12 13:27:02 gbvpi-bedroom go-librespot[18003]: time="2025-12-12T13:27:02-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:27:02 gbvpi-bedroom go-librespot[18003]: time="2025-12-12T13:27:02-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:27:02 gbvpi-bedroom go-librespot[18003]: time="2025-12-12T13:27:02-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:27:02 gbvpi-bedroom go-librespot[18003]: time="2025-12-12T13:27:02-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:27:02 gbvpi-bedroom go-librespot[18003]: time="2025-12-12T13:27:02-05:00" level=info msg="zeroconf server listening on port 41193" Dec 12 13:27:02 gbvpi-bedroom go-librespot[18003]: time="2025-12-12T13:27:02-05:00" level=debug msg="obtained new client token: AAD/eTUly63GhT1cSDJfIHD7u4SjSiEwn0rYH3K/dLK5lQrMFlmRgF9f/qGbnAWjZTO54vxnZfESI5YmhFvC37GJTUMVEzp02weNdxjO9atxO4WXAYUNqrNv/NXXOWbtFRcDN1YRiqV49TC/u48VGiizNwHUqHmp/kWsQ1dFPyTRrjAIbKqhD9jhR5BUZmoTqahobefXJJRcr109U8qnXOkzPuP62tO2w7ARiBwwoTGOCzGzmdydKwh1Fw==" Dec 12 13:27:02 gbvpi-bedroom go-librespot[18003]: time="2025-12-12T13:27:02-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:27:02 gbvpi-bedroom go-librespot[18003]: time="2025-12-12T13:27:02-05:00" level=debug msg="completed keyexchange" Dec 12 13:27:02 gbvpi-bedroom go-librespot[18003]: time="2025-12-12T13:27:02-05:00" level=debug msg="completed challenge" Dec 12 13:27:02 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:27:02 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:27:02 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:27:02 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:27:02 gbvpi-bedroom volumio[17691]: info: Listing playlists Dec 12 13:27:02 gbvpi-bedroom volumio[17691]: info: Listing playlists Dec 12 13:27:02 gbvpi-bedroom volumio[17691]: info: Listing playlists Dec 12 13:27:02 gbvpi-bedroom volumio[17691]: info: Listing playlists Dec 12 13:27:02 gbvpi-bedroom go-librespot[18003]: time="2025-12-12T13:27:02-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:27:02 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:27:02 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: Adding plugin bluetooth to MyMusic Plugins Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: Adding plugin multiroom to MyMusic Plugins Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: Adding plugin metavolumio to MyMusic Plugins Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: Adding plugin cd_controller to MyMusic Plugins Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 12 13:27:03 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: Starting MyVolumio Remote Streaming Endpoints Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: MyVolumio login type: Token Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: Streaming services startup Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: Starting Streaming Daemon Dec 12 13:27:04 gbvpi-bedroom sudo[18011]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 12 13:27:04 gbvpi-bedroom sudo[18011]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 12 13:27:04 gbvpi-bedroom sudo[18011]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: Initializing connection to go-librespot Websocket Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: error: Cannot start Volumio Streaming Daemon Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:27:04 gbvpi-bedroom volumio[17691]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: MyVolumio token set successfully Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: MYVOLUMIO: Adding device Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: MYVOLUMIO: Evaluating Server Dec 12 13:27:05 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 12 13:27:05 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:05 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:05 gbvpi-bedroom go-librespot[18027]: go-librespot daemon starting... Dec 12 13:27:05 gbvpi-bedroom go-librespot[18036]: time="2025-12-12T13:27:05-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:27:05 gbvpi-bedroom go-librespot[18036]: time="2025-12-12T13:27:05-05:00" level=debug msg="app state loaded" Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: MyVolumio Plan changed: premium Dec 12 13:27:05 gbvpi-bedroom go-librespot[18036]: time="2025-12-12T13:27:05-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: Removing browser output: myVolumio user plan is not superstar Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: Removing audio output: Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: MYVOLUMIO: Adding device Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: MYVOLUMIO: Evaluating Server Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: Remote config written successfully Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: Starting Tunnel 1 Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: Starting Tunnel Connection Checker Dec 12 13:27:05 gbvpi-bedroom volumio[17691]: info: Completed starting MyVolumio Plugin Dec 12 13:27:05 gbvpi-bedroom go-librespot[18036]: time="2025-12-12T13:27:05-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 12 13:27:05 gbvpi-bedroom go-librespot[18036]: time="2025-12-12T13:27:05-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 12 13:27:05 gbvpi-bedroom go-librespot[18036]: time="2025-12-12T13:27:05-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 12 13:27:05 gbvpi-bedroom go-librespot[18036]: time="2025-12-12T13:27:05-05:00" level=info msg="zeroconf server listening on port 42773" Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: MYVolumio Device enabled Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: MyVolumio status changed Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: Streaming services startup Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: Starting Streaming Daemon Dec 12 13:27:06 gbvpi-bedroom sudo[18065]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 12 13:27:06 gbvpi-bedroom sudo[18065]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Dec 12 13:27:06 gbvpi-bedroom sudo[18065]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:06 gbvpi-bedroom go-librespot[18036]: time="2025-12-12T13:27:06-05:00" level=debug msg="obtained new client token: AABjJ2gfJYDvCj4tUFMEZEO0GArPqk98GLB63jz43XUSXQookdPxKSvxgWsv0jE1BjpWSqA/rIdkT9VBM6VSAX4fa1JGUTBlQhpKPMB8oBG+4D2wZTayyTVtRbqyjOFeQyoFAs7NPwKwInssIfQFjb5NAEWRxN87MGJSGykFBzhyLh43hXi2hVoctk7XODWrysEhixLeAu7Y2rdGPQg8yjdKT9DWzvXbYAR9gWakS/f2x7o+pB/53F4=" Dec 12 13:27:06 gbvpi-bedroom go-librespot[18036]: time="2025-12-12T13:27:06-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Dec 12 13:27:06 gbvpi-bedroom go-librespot[18036]: time="2025-12-12T13:27:06-05:00" level=debug msg="completed keyexchange" Dec 12 13:27:06 gbvpi-bedroom go-librespot[18036]: time="2025-12-12T13:27:06-05:00" level=debug msg="completed challenge" Dec 12 13:27:06 gbvpi-bedroom go-librespot[18036]: time="2025-12-12T13:27:06-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:27:06 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:27:06 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Dec 12 13:27:06 gbvpi-bedroom sudo[18069]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Dec 12 13:27:06 gbvpi-bedroom sudo[18069]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:06 gbvpi-bedroom sudo[18069]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: /usr/bin/mkdir: cannot create directory ‘/tmp/hls’: File exists Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: MRS: MultiRoom plugin initialized Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: MRS: STOPPING SNAPCLIENT Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: MRS: Snap server stop Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: MRS: STOPPING volumioStreaming Dec 12 13:27:06 gbvpi-bedroom sudo[18086]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Dec 12 13:27:06 gbvpi-bedroom sudo[18086]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:06 gbvpi-bedroom sudo[18088]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Dec 12 13:27:06 gbvpi-bedroom sudo[18088]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Dec 12 13:27:06 gbvpi-bedroom sudo[18093]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Dec 12 13:27:06 gbvpi-bedroom sudo[18092]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Dec 12 13:27:06 gbvpi-bedroom sudo[18092]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:06 gbvpi-bedroom sudo[18093]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Dec 12 13:27:06 gbvpi-bedroom sudo[18093]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:06 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Dec 12 13:27:07 gbvpi-bedroom sudo[18088]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Dec 12 13:27:07 gbvpi-bedroom sudo[18086]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:07 gbvpi-bedroom sudo[18092]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Preparing to generate the ALSA configuration file Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Setting Geolocation for MyVolumio to us4 Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Setting Geolocation for MyVolumio to us1 Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Reading ALSA contributions from plugins. Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: MRS: Removed streaming files Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: MRS: volumioStreaming STOPPED Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: MRS: SNAPSERVER STOPPED Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: MRS: SNAPCLIENT STOPPED Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: error: Cannot start Volumio Streaming Daemon Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Asound.conf file written Dec 12 13:27:07 gbvpi-bedroom sudo[18100]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 12 13:27:07 gbvpi-bedroom sudo[18100]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:07 gbvpi-bedroom sudo[18100]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Output device has changed, restarting MPD Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Output device has changed, restarting Shairport Sync Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:07 gbvpi-bedroom sudo[18106]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 12 13:27:07 gbvpi-bedroom sudo[18106]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:07 gbvpi-bedroom sudo[18106]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:07 gbvpi-bedroom sudo[18108]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 12 13:27:07 gbvpi-bedroom sudo[18108]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: ------------------------------------ BT MESSAGE: [FUNC] onStart Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Dec 12 13:27:07 gbvpi-bedroom systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: MRS: Pushing multiroomSync output for this device Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: MRS: Pushing multiroomSync output Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Adding audio output: Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Adding audio output: Dec 12 13:27:07 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 12 13:27:07 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 12 13:27:07 gbvpi-bedroom systemd[1]: mpd.service: Consumed 1.945s CPU time. Dec 12 13:27:07 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 12 13:27:07 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 12 13:27:07 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Adding METAVOLUMIO REST API Endpoints Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Preparing CD Folders Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Adding CD REST API Endpoints Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Starting UDEV Watcher for CD Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: Detecting CD presence with UDEV Dec 12 13:27:07 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Dec 12 13:27:07 gbvpi-bedroom bluetoothd[763]: Path / reserved for Adv Monitor app :1.46409 Dec 12 13:27:07 gbvpi-bedroom bluetoothd[763]: Adv Monitor app :1.46409 disconnected from D-Bus Dec 12 13:27:07 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 12 13:27:07 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 12 13:27:07 gbvpi-bedroom sudo[18128]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 12 13:27:07 gbvpi-bedroom sudo[18128]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 12 13:27:07 gbvpi-bedroom sudo[18128]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:08 gbvpi-bedroom mpd[18130]: 2025-12-12T13:27:08 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 12 13:27:08 gbvpi-bedroom systemd[1]: Started mpd.service - Music Player Daemon. Dec 12 13:27:08 gbvpi-bedroom sudo[18108]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:09 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 12 13:27:09 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:09 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:09 gbvpi-bedroom go-librespot[18133]: go-librespot daemon starting... Dec 12 13:27:09 gbvpi-bedroom go-librespot[18134]: time="2025-12-12T13:27:09-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:27:09 gbvpi-bedroom go-librespot[18134]: time="2025-12-12T13:27:09-05:00" level=debug msg="app state loaded" Dec 12 13:27:09 gbvpi-bedroom go-librespot[18134]: time="2025-12-12T13:27:09-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:27:09 gbvpi-bedroom go-librespot[18134]: time="2025-12-12T13:27:09-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:27:09 gbvpi-bedroom go-librespot[18134]: time="2025-12-12T13:27:09-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:27:09 gbvpi-bedroom go-librespot[18134]: time="2025-12-12T13:27:09-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:27:09 gbvpi-bedroom go-librespot[18134]: time="2025-12-12T13:27:09-05:00" level=info msg="zeroconf server listening on port 43261" Dec 12 13:27:09 gbvpi-bedroom go-librespot[18134]: time="2025-12-12T13:27:09-05:00" level=debug msg="obtained new client token: AAC/u3EpwyqcnMaZdVMhaKE9as2rDZyGg8iG9Ed9aItm3u5SMmRvWWLkrh3YEhkaIkFlTrq5D8ZySIKhMnM+mO7e10zPvePBhC09D6qt84vwNPBmDeU0YHZ7P/R7wrvzspUOZZ8NpqghUrKpAr+M5GMvRtqGvYpINljXRExJymzFFyvQ0NWaRqsE6gSBruLADb0nmfCB4qlS00M9PnTlEfu87rC1bjXB8as6ZGw3x6aMcx5awZSryt9IkA==" Dec 12 13:27:09 gbvpi-bedroom go-librespot[18134]: time="2025-12-12T13:27:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:27:09 gbvpi-bedroom go-librespot[18134]: time="2025-12-12T13:27:09-05:00" level=debug msg="completed keyexchange" Dec 12 13:27:09 gbvpi-bedroom go-librespot[18134]: time="2025-12-12T13:27:09-05:00" level=debug msg="completed challenge" Dec 12 13:27:09 gbvpi-bedroom go-librespot[18134]: time="2025-12-12T13:27:09-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:27:09 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:27:09 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: warn: [cd-plugin] cdspeedctl: device or media not ready Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Adding inputs REST Endpoints Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Scanning Audio Inputs Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Checking against Known Cards name Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Adding Server instance for streaming Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: error: Hi Res Audio Failed Login: Missing Login Data Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Adding HIGHRESAUDIO REST API Endpoints Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Dec 12 13:27:12 gbvpi-bedroom sudo[18159]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: QobuzConnect: Starting Qobuz Connect socket and service Dec 12 13:27:12 gbvpi-bedroom sudo[18159]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Adding TIDAL REST API Endpoints Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Stopping AccessToken refresher cron for QOBUZ Dec 12 13:27:12 gbvpi-bedroom systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Dec 12 13:27:12 gbvpi-bedroom systemd[1]: vtcs.service: Killing process 17635 (vtcs) with signal SIGKILL. Dec 12 13:27:12 gbvpi-bedroom sudo[18166]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Dec 12 13:27:12 gbvpi-bedroom systemd[1]: vtcs.service: Deactivated successfully. Dec 12 13:27:12 gbvpi-bedroom sudo[18166]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:12 gbvpi-bedroom systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Dec 12 13:27:12 gbvpi-bedroom sudo[18159]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: AccessToken refresher cron started for QOBUZ Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Adding QOBUZ REST API Endpoints Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: MRS: Getting audio outputs on start Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: MRS: Requesting all other devices output Dec 12 13:27:12 gbvpi-bedroom sudo[18166]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Initializing connection to go-librespot Websocket Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Updating MyVolumio device info Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Updating MyVolumio device info Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:12 gbvpi-bedroom sudo[18169]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Dec 12 13:27:12 gbvpi-bedroom sudo[18169]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Successfully Added MyVolumio device Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Successfully Added MyVolumio device Dec 12 13:27:12 gbvpi-bedroom systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Dec 12 13:27:12 gbvpi-bedroom qobuz-connect[17594]: 20251212 13:27:12.541 [17594.17594] INFO SampleApp: Stopping Local configuration server Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: MPD Permissions set Dec 12 13:27:12 gbvpi-bedroom sudo[18172]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Dec 12 13:27:12 gbvpi-bedroom sudo[18172]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:27:12 gbvpi-bedroom sudo[18172]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: error: updateQueue error: null Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioStop Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::stop Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Starting Shairport Sync Dec 12 13:27:12 gbvpi-bedroom sudo[18187]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Dec 12 13:27:12 gbvpi-bedroom sudo[18187]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: MRS: Found cast device: SmartTV-4K-fe72c264393a59c76d38e27b8168114d Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Adding audio output: Dec 12 13:27:12 gbvpi-bedroom sudo[18190]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 12 13:27:12 gbvpi-bedroom sudo[18190]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: MRS: Found cast device: Google-Home-Mini-f209fa314cb426d40a59bcf66354ddc9 Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Adding audio output: Dec 12 13:27:12 gbvpi-bedroom systemd[1]: Stopping sshtunnel.service - MyVolumio SSH Tunnel... Dec 12 13:27:12 gbvpi-bedroom autossh[17569]: received signal to exit (15) Dec 12 13:27:12 gbvpi-bedroom systemd[1]: sshtunnel.service: Deactivated successfully. Dec 12 13:27:12 gbvpi-bedroom systemd[1]: Stopped sshtunnel.service - MyVolumio SSH Tunnel. Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Successfully Updated MyVolumio device Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Successfully Updated MyVolumio device Dec 12 13:27:12 gbvpi-bedroom systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Dec 12 13:27:12 gbvpi-bedroom sudo[18187]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Remote SSH Started Dec 12 13:27:12 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 12 13:27:12 gbvpi-bedroom autossh[18193]: port set to 0, monitoring disabled Dec 12 13:27:12 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 12 13:27:12 gbvpi-bedroom autossh[18193]: starting ssh (count 1) Dec 12 13:27:12 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 13:27:12 gbvpi-bedroom autossh[18193]: ssh child pid is 18196 Dec 12 13:27:12 gbvpi-bedroom systemd[1]: shairport-sync.service: Consumed 1.600s CPU time. Dec 12 13:27:12 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 12 13:27:12 gbvpi-bedroom sudo[18190]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: Shairport-Sync Started Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 12 13:27:12 gbvpi-bedroom volumiossh-tunnel[18196]: Warning: Permanently added '[us1.myvolumio.org]:2222' (RSA) to the list of known hosts. Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:27:12 gbvpi-bedroom volumio[17691]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.KgLfU6XUUlR7svHZAvNpgZIq9af1.66712a116082b2e6ca4ffe3109a843e6.state.status' Dec 12 13:27:13 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 12 13:27:13 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:13 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:13 gbvpi-bedroom go-librespot[18212]: go-librespot daemon starting... Dec 12 13:27:13 gbvpi-bedroom go-librespot[18213]: time="2025-12-12T13:27:13-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:27:13 gbvpi-bedroom go-librespot[18213]: time="2025-12-12T13:27:13-05:00" level=debug msg="app state loaded" Dec 12 13:27:13 gbvpi-bedroom go-librespot[18213]: time="2025-12-12T13:27:13-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:27:13 gbvpi-bedroom go-librespot[18213]: time="2025-12-12T13:27:13-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:27:13 gbvpi-bedroom go-librespot[18213]: time="2025-12-12T13:27:13-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:27:13 gbvpi-bedroom go-librespot[18213]: time="2025-12-12T13:27:13-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:27:13 gbvpi-bedroom go-librespot[18213]: time="2025-12-12T13:27:13-05:00" level=info msg="zeroconf server listening on port 35909" Dec 12 13:27:13 gbvpi-bedroom go-librespot[18213]: time="2025-12-12T13:27:13-05:00" level=debug msg="obtained new client token: AADVnLh1z7NLmjVQogfucwr/mPwa7BL2626imRu1Nh8mTc7ui2ywCoYUCLKXqwGbrA/ZmSGY84aXahaWZRp3V7H/c1/Qg3lx4RuKZtJ1ugi3Gz/l38AmTM5Aq2/VW9jmKQTQ8V0HDEE//coeZhL71yclBwuxmn3TUyAz1Tsv9mPUX8iLOU/LLu6Cy1+IHe2HIreO+4HuIgQ0udhKbJ3vxdNZ16f0+Y9lswrtOlNs+BjGzLCC8mM8Egfy+g==" Dec 12 13:27:13 gbvpi-bedroom systemd[1]: qobuz-connect.service: Deactivated successfully. Dec 12 13:27:13 gbvpi-bedroom systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Dec 12 13:27:13 gbvpi-bedroom go-librespot[18213]: time="2025-12-12T13:27:13-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:27:13 gbvpi-bedroom systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Dec 12 13:27:13 gbvpi-bedroom sudo[18169]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:13 gbvpi-bedroom go-librespot[18213]: time="2025-12-12T13:27:13-05:00" level=debug msg="completed keyexchange" Dec 12 13:27:13 gbvpi-bedroom go-librespot[18213]: time="2025-12-12T13:27:13-05:00" level=debug msg="completed challenge" Dec 12 13:27:13 gbvpi-bedroom volumio[17691]: info: Executing endpoint qc_getconfig Dec 12 13:27:13 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Dec 12 13:27:13 gbvpi-bedroom go-librespot[18213]: time="2025-12-12T13:27:13-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:27:13 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:27:13 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:27:13 gbvpi-bedroom qobuz-connect[18221]: 20251212 13:27:13.770 [18221.18221] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Dec 12 13:27:13 gbvpi-bedroom volumio[17691]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Dec 12 13:27:13 gbvpi-bedroom volumio[17691]: info: QobuzConnect: QOBUZ Connect daemon connected Dec 12 13:27:13 gbvpi-bedroom qobuz-connect[18221]: 20251212 13:27:13.774 [18221.18221] INFO VolumeManager: [0x1e77588]: Setting new playback volume: 75 Dec 12 13:27:13 gbvpi-bedroom qobuz-connect[18221]: 20251212 13:27:13.774 [18221.18221] INFO VolumeManager: [0x1e77588]: Setting new mute state: 0 Dec 12 13:27:13 gbvpi-bedroom qobuz-connect[18221]: 20251212 13:27:13.775 [18221.18221] INFO QobuzConnect: [0x1e77f58]: Client initialized! Dec 12 13:27:13 gbvpi-bedroom qobuz-connect[18221]: 20251212 13:27:13.775 [18221.18221] INFO SampleApp: Starting Avahi advertising, name: GBVPi-Bedroom, service name: _qobuz-connect._tcp Dec 12 13:27:13 gbvpi-bedroom qobuz-connect[18221]: 20251212 13:27:13.786 [18221.18221] INFO LocalConfigManager: [0x1e76e68]: Starting Local Configuration server Dec 12 13:27:13 gbvpi-bedroom qobuz-connect[18221]: 20251212 13:27:13.786 [18221.18221] INFO SampleApp: Starting Local configuration server Dec 12 13:27:13 gbvpi-bedroom qobuz-connect[18221]: 20251212 13:27:13.786 [18221.18221] INFO SampleApp: Connected to UNIX socket client 0x1e61818 Dec 12 13:27:13 gbvpi-bedroom qobuz-connect[18221]: 20251212 13:27:13.920 [18221.18221] INFO SampleApp: Playback volume changed: 75 Dec 12 13:27:13 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: TidalConnect service stoped! Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Dec 12 13:27:15 gbvpi-bedroom sudo[18236]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Dec 12 13:27:15 gbvpi-bedroom sudo[18236]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:15 gbvpi-bedroom sudo[18240]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 12 13:27:15 gbvpi-bedroom sudo[18240]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: Initializing connection to go-librespot Websocket Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:27:15 gbvpi-bedroom systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Dec 12 13:27:15 gbvpi-bedroom sudo[18236]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:15 gbvpi-bedroom systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 12 13:27:15 gbvpi-bedroom systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 12 13:27:15 gbvpi-bedroom systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 12 13:27:15 gbvpi-bedroom systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 12 13:27:15 gbvpi-bedroom sudo[18240]: pam_unix(sudo:session): session closed for user root Dec 12 13:27:15 gbvpi-bedroom mpd_monitor.sh[18244]: MPD Monitor Service: Starting MPD Monitor Service Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: Successfully started MPD Monitor Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: Executing endpoint tc_getconfig Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Dec 12 13:27:15 gbvpi-bedroom vtcs[18242]: STARTING TidalConnect services, version: 1.5.2.56 Dec 12 13:27:15 gbvpi-bedroom vtcs[18242]: STARTED TidalConnect services. Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: Executing endpoint tc_connect Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: Connecting to TidalConnect Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::servicePushState Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::pushState Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioPushState Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: MRS: Pushing multiroomSync output update for this device Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: MRS: Pushing multiroomSync output Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received tidalconnect Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::servicePushState Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CoreStateMachine::pushState Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioPushState Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: MRS: Pushing multiroomSync output update for this device Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: MRS: Pushing multiroomSync output Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: CorePlayQueue::getTrack 0 Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received tidalconnect Dec 12 13:27:15 gbvpi-bedroom volumio[17691]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.KgLfU6XUUlR7svHZAvNpgZIq9af1.66712a116082b2e6ca4ffe3109a843e6.state.status' Dec 12 13:27:16 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 12 13:27:16 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:17 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:17 gbvpi-bedroom go-librespot[18262]: go-librespot daemon starting... Dec 12 13:27:17 gbvpi-bedroom go-librespot[18263]: time="2025-12-12T13:27:17-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:27:17 gbvpi-bedroom go-librespot[18263]: time="2025-12-12T13:27:17-05:00" level=debug msg="app state loaded" Dec 12 13:27:17 gbvpi-bedroom go-librespot[18263]: time="2025-12-12T13:27:17-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:27:17 gbvpi-bedroom go-librespot[18263]: time="2025-12-12T13:27:17-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 12 13:27:17 gbvpi-bedroom go-librespot[18263]: time="2025-12-12T13:27:17-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 12 13:27:17 gbvpi-bedroom go-librespot[18263]: time="2025-12-12T13:27:17-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 12 13:27:17 gbvpi-bedroom go-librespot[18263]: time="2025-12-12T13:27:17-05:00" level=info msg="zeroconf server listening on port 37645" Dec 12 13:27:17 gbvpi-bedroom go-librespot[18263]: time="2025-12-12T13:27:17-05:00" level=debug msg="obtained new client token: AAD3jXJwBtoq+jHpZbxpEoAQALMWPg8Vt8f9bKyTqgoaowlV2pkIG3t84KHgJln97vdGj9iHZXN7Zr8Vqg6XEC2AEkuyCH+gdBEhPDq4FXZYNRJpMmvmg2jezGGHy53vo0OrB2U+/caSJbAj4j+0BCN6wETGTHXvcm0/dgfsb4bVU6ep1ZM7xmyb+27Tflhxx1pYUdHpNtcxcG/vMN+9AEyClFsN3fRCEQv9glalx1sxFV80brIWj/YJkw==" Dec 12 13:27:17 gbvpi-bedroom go-librespot[18263]: time="2025-12-12T13:27:17-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:27:17 gbvpi-bedroom go-librespot[18263]: time="2025-12-12T13:27:17-05:00" level=debug msg="completed keyexchange" Dec 12 13:27:17 gbvpi-bedroom go-librespot[18263]: time="2025-12-12T13:27:17-05:00" level=debug msg="completed challenge" Dec 12 13:27:17 gbvpi-bedroom go-librespot[18263]: time="2025-12-12T13:27:17-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:27:17 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:27:17 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:27:18 gbvpi-bedroom volumio[17691]: info: Initializing connection to go-librespot Websocket Dec 12 13:27:18 gbvpi-bedroom volumio[17691]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:27:18 gbvpi-bedroom volumio[17691]: info: TidalConnect service started! Dec 12 13:27:18 gbvpi-bedroom volumio[17691]: [Metrics] CommandRouter: 29s 596.98ms Dec 12 13:27:18 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumiosetStartupVolume Dec 12 13:27:18 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:18 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:18 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::Close All Modals sent Dec 12 13:27:18 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::Close All Modals sent Dec 12 13:27:19 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 12 13:27:19 gbvpi-bedroom volumio[17691]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 12 13:27:19 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:27:19 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 12 13:27:19 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 12 13:27:19 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 12 13:27:20 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 12 13:27:20 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:20 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:20 gbvpi-bedroom go-librespot[18287]: go-librespot daemon starting... Dec 12 13:27:20 gbvpi-bedroom go-librespot[18288]: time="2025-12-12T13:27:20-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:27:20 gbvpi-bedroom go-librespot[18288]: time="2025-12-12T13:27:20-05:00" level=debug msg="app state loaded" Dec 12 13:27:20 gbvpi-bedroom go-librespot[18288]: time="2025-12-12T13:27:20-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:27:20 gbvpi-bedroom go-librespot[18288]: time="2025-12-12T13:27:20-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 12 13:27:20 gbvpi-bedroom go-librespot[18288]: time="2025-12-12T13:27:20-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 12 13:27:20 gbvpi-bedroom go-librespot[18288]: time="2025-12-12T13:27:20-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 12 13:27:20 gbvpi-bedroom go-librespot[18288]: time="2025-12-12T13:27:20-05:00" level=info msg="zeroconf server listening on port 39673" Dec 12 13:27:20 gbvpi-bedroom go-librespot[18288]: time="2025-12-12T13:27:20-05:00" level=debug msg="obtained new client token: AACEHLihl4KsiIwe4Ka+7LiEN+Ll+K6skDSpaFRsJAIL37QQomH4ofFK96YSpqNd8DeFx/UQ1HvWvj71enTTZtbo7nMsFsae1XLsTv6XVdESeCH7gyJqigexuny9MsFP1vPXsdfhjK4uXGJvB+L3R8AbqbnHG/L68e1W311t4Fjzls3zYOYMQtIdATNXje3XbykrbdhSjbRgyPi1ok9XHG1tYEIeLnxtQLwtzCYGKhijk2k6JWRFbzIVVg==" Dec 12 13:27:20 gbvpi-bedroom go-librespot[18288]: time="2025-12-12T13:27:20-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:27:20 gbvpi-bedroom go-librespot[18288]: time="2025-12-12T13:27:20-05:00" level=debug msg="completed keyexchange" Dec 12 13:27:20 gbvpi-bedroom go-librespot[18288]: time="2025-12-12T13:27:20-05:00" level=debug msg="completed challenge" Dec 12 13:27:20 gbvpi-bedroom go-librespot[18288]: time="2025-12-12T13:27:20-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:27:20 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:27:20 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:27:21 gbvpi-bedroom volumio[17691]: info: Initializing connection to go-librespot Websocket Dec 12 13:27:21 gbvpi-bedroom volumio[17691]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:27:22 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:27:22 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetState Dec 12 13:27:22 gbvpi-bedroom volumio[17691]: info: Listing playlists Dec 12 13:27:22 gbvpi-bedroom volumio[17691]: info: Listing playlists Dec 12 13:27:22 gbvpi-bedroom volumio[17691]: info: Listing playlists Dec 12 13:27:22 gbvpi-bedroom volumio[17691]: info: Listing playlists Dec 12 13:27:23 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 13:27:23 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 12 13:27:23 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 12 13:27:23 gbvpi-bedroom volumio-remote-updater[775]: Test mode enabled Dec 12 13:27:23 gbvpi-bedroom volumio-remote-updater[775]: Alpha mode disabled Dec 12 13:27:23 gbvpi-bedroom volumio-remote-updater[775]: Alpha legacy test mode disabled Dec 12 13:27:23 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 12 13:27:24 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:24 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 13:27:24 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 12 13:27:24 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 12 13:27:24 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 12 13:27:24 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::volumioGetBrowseSources Dec 12 13:27:24 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 12 13:27:24 gbvpi-bedroom volumio[17691]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

CAUTION

\n
    \n
  • This build may break your network
    • \n
\n

FIX

\n
    \n
  • Wireless and network handling
    • \n
\n","title":"Update v4.080","updateavailable":true} Dec 12 13:27:24 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Dec 12 13:27:24 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:24 gbvpi-bedroom volumio[17691]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 12 13:27:24 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:24 gbvpi-bedroom go-librespot[18299]: go-librespot daemon starting... Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=debug msg="app state loaded" Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=info msg="zeroconf server listening on port 37821" Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=debug msg="obtained new client token: AADw1TK5XS43I4+ytavj0qiMXWtFUwD8rynVTvaNTGm00pzv0Ps29guxJ6WWMYew5tdJ/Uqco+iH1yTi1w1K4DfywXH2jcSaNSPQGeqwaXud+jk2+aJLPDO9NYl0eVaOPCI9nofkJv52fdBF8ALunZjRq9/Wiyu8LIQrVzaR4QoRz/Z7CtxThLf3Fw3R6BjwvjHXTZ919ogJ/Copz/wpIyrC6saKM6jbm0ZMTT27i20u4Waq++16jtv+Ng==" Dec 12 13:27:24 gbvpi-bedroom volumio[17691]: info: Initializing connection to go-librespot Websocket Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=debug msg="new websocket client" Dec 12 13:27:24 gbvpi-bedroom volumio[17691]: info: Connection to go-librespot Websocket established Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=debug msg="completed keyexchange" Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=debug msg="completed challenge" Dec 12 13:27:24 gbvpi-bedroom go-librespot[18300]: time="2025-12-12T13:27:24-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 12 13:27:24 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 13:27:24 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 13:27:24 gbvpi-bedroom volumio[17691]: info: Connection to go-librespot Websocket closed Dec 12 13:27:25 gbvpi-bedroom volumio[17691]: info: BOOT COMPLETED Dec 12 13:27:27 gbvpi-bedroom volumio[17691]: info: Getting Spotify volume Dec 12 13:27:27 gbvpi-bedroom volumio[17691]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 13:27:27 gbvpi-bedroom volumio[17691]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 13:27:27 gbvpi-bedroom volumio[17691]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 12 13:27:27 gbvpi-bedroom volumio[17691]: errno: -111, Dec 12 13:27:27 gbvpi-bedroom volumio[17691]: code: 'ECONNREFUSED', Dec 12 13:27:27 gbvpi-bedroom volumio[17691]: syscall: 'connect', Dec 12 13:27:27 gbvpi-bedroom volumio[17691]: address: '127.0.0.1', Dec 12 13:27:27 gbvpi-bedroom volumio[17691]: port: 9879, Dec 12 13:27:27 gbvpi-bedroom volumio[17691]: response: undefined Dec 12 13:27:27 gbvpi-bedroom volumio[17691]: } Dec 12 13:27:27 gbvpi-bedroom volumio[17691]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 13:27:27 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Dec 12 13:27:27 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:28 gbvpi-bedroom sudo[18323]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-12 13:26' Dec 12 13:27:28 gbvpi-bedroom sudo[18323]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 13:27:28 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 13:27:28 gbvpi-bedroom go-librespot[18320]: go-librespot daemon starting... Dec 12 13:27:28 gbvpi-bedroom go-librespot[18325]: time="2025-12-12T13:27:28-05:00" level=info msg="running go-librespot 0.4.0" Dec 12 13:27:28 gbvpi-bedroom go-librespot[18325]: time="2025-12-12T13:27:28-05:00" level=debug msg="app state loaded" Dec 12 13:27:28 gbvpi-bedroom go-librespot[18325]: time="2025-12-12T13:27:28-05:00" level=info msg="api server listening on 127.0.0.1:9879" 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="6a0bffa825dc2af90b21170949f5219ba5ab5701" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed Dec 10 09:27:23 UTC 2025" VOLUMIO_VERSION="4.075" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4bd01f93a654c7068f4553fbd69478e2"