Mar 05 01:42:11 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:42:11.600+08:00 level=ERROR msg="failed reading message" component=volumio/socket error="read tcp 127.0.0.1:45682->127.0.0.1:3000: read: connection reset by peer" Mar 05 01:42:11 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:42:11] [error] handle_read_frame error: asio.system:104 (Connection reset by peer) Mar 05 01:42:11 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:42:11] [disconnect] Disconnect close local:[1006,Connection reset by peer] remote:[1006] Mar 05 01:42:11 rpistreamer systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 05 01:42:11 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:42:11.605+08:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 05 01:42:11 rpistreamer systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 05 01:42:11 rpistreamer systemd[1]: volumio.service: Consumed 24.466s CPU time. Mar 05 01:42:11 rpistreamer systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 05 01:42:11 rpistreamer systemd[1]: dynamicswap.service: Deactivated successfully. Mar 05 01:42:11 rpistreamer systemd[1]: volumio.service: Scheduled restart job, restart counter is at 583. Mar 05 01:42:11 rpistreamer systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 05 01:42:11 rpistreamer systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 05 01:42:11 rpistreamer systemd[1]: volumio.service: Consumed 24.466s CPU time. Mar 05 01:42:11 rpistreamer systemd[1]: Started volumio.service - Volumio Backend Module. Mar 05 01:42:11 rpistreamer systemd[1]: dynamicswap.service: Deactivated successfully. Mar 05 01:42:11 rpistreamer go-librespot[464]: time="2026-03-05T01:42:11+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 05 01:42:11 rpistreamer go-librespot[464]: time="2026-03-05T01:42:11+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 05 01:42:11 rpistreamer go-librespot[464]: time="2026-03-05T01:42:11+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 05 01:42:11 rpistreamer go-librespot[464]: time="2026-03-05T01:42:11+08:00" level=info msg="zeroconf server listening on port 42951" Mar 05 01:42:12 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:42:12.607+08:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 05 01:42:13 rpistreamer go-librespot[464]: time="2026-03-05T01:42:13+08:00" level=debug msg="obtained new client token: AAAl2+1TUg5fmC38dgDlZJOUY44nDVhLKvp4Pd/hWXObsuZpCnL8Pt7zIJcHLU5QL9036zyQz/roJq6PWO7F2F28uRr146GqVa6LC8G4zIwL1zsc0lpIszrQf9mIl74ujDsUiKGQfsaCRCT/e/5i5QmMgbQdsaJMxzHQa+wuIGzl6Y7gy5PApXKtdU7NTAuGc+/x8wTEu+qA9bK673UAhvwJCKzae2N4fOmzscW1MVPlZ3npLl7s4aU=" Mar 05 01:42:13 rpistreamer go-librespot[464]: time="2026-03-05T01:42:13+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:42:13 rpistreamer go-librespot[464]: time="2026-03-05T01:42:13+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.8.50:54734->104.199.241.202:4070: read: connection reset by peer" Mar 05 01:42:13 rpistreamer volumio[510]: info: ------------------------------------------- Mar 05 01:42:13 rpistreamer volumio[510]: info: ----- Volumio3 ---- Mar 05 01:42:13 rpistreamer volumio[510]: info: ------------------------------------------- Mar 05 01:42:13 rpistreamer volumio[510]: info: ----- System startup ---- Mar 05 01:42:13 rpistreamer volumio[510]: info: ------------------------------------------- Mar 05 01:42:14 rpistreamer go-librespot[464]: time="2026-03-05T01:42:14+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.241.202:443: connect: connection refused" Mar 05 01:42:14 rpistreamer go-librespot[464]: time="2026-03-05T01:42:14+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.241.202:80: connect: connection refused" Mar 05 01:42:14 rpistreamer volumio[510]: info: MYVOLUMIO Environment detected Mar 05 01:42:14 rpistreamer volumio[510]: info: Plugin folders cleanup Mar 05 01:42:14 rpistreamer volumio[510]: info: Scanning into folder /volumio/app/plugins/ Mar 05 01:42:14 rpistreamer volumio[510]: info: Scanning category audio_interface Mar 05 01:42:14 rpistreamer volumio[510]: info: Scanning category miscellanea Mar 05 01:42:14 rpistreamer volumio[510]: info: Scanning category music_service Mar 05 01:42:14 rpistreamer volumio[510]: info: Scanning category plugins.json Mar 05 01:42:14 rpistreamer volumio[510]: info: Scanning category system_controller Mar 05 01:42:14 rpistreamer volumio[510]: info: Scanning category user_interface Mar 05 01:42:14 rpistreamer volumio[510]: info: Scanning into folder /data/plugins/ Mar 05 01:42:14 rpistreamer volumio[510]: info: Scanning category music_service Mar 05 01:42:14 rpistreamer volumio[510]: info: Scanning category system_hardware Mar 05 01:42:14 rpistreamer volumio[510]: info: Plugin folders cleanup completed Mar 05 01:42:14 rpistreamer volumio[510]: info: ------------------------------------------- Mar 05 01:42:14 rpistreamer volumio[510]: info: ----- Core plugins startup ---- Mar 05 01:42:14 rpistreamer volumio[510]: info: ------------------------------------------- Mar 05 01:42:14 rpistreamer volumio[510]: info: Loading plugins from folder /volumio/app/plugins/ Mar 05 01:42:14 rpistreamer volumio[510]: info: Adding plugin upnp to MyMusic Plugins Mar 05 01:42:14 rpistreamer volumio[510]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 05 01:42:14 rpistreamer volumio[510]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 05 01:42:14 rpistreamer volumio[510]: info: Loading plugins from folder /data/plugins/ Mar 05 01:42:14 rpistreamer volumio[510]: info: Loading plugin "system"... Mar 05 01:42:14 rpistreamer volumio[510]: info: Loading plugin "appearance"... Mar 05 01:42:14 rpistreamer go-librespot[464]: time="2026-03-05T01:42:14+08:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 05 01:42:14 rpistreamer go-librespot[464]: time="2026-03-05T01:42:14+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:14 rpistreamer go-librespot[464]: time="2026-03-05T01:42:14+08:00" level=debug msg="completed challenge" Mar 05 01:42:15 rpistreamer go-librespot[464]: time="2026-03-05T01:42:15+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:15 rpistreamer volumio[510]: info: Loading plugin "network"... Mar 05 01:42:15 rpistreamer volumio[510]: info: Refreshing Cached IP Addresses Mar 05 01:42:15 rpistreamer sudo[541]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 01:42:15 rpistreamer sudo[541]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:15 rpistreamer sudo[541]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:15 rpistreamer sudo[545]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 01:42:15 rpistreamer sudo[545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:15 rpistreamer volumio[510]: info: Loading plugin "services"... Mar 05 01:42:15 rpistreamer volumio[510]: info: Loading plugin "volumio5onboarding"... Mar 05 01:42:15 rpistreamer sudo[545]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:15 rpistreamer sudo[556]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 05 01:42:15 rpistreamer sudo[556]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:15 rpistreamer volumio[510]: info: Loading plugin "alsa_controller"... Mar 05 01:42:15 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 01:42:15 rpistreamer volumio[510]: info: Loading plugin "wizard"... Mar 05 01:42:15 rpistreamer volumio[510]: info: Loading plugin "networkfs"... Mar 05 01:42:15 rpistreamer volumio[510]: info: Starting Udev Watcher for removable devices Mar 05 01:42:15 rpistreamer volumio[510]: info: Ignoring mount for partition: boot Mar 05 01:42:15 rpistreamer volumio[510]: info: Ignoring mount for partition: volumio Mar 05 01:42:15 rpistreamer volumio[510]: info: Ignoring mount for partition: volumio_data Mar 05 01:42:15 rpistreamer volumio[510]: info: Mounting Device 689E-A36F Mar 05 01:42:16 rpistreamer sudo[582]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/689E-A36F -o noatime Mar 05 01:42:16 rpistreamer sudo[582]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:16 rpistreamer sudo[582]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:16 rpistreamer volumio[510]: mount: /media/689E-A36F: /dev/sda1 already mounted on /media/689E-A36F. Mar 05 01:42:16 rpistreamer volumio[510]: dmesg(1) may have more information after failed mount system call. Mar 05 01:42:16 rpistreamer volumio[510]: error: Failed to mount 689E-A36F: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/689E-A36F" -o noatime Mar 05 01:42:16 rpistreamer volumio[510]: mount: /media/689E-A36F: /dev/sda1 already mounted on /media/689E-A36F. Mar 05 01:42:16 rpistreamer volumio[510]: dmesg(1) may have more information after failed mount system call. Mar 05 01:42:16 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 01:42:16 rpistreamer volumio[510]: info: Loading plugin "volumio_command_line_client"... Mar 05 01:42:16 rpistreamer volumio[510]: info: Loading plugin "upnp"... Mar 05 01:42:16 rpistreamer volumio[510]: info: [1772646136053] Starting Upmpd Daemon Mar 05 01:42:16 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 01:42:16 rpistreamer volumio[510]: info: Loading plugin "my_music"... Mar 05 01:42:16 rpistreamer volumio[510]: info: Loading plugin "mpd"... Mar 05 01:42:16 rpistreamer go-librespot[464]: time="2026-03-05T01:42:16+08:00" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 05 01:42:16 rpistreamer volumio[510]: info: Loading plugin "upnp_browser"... Mar 05 01:42:16 rpistreamer go-librespot[464]: time="2026-03-05T01:42:16+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Mar 05 01:42:16 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:42:16] [connect] Successful connection Mar 05 01:42:16 rpistreamer sudo[556]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:17 rpistreamer go-librespot[464]: time="2026-03-05T01:42:17+08:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 05 01:42:17 rpistreamer go-librespot[464]: time="2026-03-05T01:42:17+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:17 rpistreamer go-librespot[464]: time="2026-03-05T01:42:17+08:00" level=debug msg="completed challenge" Mar 05 01:42:17 rpistreamer volumio[510]: info: Starting UPNP Browser Mar 05 01:42:17 rpistreamer volumio[510]: info: Loading plugin "alarm-clock"... Mar 05 01:42:18 rpistreamer volumio[510]: info: Loading plugin "airplay_emulation"... Mar 05 01:42:18 rpistreamer volumio[510]: info: Starting Shairport Sync Mar 05 01:42:18 rpistreamer volumio[510]: info: Loading plugin "last_100"... Mar 05 01:42:18 rpistreamer volumio[510]: info: Loading plugin "webradio"... Mar 05 01:42:18 rpistreamer volumio[510]: info: Loading plugin "i2s_dacs"... Mar 05 01:42:18 rpistreamer volumio[510]: info: Loading plugin "volumiodiscovery"... Mar 05 01:42:18 rpistreamer volumio[510]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 05 01:42:18 rpistreamer volumio[510]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:42:18 rpistreamer volumio[510]: *** WARNING *** For more information see Mar 05 01:42:18 rpistreamer volumio[510]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 05 01:42:18 rpistreamer volumio[510]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:42:18 rpistreamer volumio[510]: *** WARNING *** For more information see Mar 05 01:42:18 rpistreamer node[510]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 05 01:42:18 rpistreamer node[510]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:42:18 rpistreamer node[510]: *** WARNING *** For more information see Mar 05 01:42:18 rpistreamer node[510]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 05 01:42:18 rpistreamer node[510]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:42:18 rpistreamer node[510]: *** WARNING *** For more information see Mar 05 01:42:18 rpistreamer volumio[510]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 05 01:42:18 rpistreamer volumio[510]: info: Discovery: Started advertising with name: RPiStreamer Mar 05 01:42:18 rpistreamer go-librespot[464]: time="2026-03-05T01:42:18+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:18 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 01:42:18 rpistreamer volumio[510]: info: Loading plugin "spop"... Mar 05 01:42:19 rpistreamer go-librespot[464]: time="2026-03-05T01:42:19+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:42:19 rpistreamer go-librespot[464]: time="2026-03-05T01:42:19+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:19 rpistreamer go-librespot[464]: time="2026-03-05T01:42:19+08:00" level=debug msg="completed challenge" Mar 05 01:42:19 rpistreamer volumio[510]: info: Loading plugin "outputs"... Mar 05 01:42:19 rpistreamer volumio[510]: info: Loading plugin "albumart"... Mar 05 01:42:19 rpistreamer volumio[510]: info: Plugin example_plugin is not enabled Mar 05 01:42:19 rpistreamer volumio[510]: info: Loading plugin "inputs"... Mar 05 01:42:19 rpistreamer volumio[510]: info: Loading plugin "updater_comm"... Mar 05 01:42:19 rpistreamer go-librespot[464]: time="2026-03-05T01:42:19+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:19 rpistreamer volumio[510]: info: Plugin mpdemulation is not enabled Mar 05 01:42:19 rpistreamer volumio[510]: info: Loading plugin "rest_api"... Mar 05 01:42:19 rpistreamer volumio[510]: info: Loading plugin "websocket"... Mar 05 01:42:19 rpistreamer volumio[510]: info: Starting Socket.io Server version 1.7.4 Mar 05 01:42:19 rpistreamer volumio[510]: info: Loading plugin "Bluetoothremote"... Mar 05 01:42:19 rpistreamer volumio[510]: info: Applying required configuration parameters for plugin Bluetoothremote Mar 05 01:42:19 rpistreamer volumio[510]: info: Loading i18n strings for locale en Mar 05 01:42:19 rpistreamer volumio[510]: Updating browse sources language Mar 05 01:42:19 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:42:20 rpistreamer volumio[587]: Forking 3 albumart workers Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::initPlayerControls Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: Express server listening on port 3000 Mar 05 01:42:20 rpistreamer volumio[510]: [Metrics] WebUI: 6s 852.58ms Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreStateMachine::resetVolumioState Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreStateMachine::getcurrentVolume Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 01:42:20 rpistreamer volumio[510]: info: Volumio Network Manager: Network status updated: 2 Mar 05 01:42:20 rpistreamer go-librespot[464]: time="2026-03-05T01:42:20+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 05 01:42:20 rpistreamer go-librespot[464]: time="2026-03-05T01:42:20+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:20 rpistreamer go-librespot[464]: time="2026-03-05T01:42:20+08:00" level=debug msg="completed challenge" Mar 05 01:42:20 rpistreamer volumio[510]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreStateMachine::pushState Mar 05 01:42:20 rpistreamer volumio[510]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::volumioPushState Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreStateMachine::updateTrackBlock Mar 05 01:42:20 rpistreamer volumio[510]: info: CorePlayQueue::getTrackBlock Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 01:42:20 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:42:20] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1772646136 101 Mar 05 01:42:20 rpistreamer volumio[510]: 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 Mar 05 01:42:20 rpistreamer go-librespot[464]: time="2026-03-05T01:42:20+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:20 rpistreamer go-librespot[464]: time="2026-03-05T01:42:20+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:20 rpistreamer systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 01:42:20 rpistreamer systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: info: Reloading queue from file Mar 05 01:42:20 rpistreamer volumio[510]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreStateMachine::pushState Mar 05 01:42:20 rpistreamer volumio[510]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::volumioPushState Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreStateMachine::setRepeat true single undefined Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreStateMachine::pushState Mar 05 01:42:20 rpistreamer volumio[510]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::volumioPushState Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreStateMachine::setRandom false Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreStateMachine::pushState Mar 05 01:42:20 rpistreamer volumio[510]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::volumioPushState Mar 05 01:42:20 rpistreamer volumio[510]: info: Setting Device type: Raspberry PI Mar 05 01:42:20 rpistreamer volumio[510]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Mar 05 01:42:20 rpistreamer volumio[510]: info: Completed loading Core Plugins Mar 05 01:42:20 rpistreamer volumio[510]: info: Preparing to generate the ALSA configuration file Mar 05 01:42:20 rpistreamer volumio[510]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 05 01:42:20 rpistreamer volumio[510]: info: Reading ALSA contributions from plugins. Mar 05 01:42:20 rpistreamer volumio[510]: info: Asound.conf file unchanged, so no further update is needed Mar 05 01:42:20 rpistreamer volumio[510]: info: Output device has changed, restarting MPD Mar 05 01:42:20 rpistreamer volumio[510]: info: Output device has changed, restarting Shairport Sync Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:20 rpistreamer sudo[652]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 01:42:20 rpistreamer volumio[510]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 01:42:20 rpistreamer sudo[652]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:20 rpistreamer volumio[510]: info: ___________ START PLUGINS ___________ Mar 05 01:42:20 rpistreamer sudo[652]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:20 rpistreamer sudo[654]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 01:42:20 rpistreamer sudo[654]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:20 rpistreamer volumio[510]: info: ControllerMpd::onStart: Initializing MPD Mar 05 01:42:20 rpistreamer volumio[510]: info: Creating MPD Configuration file Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 01:42:20 rpistreamer volumio[510]: info: [1772646140910] CoreMusicLibrary::Adding element Media Servers Mar 05 01:42:20 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:42:20 rpistreamer volumio[510]: info: UPNP Browser: Client initialized successfully Mar 05 01:42:20 rpistreamer systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 05 01:42:20 rpistreamer sudo[664]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 01:42:20 rpistreamer sudo[664]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:20 rpistreamer sudo[664]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:20 rpistreamer sudo[666]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 01:42:21 rpistreamer sudo[662]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Mar 05 01:42:21 rpistreamer sudo[666]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:21 rpistreamer sudo[662]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:21 rpistreamer systemd[1]: mpd.service: Deactivated successfully. Mar 05 01:42:21 rpistreamer systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 05 01:42:21 rpistreamer systemd[1]: mpd.service: Consumed 3.897s CPU time. Mar 05 01:42:21 rpistreamer systemd[1]: mpd.socket: Deactivated successfully. Mar 05 01:42:21 rpistreamer systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 05 01:42:21 rpistreamer systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 05 01:42:21 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:21 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:21 rpistreamer volumio[510]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 01:42:21 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:21 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:21 rpistreamer systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 05 01:42:21 rpistreamer systemd[1]: Starting mpd.service - Music Player Daemon... Mar 05 01:42:21 rpistreamer volumio[510]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 01:42:21 rpistreamer volumio[510]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 01:42:21 rpistreamer volumio[510]: info: [1772646141142] CoreMusicLibrary::Adding element Last_100 Mar 05 01:42:21 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:42:21 rpistreamer volumio[510]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 01:42:21 rpistreamer volumio[510]: info: [1772646141146] CoreMusicLibrary::Adding element Webradio Mar 05 01:42:21 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:42:21 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 01:42:21 rpistreamer volumio[510]: info: Initializing BBC Radios Mar 05 01:42:21 rpistreamer systemd[1]: mpd.service: Deactivated successfully. Mar 05 01:42:21 rpistreamer systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 05 01:42:21 rpistreamer systemd[1]: mpd.socket: Deactivated successfully. Mar 05 01:42:21 rpistreamer systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 05 01:42:21 rpistreamer systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 05 01:42:21 rpistreamer sudo[662]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:21 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 01:42:21 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:21 rpistreamer volumio[510]: info: Creating Spotify config file Mar 05 01:42:21 rpistreamer systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 05 01:42:21 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:21 rpistreamer systemd[1]: Starting mpd.service - Music Player Daemon... Mar 05 01:42:21 rpistreamer sudo[696]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 05 01:42:21 rpistreamer sudo[696]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 05 01:42:21 rpistreamer sudo[696]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:21 rpistreamer volumio[510]: info: Loading i18n strings for locale en Mar 05 01:42:21 rpistreamer volumio[510]: info: Volumio Calling Home Mar 05 01:42:21 rpistreamer volumio[597]: Starting albumart workers Mar 05 01:42:21 rpistreamer volumio[598]: Starting albumart workers Mar 05 01:42:22 rpistreamer volumio[599]: Starting albumart workers Mar 05 01:42:22 rpistreamer volumio[510]: info: Discovery: adding 7e34c4f0-ee39-441c-99b9-fc337c1a9397 Mar 05 01:42:22 rpistreamer volumio[510]: info: Discovery: Found device RPiStreamer Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::volumioGetState Mar 05 01:42:22 rpistreamer volumio[510]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:22 rpistreamer volumio[510]: info: Discovery: this is already registered, 7e34c4f0-ee39-441c-99b9-fc337c1a9397 Mar 05 01:42:22 rpistreamer volumio[510]: info: Discovery: Found device RPiStreamer Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::volumioGetState Mar 05 01:42:22 rpistreamer volumio[510]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:22 rpistreamer volumio[510]: info: MPD Permissions set Mar 05 01:42:22 rpistreamer volumio[510]: info: MPD Permissions set Mar 05 01:42:22 rpistreamer volumio[510]: info: Volumio called home Mar 05 01:42:22 rpistreamer volumio[510]: info: Spotify config file written Mar 05 01:42:22 rpistreamer sudo[703]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 05 01:42:22 rpistreamer sudo[703]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:22 rpistreamer volumio[510]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 05 01:42:22 rpistreamer systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:42:22 rpistreamer systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:42:22 rpistreamer go-librespot[705]: go-librespot daemon starting... Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer sudo[703]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer go-librespot[706]: time="2026-03-05T01:42:22+08:00" level=info msg="running go-librespot 0.6.2" Mar 05 01:42:22 rpistreamer go-librespot[706]: time="2026-03-05T01:42:22+08:00" level=debug msg="app state loaded" Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer go-librespot[706]: time="2026-03-05T01:42:22+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:22 rpistreamer volumio[510]: info: No need to fix Spotify hosts Mar 05 01:42:22 rpistreamer volumio[510]: info: Starting Shairport Sync Mar 05 01:42:22 rpistreamer volumio[510]: info: Starting Shairport Sync Mar 05 01:42:23 rpistreamer volumio[510]: info: Starting Shairport Sync Mar 05 01:42:23 rpistreamer sudo[735]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 01:42:23 rpistreamer sudo[735]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:23 rpistreamer sudo[737]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 01:42:23 rpistreamer sudo[737]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:23 rpistreamer systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 05 01:42:23 rpistreamer systemd[1]: shairport-sync.service: Deactivated successfully. Mar 05 01:42:23 rpistreamer systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 05 01:42:23 rpistreamer systemd[1]: shairport-sync.service: Consumed 1.958s CPU time. Mar 05 01:42:23 rpistreamer sudo[739]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 01:42:23 rpistreamer sudo[739]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:23 rpistreamer systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 05 01:42:23 rpistreamer sudo[735]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:23 rpistreamer systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 05 01:42:23 rpistreamer systemd[1]: shairport-sync.service: Deactivated successfully. Mar 05 01:42:23 rpistreamer systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 05 01:42:23 rpistreamer systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 05 01:42:23 rpistreamer sudo[737]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:23 rpistreamer systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 05 01:42:23 rpistreamer systemd[1]: shairport-sync.service: Deactivated successfully. Mar 05 01:42:23 rpistreamer systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 05 01:42:23 rpistreamer systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 05 01:42:23 rpistreamer sudo[739]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:23 rpistreamer volumio[510]: info: Shairport-Sync Started Mar 05 01:42:23 rpistreamer volumio[510]: Error adding Membership: Error: addMembership EINVAL Mar 05 01:42:23 rpistreamer volumio[510]: info: Shairport-Sync Started Mar 05 01:42:23 rpistreamer volumio[510]: info: Shairport-Sync Started Mar 05 01:42:23 rpistreamer volumio[510]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 05 01:42:23 rpistreamer go-librespot[706]: time="2026-03-05T01:42:23+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 05 01:42:23 rpistreamer go-librespot[706]: time="2026-03-05T01:42:23+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 05 01:42:23 rpistreamer go-librespot[706]: time="2026-03-05T01:42:23+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 05 01:42:23 rpistreamer go-librespot[706]: time="2026-03-05T01:42:23+08:00" level=info msg="zeroconf server listening on port 46701" Mar 05 01:42:23 rpistreamer volumio[510]: info: CoreCommandRouter::volumioGetState Mar 05 01:42:23 rpistreamer volumio[510]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:25 rpistreamer mpd[698]: 2026-03-05T01:42:25 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 05 01:42:25 rpistreamer systemd[1]: Started mpd.service - Music Player Daemon. Mar 05 01:42:25 rpistreamer sudo[654]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:25 rpistreamer sudo[666]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:25 rpistreamer volumio[510]: info: Completed starting Core Plugins Mar 05 01:42:25 rpistreamer volumio[510]: info: ------------------------------------------- Mar 05 01:42:25 rpistreamer volumio[510]: info: ----- MyVolumio plugins startup ---- Mar 05 01:42:25 rpistreamer volumio[510]: info: ------------------------------------------- Mar 05 01:42:25 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 05 01:42:25 rpistreamer volumio[510]: error: MPD error: The expression evaluated to a falsy value: Mar 05 01:42:25 rpistreamer volumio[510]: assert.ok(self.idling) Mar 05 01:42:25 rpistreamer volumio[510]: error: The expression evaluated to a falsy value: Mar 05 01:42:25 rpistreamer volumio[510]: assert.ok(self.idling) Mar 05 01:42:25 rpistreamer volumio[510]: error: updateQueue error: null Mar 05 01:42:25 rpistreamer volumio[510]: info: MPD running with PID698 Mar 05 01:42:25 rpistreamer volumio[510]: ,establishing connection Mar 05 01:42:25 rpistreamer volumio[510]: error: updateQueue error: null Mar 05 01:42:25 rpistreamer volumio[510]: info: go-librespot daemon successfully initialized Mar 05 01:42:26 rpistreamer sudo[807]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 01:42:26 rpistreamer sudo[807]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:26 rpistreamer sudo[809]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 01:42:26 rpistreamer sudo[807]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:26 rpistreamer sudo[809]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:26 rpistreamer sudo[809]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:26 rpistreamer sudo[812]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 05 01:42:26 rpistreamer sudo[812]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:26 rpistreamer sudo[812]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:26 rpistreamer volumio[510]: info: Upmpdcli Daemon Started Mar 05 01:42:26 rpistreamer go-librespot[706]: time="2026-03-05T01:42:26+08:00" level=debug msg="obtained new client token: AAChWuPiq6/KJQwlzuqId6PaUnlbreu7moH0b2sKMkeW1AYU3mRxU44UaajvHieUWR3fXK4HUExEhMyW3OWXrrkDC47YO5Fap5c8heFAx0Uni2GLvsPNNjgfDik+mB4wPs7H+qKckMsXjSsPsYsMK8k3cmBA2/ikaQo0TtIZh6OZFN1zJsjVkZmQVUqDycLFA/v0fnv4AavofKNVE3SyHPxZ2bBejewKFTBYq7pT0nblpI6Bt4778d0=" Mar 05 01:42:26 rpistreamer go-librespot[706]: time="2026-03-05T01:42:26+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:42:26 rpistreamer go-librespot[706]: time="2026-03-05T01:42:26+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:26 rpistreamer go-librespot[706]: time="2026-03-05T01:42:26+08:00" level=debug msg="completed challenge" Mar 05 01:42:27 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:42:27.073+08:00 level=ERROR msg="failed to update discovery on Wi-Fi info change" error="failed to get system info: could not get system info: context deadline exceeded" Mar 05 01:42:27 rpistreamer go-librespot[706]: time="2026-03-05T01:42:27+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:27 rpistreamer go-librespot[706]: time="2026-03-05T01:42:27+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 05 01:42:28 rpistreamer go-librespot[706]: time="2026-03-05T01:42:28+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:28 rpistreamer go-librespot[706]: time="2026-03-05T01:42:28+08:00" level=debug msg="completed challenge" Mar 05 01:42:28 rpistreamer go-librespot[706]: time="2026-03-05T01:42:28+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:28 rpistreamer volumio[510]: info: Initializing connection to go-librespot Websocket Mar 05 01:42:28 rpistreamer go-librespot[706]: time="2026-03-05T01:42:28+08:00" level=debug msg="new websocket client" Mar 05 01:42:28 rpistreamer volumio[510]: info: Connection to go-librespot Websocket established Mar 05 01:42:29 rpistreamer go-librespot[706]: time="2026-03-05T01:42:29+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.241.202:80: connect: connection refused" Mar 05 01:42:30 rpistreamer go-librespot[706]: time="2026-03-05T01:42:30+08:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 05 01:42:30 rpistreamer go-librespot[706]: time="2026-03-05T01:42:30+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:30 rpistreamer go-librespot[706]: time="2026-03-05T01:42:30+08:00" level=debug msg="completed challenge" Mar 05 01:42:30 rpistreamer go-librespot[706]: time="2026-03-05T01:42:30+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:31 rpistreamer go-librespot[706]: time="2026-03-05T01:42:31+08:00" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 05 01:42:31 rpistreamer go-librespot[706]: time="2026-03-05T01:42:31+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:31 rpistreamer go-librespot[706]: time="2026-03-05T01:42:31+08:00" level=debug msg="completed challenge" Mar 05 01:42:31 rpistreamer volumio[510]: info: Getting Spotify volume Mar 05 01:42:31 rpistreamer volumio[510]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Mar 05 01:42:32 rpistreamer volumio[510]: info: CoreCommandRouter::volumioGetState Mar 05 01:42:32 rpistreamer volumio[510]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:32 rpistreamer volumio[510]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Mar 05 01:42:32 rpistreamer volumio[510]: SPOTIFY: SPOTIFY VOLUME undefined Mar 05 01:42:32 rpistreamer volumio[510]: SPOTIFY: VOLUMIO VOLUME 40 Mar 05 01:42:32 rpistreamer go-librespot[706]: time="2026-03-05T01:42:32+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:32 rpistreamer volumio[510]: info: Aligning Spotify Volume to Volumio Volume Mar 05 01:42:32 rpistreamer volumio[510]: info: CoreCommandRouter::volumioGetState Mar 05 01:42:32 rpistreamer volumio[510]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:32 rpistreamer volumio[510]: info: Setting Spotify Volume from Volumio: 40 Mar 05 01:42:32 rpistreamer go-librespot[706]: time="2026-03-05T01:42:32+08:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 05 01:42:33 rpistreamer go-librespot[706]: time="2026-03-05T01:42:33+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:33 rpistreamer go-librespot[706]: time="2026-03-05T01:42:33+08:00" level=debug msg="completed challenge" Mar 05 01:42:33 rpistreamer volumio[510]: SPOTIFY: SETTING SPOTIFY VOLUME 40 Mar 05 01:42:33 rpistreamer volumio[510]: info: Sending Spotify command with payload to local API: /player/volume Mar 05 01:42:33 rpistreamer volumio[510]: error: Failed to send command to Spotify local API: /player/volume: Error: Bad Request Mar 05 01:42:33 rpistreamer go-librespot[706]: time="2026-03-05T01:42:33+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:34 rpistreamer go-librespot[706]: time="2026-03-05T01:42:34+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Mar 05 01:42:34 rpistreamer go-librespot[706]: time="2026-03-05T01:42:34+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Mar 05 01:42:34 rpistreamer volumio[510]: info: Adding plugin bluetooth to MyMusic Plugins Mar 05 01:42:34 rpistreamer volumio[510]: info: Adding plugin multiroom to MyMusic Plugins Mar 05 01:42:34 rpistreamer volumio[510]: info: Adding plugin metavolumio to MyMusic Plugins Mar 05 01:42:34 rpistreamer volumio[510]: info: Adding plugin cd_controller to MyMusic Plugins Mar 05 01:42:34 rpistreamer volumio[510]: info: Adding plugin qobuzconnect to MyMusic Plugins Mar 05 01:42:34 rpistreamer volumio[510]: info: Adding plugin smart_inputs to MyMusic Plugins Mar 05 01:42:34 rpistreamer volumio[510]: info: Adding plugin tidalconnect to MyMusic Plugins Mar 05 01:42:34 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Mar 05 01:42:34 rpistreamer go-librespot[706]: time="2026-03-05T01:42:34+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:34 rpistreamer go-librespot[706]: time="2026-03-05T01:42:34+08:00" level=debug msg="completed challenge" Mar 05 01:42:35 rpistreamer go-librespot[706]: time="2026-03-05T01:42:35+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:35 rpistreamer go-librespot[706]: time="2026-03-05T01:42:35+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:35 rpistreamer systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 01:42:35 rpistreamer systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 01:42:35 rpistreamer volumio[510]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Mar 05 01:42:35 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Mar 05 01:42:35 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:35 rpistreamer volumio[510]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:35 rpistreamer volumio[510]: info: Starting MyVolumio Remote Streaming Endpoints Mar 05 01:42:35 rpistreamer volumio[510]: info: MyVolumio login type: Token Mar 05 01:42:35 rpistreamer volumio[510]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Mar 05 01:42:35 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Mar 05 01:42:36 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Mar 05 01:42:36 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Mar 05 01:42:36 rpistreamer volumio[510]: info: Streaming services startup Mar 05 01:42:36 rpistreamer volumio[510]: info: Starting Streaming Daemon Mar 05 01:42:36 rpistreamer sudo[831]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 05 01:42:36 rpistreamer sudo[831]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:36 rpistreamer volumio[510]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Mar 05 01:42:36 rpistreamer sudo[831]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:36 rpistreamer volumio[510]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 01:42:36 rpistreamer volumio[510]: Error: socket hang up Mar 05 01:42:36 rpistreamer volumio[510]: at connResetException (node:internal/errors:720:14) Mar 05 01:42:36 rpistreamer volumio[510]: at Socket.socketOnEnd (node:_http_client:519:23) Mar 05 01:42:36 rpistreamer volumio[510]: at Socket.emit (node:events:526:35) Mar 05 01:42:36 rpistreamer volumio[510]: at endReadableNT (node:internal/streams/readable:1376:12) Mar 05 01:42:36 rpistreamer volumio[510]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Mar 05 01:42:36 rpistreamer volumio[510]: code: 'ECONNRESET', Mar 05 01:42:36 rpistreamer volumio[510]: response: undefined Mar 05 01:42:36 rpistreamer volumio[510]: } Mar 05 01:42:36 rpistreamer volumio[510]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 01:42:37 rpistreamer sudo[856]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-05 01:41' Mar 05 01:42:37 rpistreamer sudo[856]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:37 rpistreamer sudo[856]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:37 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:42:37.772+08:00 level=ERROR msg="failed reading message" component=volumio/socket error="websocket: close 1006 (abnormal closure): unexpected EOF" Mar 05 01:42:37 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:42:37.774+08:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 05 01:42:37 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:42:37] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Mar 05 01:42:37 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:42:37] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Mar 05 01:42:37 rpistreamer systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 05 01:42:37 rpistreamer systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 05 01:42:37 rpistreamer systemd[1]: volumio.service: Consumed 26.466s CPU time. Mar 05 01:42:37 rpistreamer systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 05 01:42:37 rpistreamer systemd[1]: dynamicswap.service: Deactivated successfully. Mar 05 01:42:38 rpistreamer systemd[1]: volumio.service: Scheduled restart job, restart counter is at 584. Mar 05 01:42:38 rpistreamer systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 05 01:42:38 rpistreamer systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 05 01:42:38 rpistreamer systemd[1]: volumio.service: Consumed 26.466s CPU time. Mar 05 01:42:38 rpistreamer systemd[1]: Started volumio.service - Volumio Backend Module. Mar 05 01:42:38 rpistreamer systemd[1]: dynamicswap.service: Deactivated successfully. Mar 05 01:42:38 rpistreamer systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Mar 05 01:42:38 rpistreamer systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:42:38 rpistreamer systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:42:38 rpistreamer go-librespot[887]: go-librespot daemon starting... Mar 05 01:42:38 rpistreamer go-librespot[888]: time="2026-03-05T01:42:38+08:00" level=info msg="running go-librespot 0.6.2" Mar 05 01:42:38 rpistreamer go-librespot[888]: time="2026-03-05T01:42:38+08:00" level=debug msg="app state loaded" Mar 05 01:42:38 rpistreamer go-librespot[888]: time="2026-03-05T01:42:38+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 05 01:42:38 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:42:38.776+08:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 05 01:42:38 rpistreamer go-librespot[888]: time="2026-03-05T01:42:38+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 05 01:42:38 rpistreamer go-librespot[888]: time="2026-03-05T01:42:38+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 05 01:42:38 rpistreamer go-librespot[888]: time="2026-03-05T01:42:38+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 05 01:42:38 rpistreamer go-librespot[888]: time="2026-03-05T01:42:38+08:00" level=info msg="zeroconf server listening on port 41239" Mar 05 01:42:39 rpistreamer go-librespot[888]: time="2026-03-05T01:42:39+08:00" level=debug msg="obtained new client token: AADT+RDcUIPOkKOzZxhJEGmTZpVbwXjSIFRUA2S9oZJ5ILFi1wqCchvS+xFJ3vWCd3CgDeB3aNqbhujGdpLqJjVwbXYt5JAEann8h0ZIIoGHlKc2EvVdHaES7kdypaepxnTMVZylX2f37a0ONd/fy95Lhc3evz8+bx64BxbClQPhO6ajpA5umJBQzMVidIiKrElrcxv7P0GAmeL5BBPp+Nq5NAUcXhXYdAW7qwzVblAyq1kdbSDRxogp8Q==" Mar 05 01:42:39 rpistreamer go-librespot[888]: time="2026-03-05T01:42:39+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:42:39 rpistreamer go-librespot[888]: time="2026-03-05T01:42:39+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:39 rpistreamer go-librespot[888]: time="2026-03-05T01:42:39+08:00" level=debug msg="completed challenge" Mar 05 01:42:40 rpistreamer volumio[868]: info: ------------------------------------------- Mar 05 01:42:40 rpistreamer volumio[868]: info: ----- Volumio3 ---- Mar 05 01:42:40 rpistreamer volumio[868]: info: ------------------------------------------- Mar 05 01:42:40 rpistreamer volumio[868]: info: ----- System startup ---- Mar 05 01:42:40 rpistreamer volumio[868]: info: ------------------------------------------- Mar 05 01:42:40 rpistreamer go-librespot[888]: time="2026-03-05T01:42:40+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:40 rpistreamer go-librespot[888]: time="2026-03-05T01:42:40+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 05 01:42:40 rpistreamer volumio[868]: info: MYVOLUMIO Environment detected Mar 05 01:42:40 rpistreamer go-librespot[888]: time="2026-03-05T01:42:40+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:40 rpistreamer go-librespot[888]: time="2026-03-05T01:42:40+08:00" level=debug msg="completed challenge" Mar 05 01:42:40 rpistreamer volumio[868]: info: Plugin folders cleanup Mar 05 01:42:40 rpistreamer volumio[868]: info: Scanning into folder /volumio/app/plugins/ Mar 05 01:42:40 rpistreamer volumio[868]: info: Scanning category audio_interface Mar 05 01:42:40 rpistreamer volumio[868]: info: Scanning category miscellanea Mar 05 01:42:40 rpistreamer volumio[868]: info: Scanning category music_service Mar 05 01:42:40 rpistreamer volumio[868]: info: Scanning category plugins.json Mar 05 01:42:40 rpistreamer volumio[868]: info: Scanning category system_controller Mar 05 01:42:40 rpistreamer volumio[868]: info: Scanning category user_interface Mar 05 01:42:40 rpistreamer volumio[868]: info: Scanning into folder /data/plugins/ Mar 05 01:42:40 rpistreamer volumio[868]: info: Scanning category music_service Mar 05 01:42:40 rpistreamer volumio[868]: info: Scanning category system_hardware Mar 05 01:42:40 rpistreamer volumio[868]: info: Plugin folders cleanup completed Mar 05 01:42:40 rpistreamer volumio[868]: info: ------------------------------------------- Mar 05 01:42:40 rpistreamer volumio[868]: info: ----- Core plugins startup ---- Mar 05 01:42:40 rpistreamer volumio[868]: info: ------------------------------------------- Mar 05 01:42:40 rpistreamer volumio[868]: info: Loading plugins from folder /volumio/app/plugins/ Mar 05 01:42:40 rpistreamer volumio[868]: info: Adding plugin upnp to MyMusic Plugins Mar 05 01:42:40 rpistreamer volumio[868]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 05 01:42:40 rpistreamer volumio[868]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 05 01:42:40 rpistreamer volumio[868]: info: Loading plugins from folder /data/plugins/ Mar 05 01:42:40 rpistreamer volumio[868]: info: Loading plugin "system"... Mar 05 01:42:41 rpistreamer volumio[868]: info: Loading plugin "appearance"... Mar 05 01:42:41 rpistreamer go-librespot[888]: time="2026-03-05T01:42:41+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:41 rpistreamer go-librespot[888]: time="2026-03-05T01:42:41+08:00" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 05 01:42:42 rpistreamer volumio[868]: info: Loading plugin "network"... Mar 05 01:42:42 rpistreamer volumio[868]: info: Refreshing Cached IP Addresses Mar 05 01:42:42 rpistreamer sudo[910]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 01:42:42 rpistreamer sudo[910]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:42 rpistreamer sudo[912]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 01:42:42 rpistreamer volumio[868]: info: Loading plugin "services"... Mar 05 01:42:42 rpistreamer sudo[912]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:42 rpistreamer sudo[910]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:42 rpistreamer volumio[868]: info: Loading plugin "volumio5onboarding"... Mar 05 01:42:42 rpistreamer sudo[912]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:42 rpistreamer volumio[868]: info: Loading plugin "alsa_controller"... Mar 05 01:42:42 rpistreamer sudo[921]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 05 01:42:42 rpistreamer sudo[921]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:42 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 01:42:42 rpistreamer volumio[868]: info: Loading plugin "wizard"... Mar 05 01:42:42 rpistreamer volumio[868]: info: Loading plugin "networkfs"... Mar 05 01:42:42 rpistreamer volumio[868]: info: Starting Udev Watcher for removable devices Mar 05 01:42:42 rpistreamer volumio[868]: info: Ignoring mount for partition: boot Mar 05 01:42:42 rpistreamer volumio[868]: info: Ignoring mount for partition: volumio Mar 05 01:42:42 rpistreamer volumio[868]: info: Ignoring mount for partition: volumio_data Mar 05 01:42:42 rpistreamer volumio[868]: info: Mounting Device 689E-A36F Mar 05 01:42:42 rpistreamer sudo[957]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/689E-A36F -o noatime Mar 05 01:42:42 rpistreamer sudo[957]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:42 rpistreamer sudo[957]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:42 rpistreamer volumio[868]: mount: /media/689E-A36F: /dev/sda1 already mounted on /media/689E-A36F. Mar 05 01:42:42 rpistreamer volumio[868]: dmesg(1) may have more information after failed mount system call. Mar 05 01:42:42 rpistreamer volumio[868]: error: Failed to mount 689E-A36F: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/689E-A36F" -o noatime Mar 05 01:42:42 rpistreamer volumio[868]: mount: /media/689E-A36F: /dev/sda1 already mounted on /media/689E-A36F. Mar 05 01:42:42 rpistreamer volumio[868]: dmesg(1) may have more information after failed mount system call. Mar 05 01:42:42 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 01:42:42 rpistreamer volumio[868]: info: Loading plugin "volumio_command_line_client"... Mar 05 01:42:42 rpistreamer volumio[868]: info: Loading plugin "upnp"... Mar 05 01:42:42 rpistreamer volumio[868]: info: [1772646162396] Starting Upmpd Daemon Mar 05 01:42:42 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 01:42:42 rpistreamer volumio[868]: info: Loading plugin "my_music"... Mar 05 01:42:42 rpistreamer volumio[868]: info: Loading plugin "mpd"... Mar 05 01:42:42 rpistreamer go-librespot[888]: time="2026-03-05T01:42:42+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:42 rpistreamer go-librespot[888]: time="2026-03-05T01:42:42+08:00" level=debug msg="completed challenge" Mar 05 01:42:42 rpistreamer volumio[868]: info: Loading plugin "upnp_browser"... Mar 05 01:42:42 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:42:42] [connect] Successful connection Mar 05 01:42:42 rpistreamer sudo[921]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:43 rpistreamer go-librespot[888]: time="2026-03-05T01:42:43+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:44 rpistreamer go-librespot[888]: time="2026-03-05T01:42:44+08:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Mar 05 01:42:44 rpistreamer volumio[868]: info: Starting UPNP Browser Mar 05 01:42:44 rpistreamer volumio[868]: info: Loading plugin "alarm-clock"... Mar 05 01:42:44 rpistreamer volumio[868]: info: Loading plugin "airplay_emulation"... Mar 05 01:42:44 rpistreamer volumio[868]: info: Starting Shairport Sync Mar 05 01:42:44 rpistreamer volumio[868]: info: Loading plugin "last_100"... Mar 05 01:42:44 rpistreamer volumio[868]: info: Loading plugin "webradio"... Mar 05 01:42:44 rpistreamer volumio[868]: info: Loading plugin "i2s_dacs"... Mar 05 01:42:44 rpistreamer volumio[868]: info: Loading plugin "volumiodiscovery"... Mar 05 01:42:44 rpistreamer volumio[868]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 05 01:42:44 rpistreamer volumio[868]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:42:44 rpistreamer volumio[868]: *** WARNING *** For more information see Mar 05 01:42:44 rpistreamer volumio[868]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 05 01:42:44 rpistreamer volumio[868]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:42:44 rpistreamer volumio[868]: *** WARNING *** For more information see Mar 05 01:42:44 rpistreamer node[868]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 05 01:42:44 rpistreamer node[868]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:42:44 rpistreamer node[868]: *** WARNING *** For more information see Mar 05 01:42:44 rpistreamer node[868]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 05 01:42:44 rpistreamer node[868]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:42:44 rpistreamer node[868]: *** WARNING *** For more information see Mar 05 01:42:44 rpistreamer volumio[868]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 05 01:42:44 rpistreamer volumio[868]: info: Discovery: Started advertising with name: RPiStreamer Mar 05 01:42:44 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 01:42:44 rpistreamer volumio[868]: info: Loading plugin "spop"... Mar 05 01:42:44 rpistreamer go-librespot[888]: time="2026-03-05T01:42:44+08:00" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 05 01:42:45 rpistreamer go-librespot[888]: time="2026-03-05T01:42:45+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:45 rpistreamer go-librespot[888]: time="2026-03-05T01:42:45+08:00" level=debug msg="completed challenge" Mar 05 01:42:45 rpistreamer go-librespot[888]: time="2026-03-05T01:42:45+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:45 rpistreamer volumio[868]: info: Loading plugin "outputs"... Mar 05 01:42:45 rpistreamer volumio[868]: info: Loading plugin "albumart"... Mar 05 01:42:45 rpistreamer volumio[868]: info: Plugin example_plugin is not enabled Mar 05 01:42:45 rpistreamer volumio[868]: info: Loading plugin "inputs"... Mar 05 01:42:45 rpistreamer volumio[868]: info: Loading plugin "updater_comm"... Mar 05 01:42:45 rpistreamer volumio[868]: info: Plugin mpdemulation is not enabled Mar 05 01:42:45 rpistreamer volumio[868]: info: Loading plugin "rest_api"... Mar 05 01:42:45 rpistreamer volumio[868]: info: Loading plugin "websocket"... Mar 05 01:42:45 rpistreamer volumio[868]: info: Starting Socket.io Server version 1.7.4 Mar 05 01:42:45 rpistreamer volumio[868]: info: Loading plugin "Bluetoothremote"... Mar 05 01:42:46 rpistreamer volumio[868]: info: Applying required configuration parameters for plugin Bluetoothremote Mar 05 01:42:46 rpistreamer volumio[868]: info: Loading i18n strings for locale en Mar 05 01:42:46 rpistreamer volumio[868]: Updating browse sources language Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:42:46 rpistreamer go-librespot[888]: time="2026-03-05T01:42:46+08:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 05 01:42:46 rpistreamer volumio[962]: Forking 3 albumart workers Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::initPlayerControls Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 01:42:46 rpistreamer volumio[868]: Express server listening on port 3000 Mar 05 01:42:46 rpistreamer volumio[868]: [Metrics] WebUI: 6s 815.91ms Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreStateMachine::resetVolumioState Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreStateMachine::getcurrentVolume Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 01:42:46 rpistreamer volumio[868]: info: Volumio Network Manager: Network status updated: 2 Mar 05 01:42:46 rpistreamer volumio[868]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreStateMachine::pushState Mar 05 01:42:46 rpistreamer volumio[868]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::volumioPushState Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreStateMachine::updateTrackBlock Mar 05 01:42:46 rpistreamer volumio[868]: info: CorePlayQueue::getTrackBlock Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 01:42:46 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:42:46] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1772646162 101 Mar 05 01:42:46 rpistreamer volumio[868]: 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 Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:46 rpistreamer volumio[868]: info: Reloading queue from file Mar 05 01:42:46 rpistreamer volumio[868]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreStateMachine::pushState Mar 05 01:42:46 rpistreamer volumio[868]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::volumioPushState Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreStateMachine::setRepeat true single undefined Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreStateMachine::pushState Mar 05 01:42:46 rpistreamer volumio[868]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::volumioPushState Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreStateMachine::setRandom false Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreStateMachine::pushState Mar 05 01:42:46 rpistreamer volumio[868]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::volumioPushState Mar 05 01:42:46 rpistreamer volumio[868]: info: Setting Device type: Raspberry PI Mar 05 01:42:46 rpistreamer volumio[868]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Mar 05 01:42:46 rpistreamer volumio[868]: info: Received Get System Info Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 05 01:42:46 rpistreamer volumio[868]: info: Discovery: Getting this device information Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::volumioGetState Mar 05 01:42:46 rpistreamer volumio[868]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:46 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 05 01:42:46 rpistreamer volumio[868]: info: Completed loading Core Plugins Mar 05 01:42:46 rpistreamer volumio[868]: info: Preparing to generate the ALSA configuration file Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 05 01:42:47 rpistreamer volumio[868]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 05 01:42:47 rpistreamer volumio[868]: info: Reading ALSA contributions from plugins. Mar 05 01:42:47 rpistreamer volumio[868]: info: Asound.conf file unchanged, so no further update is needed Mar 05 01:42:47 rpistreamer volumio[868]: info: Output device has changed, restarting MPD Mar 05 01:42:47 rpistreamer go-librespot[888]: time="2026-03-05T01:42:47+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:47 rpistreamer go-librespot[888]: time="2026-03-05T01:42:47+08:00" level=debug msg="completed challenge" Mar 05 01:42:47 rpistreamer volumio[868]: info: Output device has changed, restarting Shairport Sync Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:47 rpistreamer sudo[1026]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 01:42:47 rpistreamer sudo[1028]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 01:42:47 rpistreamer sudo[1026]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:47 rpistreamer sudo[1028]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:47 rpistreamer sudo[1026]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:47 rpistreamer volumio[868]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 01:42:47 rpistreamer volumio[868]: info: ___________ START PLUGINS ___________ Mar 05 01:42:47 rpistreamer volumio[868]: info: ControllerMpd::onStart: Initializing MPD Mar 05 01:42:47 rpistreamer systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 05 01:42:47 rpistreamer volumio[868]: info: Creating MPD Configuration file Mar 05 01:42:47 rpistreamer sudo[1037]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Mar 05 01:42:47 rpistreamer sudo[1037]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 01:42:47 rpistreamer systemd[1]: mpd.service: Deactivated successfully. Mar 05 01:42:47 rpistreamer volumio[868]: info: [1772646167295] CoreMusicLibrary::Adding element Media Servers Mar 05 01:42:47 rpistreamer systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 05 01:42:47 rpistreamer sudo[1040]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 01:42:47 rpistreamer systemd[1]: mpd.service: Consumed 3.909s CPU time. Mar 05 01:42:47 rpistreamer sudo[1040]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:47 rpistreamer systemd[1]: mpd.socket: Deactivated successfully. Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:42:47 rpistreamer systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 05 01:42:47 rpistreamer sudo[1040]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:47 rpistreamer go-librespot[888]: time="2026-03-05T01:42:47+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:47 rpistreamer systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 05 01:42:47 rpistreamer sudo[1042]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 01:42:47 rpistreamer volumio[868]: info: UPNP Browser: Client initialized successfully Mar 05 01:42:47 rpistreamer sudo[1042]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:47 rpistreamer systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 05 01:42:47 rpistreamer systemd[1]: Starting mpd.service - Music Player Daemon... Mar 05 01:42:47 rpistreamer volumio[868]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:47 rpistreamer systemd[1]: mpd.service: Deactivated successfully. Mar 05 01:42:47 rpistreamer systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 05 01:42:47 rpistreamer sudo[1037]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:47 rpistreamer systemd[1]: mpd.socket: Deactivated successfully. Mar 05 01:42:47 rpistreamer systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 05 01:42:47 rpistreamer systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 05 01:42:47 rpistreamer systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 05 01:42:47 rpistreamer volumio[868]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 01:42:47 rpistreamer volumio[868]: info: [1772646167514] CoreMusicLibrary::Adding element Last_100 Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:42:47 rpistreamer systemd[1]: Starting mpd.service - Music Player Daemon... Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 01:42:47 rpistreamer volumio[868]: info: [1772646167528] CoreMusicLibrary::Adding element Webradio Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 01:42:47 rpistreamer volumio[868]: info: Initializing BBC Radios Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:47 rpistreamer volumio[868]: info: Creating Spotify config file Mar 05 01:42:47 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:47 rpistreamer sudo[1058]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 05 01:42:47 rpistreamer sudo[1058]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 05 01:42:47 rpistreamer sudo[1058]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:47 rpistreamer go-librespot[888]: time="2026-03-05T01:42:47+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:42:48 rpistreamer go-librespot[888]: time="2026-03-05T01:42:48+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:48 rpistreamer go-librespot[888]: time="2026-03-05T01:42:48+08:00" level=debug msg="completed challenge" Mar 05 01:42:48 rpistreamer volumio[975]: Starting albumart workers Mar 05 01:42:48 rpistreamer go-librespot[888]: time="2026-03-05T01:42:48+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:48 rpistreamer go-librespot[888]: time="2026-03-05T01:42:48+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:48 rpistreamer volumio[973]: Starting albumart workers Mar 05 01:42:48 rpistreamer systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 01:42:48 rpistreamer systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 01:42:48 rpistreamer volumio[974]: Starting albumart workers Mar 05 01:42:48 rpistreamer volumio[868]: info: Loading i18n strings for locale en Mar 05 01:42:48 rpistreamer volumio[868]: info: Volumio Calling Home Mar 05 01:42:49 rpistreamer volumio[868]: info: Discovery: adding 7e34c4f0-ee39-441c-99b9-fc337c1a9397 Mar 05 01:42:49 rpistreamer volumio[868]: info: Discovery: Found device RPiStreamer Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::volumioGetState Mar 05 01:42:49 rpistreamer volumio[868]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:49 rpistreamer volumio[868]: info: Discovery: this is already registered, 7e34c4f0-ee39-441c-99b9-fc337c1a9397 Mar 05 01:42:49 rpistreamer volumio[868]: info: Discovery: Found device RPiStreamer Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::volumioGetState Mar 05 01:42:49 rpistreamer volumio[868]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:49 rpistreamer volumio[868]: info: MPD Permissions set Mar 05 01:42:49 rpistreamer volumio[868]: info: MPD Permissions set Mar 05 01:42:49 rpistreamer volumio[868]: info: Spotify config file written Mar 05 01:42:49 rpistreamer volumio[868]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer sudo[1097]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 05 01:42:49 rpistreamer sudo[1097]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:42:49 rpistreamer volumio[868]: info: No need to fix Spotify hosts Mar 05 01:42:49 rpistreamer systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:42:49 rpistreamer go-librespot[1109]: go-librespot daemon starting... Mar 05 01:42:49 rpistreamer sudo[1097]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:49 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:49+08:00" level=info msg="running go-librespot 0.6.2" Mar 05 01:42:49 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:49+08:00" level=debug msg="app state loaded" Mar 05 01:42:49 rpistreamer volumio[868]: info: Starting Shairport Sync Mar 05 01:42:49 rpistreamer volumio[868]: info: Starting Shairport Sync Mar 05 01:42:49 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:49+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 05 01:42:49 rpistreamer volumio[868]: info: Starting Shairport Sync Mar 05 01:42:49 rpistreamer sudo[1125]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 01:42:49 rpistreamer sudo[1125]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:49 rpistreamer sudo[1127]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 01:42:49 rpistreamer sudo[1127]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:49 rpistreamer sudo[1131]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 01:42:49 rpistreamer sudo[1131]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:49 rpistreamer systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 05 01:42:49 rpistreamer systemd[1]: shairport-sync.service: Deactivated successfully. Mar 05 01:42:49 rpistreamer systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 05 01:42:49 rpistreamer systemd[1]: shairport-sync.service: Consumed 1.807s CPU time. Mar 05 01:42:49 rpistreamer volumio[868]: info: Volumio called home Mar 05 01:42:49 rpistreamer systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 05 01:42:49 rpistreamer sudo[1125]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:49 rpistreamer sudo[1131]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:49 rpistreamer sudo[1127]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:49 rpistreamer volumio[868]: info: Shairport-Sync Started Mar 05 01:42:49 rpistreamer volumio[868]: Error adding Membership: Error: addMembership EINVAL Mar 05 01:42:49 rpistreamer volumio[868]: info: Shairport-Sync Started Mar 05 01:42:49 rpistreamer volumio[868]: info: Shairport-Sync Started Mar 05 01:42:49 rpistreamer volumio[868]: info: CoreCommandRouter::volumioGetState Mar 05 01:42:49 rpistreamer volumio[868]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:50 rpistreamer volumio[868]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 05 01:42:51 rpistreamer mpd[1079]: 2026-03-05T01:42:51 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 05 01:42:51 rpistreamer systemd[1]: Started mpd.service - Music Player Daemon. Mar 05 01:42:51 rpistreamer sudo[1028]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:51 rpistreamer sudo[1042]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:51 rpistreamer volumio[868]: info: Completed starting Core Plugins Mar 05 01:42:51 rpistreamer volumio[868]: info: ------------------------------------------- Mar 05 01:42:51 rpistreamer volumio[868]: info: ----- MyVolumio plugins startup ---- Mar 05 01:42:51 rpistreamer volumio[868]: info: ------------------------------------------- Mar 05 01:42:51 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 05 01:42:51 rpistreamer volumio[868]: error: MPD error: The expression evaluated to a falsy value: Mar 05 01:42:51 rpistreamer volumio[868]: assert.ok(self.idling) Mar 05 01:42:51 rpistreamer volumio[868]: error: The expression evaluated to a falsy value: Mar 05 01:42:51 rpistreamer volumio[868]: assert.ok(self.idling) Mar 05 01:42:51 rpistreamer volumio[868]: info: MPD running with PID1079 Mar 05 01:42:51 rpistreamer volumio[868]: ,establishing connection Mar 05 01:42:51 rpistreamer volumio[868]: error: updateQueue error: null Mar 05 01:42:51 rpistreamer volumio[868]: error: updateQueue error: null Mar 05 01:42:51 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:51+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 05 01:42:51 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:51+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 05 01:42:51 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:51+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 05 01:42:51 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:51+08:00" level=info msg="zeroconf server listening on port 39007" Mar 05 01:42:52 rpistreamer sudo[1170]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 01:42:52 rpistreamer sudo[1170]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:52 rpistreamer sudo[1172]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 01:42:52 rpistreamer sudo[1172]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:52 rpistreamer sudo[1170]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:52 rpistreamer sudo[1172]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:52 rpistreamer sudo[1174]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 05 01:42:52 rpistreamer sudo[1174]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:42:52 rpistreamer sudo[1174]: pam_unix(sudo:session): session closed for user root Mar 05 01:42:52 rpistreamer volumio[868]: info: Upmpdcli Daemon Started Mar 05 01:42:52 rpistreamer volumio[868]: info: go-librespot daemon successfully initialized Mar 05 01:42:53 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:53+08:00" level=debug msg="obtained new client token: AAB0BzBqFwa7Ykx09dITST2eXR8v0qwozzVcvgaxQh5crbtCpPl3r8VIKJB3//NeGZ0f4lbml+UfOBCJTjqcFBXpVSz7PPqs3hSzw0hXRkbeBDVgG1L+L0zcW8Q3en0GL+x4EbFz0JETjgZttlsX8P1mqcKndNDk4AZdFj5OicP/8JhrYdYIXqv1srti982fa1ggFogzxx/IBlpb065H9d6/pbNyPwi+BH5GGq58mpI+bs6E7kddihTdcw==" Mar 05 01:42:53 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:53+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:42:54 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:54+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Mar 05 01:42:54 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:54+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 05 01:42:54 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:54+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:54 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:54+08:00" level=debug msg="completed challenge" Mar 05 01:42:55 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:55+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:55 rpistreamer volumio[868]: info: Initializing connection to go-librespot Websocket Mar 05 01:42:55 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:55+08:00" level=debug msg="new websocket client" Mar 05 01:42:55 rpistreamer volumio[868]: info: Connection to go-librespot Websocket established Mar 05 01:42:55 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:55+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.241.202:80: connect: connection refused" Mar 05 01:42:56 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:56+08:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 05 01:42:56 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:56+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:56 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:56+08:00" level=debug msg="completed challenge" Mar 05 01:42:56 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:56+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:57 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:57+08:00" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 05 01:42:57 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:57+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:57 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:57+08:00" level=debug msg="completed challenge" Mar 05 01:42:58 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:58+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:42:58 rpistreamer volumio[868]: info: Getting Spotify volume Mar 05 01:42:58 rpistreamer volumio[868]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Mar 05 01:42:58 rpistreamer volumio[868]: info: CoreCommandRouter::volumioGetState Mar 05 01:42:58 rpistreamer volumio[868]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:58 rpistreamer volumio[868]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Mar 05 01:42:58 rpistreamer volumio[868]: SPOTIFY: SPOTIFY VOLUME undefined Mar 05 01:42:58 rpistreamer volumio[868]: SPOTIFY: VOLUMIO VOLUME 40 Mar 05 01:42:58 rpistreamer volumio[868]: info: Aligning Spotify Volume to Volumio Volume Mar 05 01:42:58 rpistreamer volumio[868]: info: CoreCommandRouter::volumioGetState Mar 05 01:42:58 rpistreamer volumio[868]: info: CorePlayQueue::getTrack 0 Mar 05 01:42:58 rpistreamer volumio[868]: info: Setting Spotify Volume from Volumio: 40 Mar 05 01:42:59 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:59+08:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 05 01:42:59 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:59+08:00" level=debug msg="completed keyexchange" Mar 05 01:42:59 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:59+08:00" level=debug msg="completed challenge" Mar 05 01:42:59 rpistreamer go-librespot[1111]: time="2026-03-05T01:42:59+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:00 rpistreamer volumio[868]: SPOTIFY: SETTING SPOTIFY VOLUME 40 Mar 05 01:43:00 rpistreamer volumio[868]: info: Sending Spotify command with payload to local API: /player/volume Mar 05 01:43:00 rpistreamer volumio[868]: error: Failed to send command to Spotify local API: /player/volume: Error: Bad Request Mar 05 01:43:00 rpistreamer go-librespot[1111]: time="2026-03-05T01:43:00+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:43:00 rpistreamer go-librespot[1111]: time="2026-03-05T01:43:00+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:00 rpistreamer go-librespot[1111]: time="2026-03-05T01:43:00+08:00" level=debug msg="completed challenge" Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Mar 05 01:43:00 rpistreamer volumio[868]: info: Adding plugin bluetooth to MyMusic Plugins Mar 05 01:43:00 rpistreamer volumio[868]: info: Adding plugin multiroom to MyMusic Plugins Mar 05 01:43:00 rpistreamer volumio[868]: info: Adding plugin metavolumio to MyMusic Plugins Mar 05 01:43:00 rpistreamer volumio[868]: info: Adding plugin cd_controller to MyMusic Plugins Mar 05 01:43:00 rpistreamer volumio[868]: info: Adding plugin qobuzconnect to MyMusic Plugins Mar 05 01:43:00 rpistreamer volumio[868]: info: Adding plugin smart_inputs to MyMusic Plugins Mar 05 01:43:00 rpistreamer volumio[868]: info: Adding plugin tidalconnect to MyMusic Plugins Mar 05 01:43:00 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Mar 05 01:43:00 rpistreamer go-librespot[1111]: time="2026-03-05T01:43:00+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:00 rpistreamer go-librespot[1111]: time="2026-03-05T01:43:00+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:00 rpistreamer systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 01:43:00 rpistreamer systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 01:43:01 rpistreamer volumio[868]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Mar 05 01:43:01 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Mar 05 01:43:01 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:01 rpistreamer volumio[868]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:01 rpistreamer volumio[868]: info: Starting MyVolumio Remote Streaming Endpoints Mar 05 01:43:01 rpistreamer volumio[868]: info: MyVolumio login type: Token Mar 05 01:43:01 rpistreamer volumio[868]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Mar 05 01:43:01 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Mar 05 01:43:02 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Mar 05 01:43:02 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Mar 05 01:43:02 rpistreamer volumio[868]: info: Streaming services startup Mar 05 01:43:02 rpistreamer volumio[868]: info: Starting Streaming Daemon Mar 05 01:43:02 rpistreamer sudo[1193]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Mar 05 01:43:02 rpistreamer sudo[1193]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:02 rpistreamer volumio[868]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Mar 05 01:43:02 rpistreamer sudo[1193]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:02 rpistreamer volumio[868]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 01:43:02 rpistreamer volumio[868]: Error: socket hang up Mar 05 01:43:02 rpistreamer volumio[868]: at connResetException (node:internal/errors:720:14) Mar 05 01:43:02 rpistreamer volumio[868]: at Socket.socketOnEnd (node:_http_client:519:23) Mar 05 01:43:02 rpistreamer volumio[868]: at Socket.emit (node:events:526:35) Mar 05 01:43:02 rpistreamer volumio[868]: at endReadableNT (node:internal/streams/readable:1376:12) Mar 05 01:43:02 rpistreamer volumio[868]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Mar 05 01:43:02 rpistreamer volumio[868]: code: 'ECONNRESET', Mar 05 01:43:02 rpistreamer volumio[868]: response: undefined Mar 05 01:43:02 rpistreamer volumio[868]: } Mar 05 01:43:02 rpistreamer volumio[868]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 01:43:03 rpistreamer sudo[1215]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-05 01:42' Mar 05 01:43:03 rpistreamer sudo[1215]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:03 rpistreamer sudo[1215]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:03 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:43:03] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Mar 05 01:43:03 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:43:03] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Mar 05 01:43:03 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:43:03.634+08:00 level=ERROR msg="failed reading message" component=volumio/socket error="websocket: close 1006 (abnormal closure): unexpected EOF" Mar 05 01:43:03 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:43:03.636+08:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 05 01:43:03 rpistreamer systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 05 01:43:03 rpistreamer systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Mar 05 01:43:03 rpistreamer systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:43:03 rpistreamer systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:43:03 rpistreamer go-librespot[1220]: go-librespot daemon starting... Mar 05 01:43:03 rpistreamer systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 05 01:43:03 rpistreamer systemd[1]: volumio.service: Consumed 26.344s CPU time. Mar 05 01:43:03 rpistreamer systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 05 01:43:03 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:03+08:00" level=info msg="running go-librespot 0.6.2" Mar 05 01:43:03 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:03+08:00" level=debug msg="app state loaded" Mar 05 01:43:03 rpistreamer systemd[1]: dynamicswap.service: Deactivated successfully. Mar 05 01:43:03 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:03+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 05 01:43:04 rpistreamer systemd[1]: volumio.service: Scheduled restart job, restart counter is at 585. Mar 05 01:43:04 rpistreamer systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 05 01:43:04 rpistreamer systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 05 01:43:04 rpistreamer systemd[1]: volumio.service: Consumed 26.344s CPU time. Mar 05 01:43:04 rpistreamer systemd[1]: Started volumio.service - Volumio Backend Module. Mar 05 01:43:04 rpistreamer systemd[1]: dynamicswap.service: Deactivated successfully. Mar 05 01:43:04 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:04+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 05 01:43:04 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:04+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 05 01:43:04 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:04+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 05 01:43:04 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:04+08:00" level=info msg="zeroconf server listening on port 34751" Mar 05 01:43:04 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:43:04.638+08:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 05 01:43:05 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:05+08:00" level=debug msg="obtained new client token: AACPiW/hsMp7gQG4MW3jiwCgDMU+BhZFeahCC1FpK5QkrwlyqL7/YljT5LPrUCqBC4I3QOBcIDqe055qygyVc51/XDTYMKpAW7GkXhLMtKjptgpblAG9LGMuQq0qDnZzqyP1ZY6bWppRnK9SBt/wLXrt1PD0YP8D5CeYiCLJw0ZvEIVTzlEI7l7zmNa7RsMZHTdQvs4p93eQZ+u+gZHSGcuQNS4Bpp3qbPwxD2EFI1P9hRyDvkrA+e4=" Mar 05 01:43:05 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:05+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:43:05 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:05+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:05 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:05+08:00" level=debug msg="completed challenge" Mar 05 01:43:05 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:05+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:06 rpistreamer volumio[1239]: info: ------------------------------------------- Mar 05 01:43:06 rpistreamer volumio[1239]: info: ----- Volumio3 ---- Mar 05 01:43:06 rpistreamer volumio[1239]: info: ------------------------------------------- Mar 05 01:43:06 rpistreamer volumio[1239]: info: ----- System startup ---- Mar 05 01:43:06 rpistreamer volumio[1239]: info: ------------------------------------------- Mar 05 01:43:06 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:06+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 05 01:43:06 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:06+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:06 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:06+08:00" level=debug msg="completed challenge" Mar 05 01:43:06 rpistreamer volumio[1239]: info: MYVOLUMIO Environment detected Mar 05 01:43:06 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:06+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:06 rpistreamer volumio[1239]: info: Plugin folders cleanup Mar 05 01:43:06 rpistreamer volumio[1239]: info: Scanning into folder /volumio/app/plugins/ Mar 05 01:43:06 rpistreamer volumio[1239]: info: Scanning category audio_interface Mar 05 01:43:06 rpistreamer volumio[1239]: info: Scanning category miscellanea Mar 05 01:43:06 rpistreamer volumio[1239]: info: Scanning category music_service Mar 05 01:43:06 rpistreamer volumio[1239]: info: Scanning category plugins.json Mar 05 01:43:06 rpistreamer volumio[1239]: info: Scanning category system_controller Mar 05 01:43:06 rpistreamer volumio[1239]: info: Scanning category user_interface Mar 05 01:43:06 rpistreamer volumio[1239]: info: Scanning into folder /data/plugins/ Mar 05 01:43:06 rpistreamer volumio[1239]: info: Scanning category music_service Mar 05 01:43:06 rpistreamer volumio[1239]: info: Scanning category system_hardware Mar 05 01:43:06 rpistreamer volumio[1239]: info: Plugin folders cleanup completed Mar 05 01:43:06 rpistreamer volumio[1239]: info: ------------------------------------------- Mar 05 01:43:06 rpistreamer volumio[1239]: info: ----- Core plugins startup ---- Mar 05 01:43:06 rpistreamer volumio[1239]: info: ------------------------------------------- Mar 05 01:43:06 rpistreamer volumio[1239]: info: Loading plugins from folder /volumio/app/plugins/ Mar 05 01:43:06 rpistreamer volumio[1239]: info: Adding plugin upnp to MyMusic Plugins Mar 05 01:43:06 rpistreamer volumio[1239]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 05 01:43:06 rpistreamer volumio[1239]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 05 01:43:06 rpistreamer volumio[1239]: info: Loading plugins from folder /data/plugins/ Mar 05 01:43:06 rpistreamer volumio[1239]: info: Loading plugin "system"... Mar 05 01:43:07 rpistreamer volumio[1239]: info: Loading plugin "appearance"... Mar 05 01:43:07 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:07+08:00" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 05 01:43:07 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:07+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:07 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:07+08:00" level=debug msg="completed challenge" Mar 05 01:43:07 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:07+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:08 rpistreamer volumio[1239]: info: Loading plugin "network"... Mar 05 01:43:08 rpistreamer volumio[1239]: info: Refreshing Cached IP Addresses Mar 05 01:43:08 rpistreamer sudo[1267]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 01:43:08 rpistreamer sudo[1267]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:08 rpistreamer sudo[1267]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:08 rpistreamer sudo[1269]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 01:43:08 rpistreamer sudo[1269]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:08 rpistreamer volumio[1239]: info: Loading plugin "services"... Mar 05 01:43:08 rpistreamer sudo[1269]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:08 rpistreamer volumio[1239]: info: Loading plugin "volumio5onboarding"... Mar 05 01:43:08 rpistreamer sudo[1279]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 05 01:43:08 rpistreamer sudo[1279]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:08 rpistreamer volumio[1239]: info: Loading plugin "alsa_controller"... Mar 05 01:43:08 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 01:43:08 rpistreamer volumio[1239]: info: Loading plugin "wizard"... Mar 05 01:43:08 rpistreamer volumio[1239]: info: Loading plugin "networkfs"... Mar 05 01:43:08 rpistreamer volumio[1239]: info: Starting Udev Watcher for removable devices Mar 05 01:43:08 rpistreamer volumio[1239]: info: Ignoring mount for partition: boot Mar 05 01:43:08 rpistreamer volumio[1239]: info: Ignoring mount for partition: volumio Mar 05 01:43:08 rpistreamer volumio[1239]: info: Ignoring mount for partition: volumio_data Mar 05 01:43:08 rpistreamer volumio[1239]: info: Mounting Device 689E-A36F Mar 05 01:43:08 rpistreamer sudo[1306]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/689E-A36F -o noatime Mar 05 01:43:08 rpistreamer sudo[1306]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:08 rpistreamer sudo[1306]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:08 rpistreamer volumio[1239]: mount: /media/689E-A36F: /dev/sda1 already mounted on /media/689E-A36F. Mar 05 01:43:08 rpistreamer volumio[1239]: dmesg(1) may have more information after failed mount system call. Mar 05 01:43:08 rpistreamer volumio[1239]: error: Failed to mount 689E-A36F: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/689E-A36F" -o noatime Mar 05 01:43:08 rpistreamer volumio[1239]: mount: /media/689E-A36F: /dev/sda1 already mounted on /media/689E-A36F. Mar 05 01:43:08 rpistreamer volumio[1239]: dmesg(1) may have more information after failed mount system call. Mar 05 01:43:08 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 01:43:08 rpistreamer volumio[1239]: info: Loading plugin "volumio_command_line_client"... Mar 05 01:43:08 rpistreamer volumio[1239]: info: Loading plugin "upnp"... Mar 05 01:43:08 rpistreamer volumio[1239]: info: [1772646188424] Starting Upmpd Daemon Mar 05 01:43:08 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 01:43:08 rpistreamer volumio[1239]: info: Loading plugin "my_music"... Mar 05 01:43:08 rpistreamer volumio[1239]: info: Loading plugin "mpd"... Mar 05 01:43:08 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:43:08] [connect] Successful connection Mar 05 01:43:08 rpistreamer volumio[1239]: info: Loading plugin "upnp_browser"... Mar 05 01:43:08 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:08+08:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Mar 05 01:43:08 rpistreamer sudo[1279]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:09 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:09+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:09 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:09+08:00" level=debug msg="completed challenge" Mar 05 01:43:09 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:09+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:10 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:10+08:00" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 05 01:43:10 rpistreamer volumio[1239]: info: Starting UPNP Browser Mar 05 01:43:10 rpistreamer volumio[1239]: info: Loading plugin "alarm-clock"... Mar 05 01:43:10 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:10+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:10 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:10+08:00" level=debug msg="completed challenge" Mar 05 01:43:10 rpistreamer volumio[1239]: info: Loading plugin "airplay_emulation"... Mar 05 01:43:10 rpistreamer volumio[1239]: info: Starting Shairport Sync Mar 05 01:43:10 rpistreamer volumio[1239]: info: Loading plugin "last_100"... Mar 05 01:43:10 rpistreamer volumio[1239]: info: Loading plugin "webradio"... Mar 05 01:43:10 rpistreamer volumio[1239]: info: Loading plugin "i2s_dacs"... Mar 05 01:43:10 rpistreamer volumio[1239]: info: Loading plugin "volumiodiscovery"... Mar 05 01:43:10 rpistreamer volumio[1239]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 05 01:43:10 rpistreamer volumio[1239]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:43:10 rpistreamer volumio[1239]: *** WARNING *** For more information see Mar 05 01:43:10 rpistreamer volumio[1239]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 05 01:43:10 rpistreamer volumio[1239]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:43:10 rpistreamer volumio[1239]: *** WARNING *** For more information see Mar 05 01:43:10 rpistreamer node[1239]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 05 01:43:10 rpistreamer node[1239]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:43:10 rpistreamer node[1239]: *** WARNING *** For more information see Mar 05 01:43:10 rpistreamer node[1239]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 05 01:43:10 rpistreamer node[1239]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:43:10 rpistreamer node[1239]: *** WARNING *** For more information see Mar 05 01:43:10 rpistreamer volumio[1239]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 05 01:43:10 rpistreamer volumio[1239]: info: Discovery: Started advertising with name: RPiStreamer Mar 05 01:43:10 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 01:43:10 rpistreamer volumio[1239]: info: Loading plugin "spop"... Mar 05 01:43:10 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:10+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:11 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:11+08:00" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 05 01:43:11 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:11+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Mar 05 01:43:11 rpistreamer go-librespot[1223]: time="2026-03-05T01:43:11+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Mar 05 01:43:11 rpistreamer systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 01:43:11 rpistreamer systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 01:43:11 rpistreamer volumio[1239]: info: Loading plugin "outputs"... Mar 05 01:43:11 rpistreamer volumio[1239]: info: Loading plugin "albumart"... Mar 05 01:43:11 rpistreamer volumio[1239]: info: Plugin example_plugin is not enabled Mar 05 01:43:11 rpistreamer volumio[1239]: info: Loading plugin "inputs"... Mar 05 01:43:11 rpistreamer volumio[1239]: info: Loading plugin "updater_comm"... Mar 05 01:43:11 rpistreamer volumio[1239]: info: Plugin mpdemulation is not enabled Mar 05 01:43:11 rpistreamer volumio[1239]: info: Loading plugin "rest_api"... Mar 05 01:43:12 rpistreamer volumio[1239]: info: Loading plugin "websocket"... Mar 05 01:43:12 rpistreamer volumio[1239]: info: Starting Socket.io Server version 1.7.4 Mar 05 01:43:12 rpistreamer volumio[1239]: info: Loading plugin "Bluetoothremote"... Mar 05 01:43:12 rpistreamer volumio[1239]: info: Applying required configuration parameters for plugin Bluetoothremote Mar 05 01:43:12 rpistreamer volumio[1239]: info: Loading i18n strings for locale en Mar 05 01:43:12 rpistreamer volumio[1239]: Updating browse sources language Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:43:12 rpistreamer volumio[1310]: Forking 3 albumart workers Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::initPlayerControls Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 01:43:12 rpistreamer volumio[1239]: Express server listening on port 3000 Mar 05 01:43:12 rpistreamer volumio[1239]: [Metrics] WebUI: 6s 914.02ms Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreStateMachine::resetVolumioState Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreStateMachine::getcurrentVolume Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 01:43:12 rpistreamer volumio[1239]: info: Volumio Network Manager: Network status updated: 2 Mar 05 01:43:12 rpistreamer volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreStateMachine::pushState Mar 05 01:43:12 rpistreamer volumio[1239]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioPushState Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreStateMachine::updateTrackBlock Mar 05 01:43:12 rpistreamer volumio[1239]: info: CorePlayQueue::getTrackBlock Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 01:43:12 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:43:12] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1772646188 101 Mar 05 01:43:12 rpistreamer volumio[1239]: 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 Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:12 rpistreamer volumio[1239]: info: Reloading queue from file Mar 05 01:43:12 rpistreamer volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreStateMachine::setRepeat true single undefined Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreStateMachine::pushState Mar 05 01:43:12 rpistreamer volumio[1239]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioPushState Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreStateMachine::setRandom false Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreStateMachine::pushState Mar 05 01:43:12 rpistreamer volumio[1239]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioPushState Mar 05 01:43:12 rpistreamer volumio[1239]: info: Setting Device type: Raspberry PI Mar 05 01:43:12 rpistreamer volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2 Mar 05 01:43:12 rpistreamer volumio[1239]: info: Received Get System Info Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 05 01:43:12 rpistreamer volumio[1239]: info: Discovery: Getting this device information Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioGetState Mar 05 01:43:12 rpistreamer volumio[1239]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:12 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 05 01:43:13 rpistreamer volumio[1239]: info: Completed loading Core Plugins Mar 05 01:43:13 rpistreamer volumio[1239]: info: Preparing to generate the ALSA configuration file Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreStateMachine::pushState Mar 05 01:43:13 rpistreamer volumio[1239]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioPushState Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 05 01:43:13 rpistreamer volumio[1239]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 05 01:43:13 rpistreamer volumio[1239]: info: Reading ALSA contributions from plugins. Mar 05 01:43:13 rpistreamer volumio[1239]: info: Asound.conf file unchanged, so no further update is needed Mar 05 01:43:13 rpistreamer volumio[1239]: info: Output device has changed, restarting MPD Mar 05 01:43:13 rpistreamer volumio[1239]: info: Output device has changed, restarting Shairport Sync Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:13 rpistreamer sudo[1377]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 01:43:13 rpistreamer sudo[1377]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:13 rpistreamer sudo[1379]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 01:43:13 rpistreamer sudo[1379]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:13 rpistreamer sudo[1377]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:13 rpistreamer volumio[1239]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 01:43:13 rpistreamer volumio[1239]: info: ___________ START PLUGINS ___________ Mar 05 01:43:13 rpistreamer systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 05 01:43:13 rpistreamer volumio[1239]: info: ControllerMpd::onStart: Initializing MPD Mar 05 01:43:13 rpistreamer volumio[1239]: info: Creating MPD Configuration file Mar 05 01:43:13 rpistreamer systemd[1]: mpd.service: Deactivated successfully. Mar 05 01:43:13 rpistreamer systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 05 01:43:13 rpistreamer systemd[1]: mpd.service: Consumed 3.929s CPU time. Mar 05 01:43:13 rpistreamer systemd[1]: mpd.socket: Deactivated successfully. Mar 05 01:43:13 rpistreamer systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 05 01:43:13 rpistreamer systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 01:43:13 rpistreamer volumio[1239]: info: [1772646193367] CoreMusicLibrary::Adding element Media Servers Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:43:13 rpistreamer sudo[1389]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 01:43:13 rpistreamer sudo[1389]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:13 rpistreamer sudo[1387]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Mar 05 01:43:13 rpistreamer sudo[1387]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:13 rpistreamer sudo[1389]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:13 rpistreamer sudo[1391]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 01:43:13 rpistreamer sudo[1391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:13 rpistreamer systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 05 01:43:13 rpistreamer systemd[1]: Starting mpd.service - Music Player Daemon... Mar 05 01:43:13 rpistreamer volumio[1239]: info: UPNP Browser: Client initialized successfully Mar 05 01:43:13 rpistreamer systemd[1]: mpd.service: Deactivated successfully. Mar 05 01:43:13 rpistreamer systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:13 rpistreamer systemd[1]: mpd.socket: Deactivated successfully. Mar 05 01:43:13 rpistreamer sudo[1387]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:13 rpistreamer systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 05 01:43:13 rpistreamer systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 05 01:43:13 rpistreamer systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 05 01:43:13 rpistreamer systemd[1]: Starting mpd.service - Music Player Daemon... Mar 05 01:43:13 rpistreamer volumio[1239]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:13 rpistreamer volumio[1239]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 01:43:13 rpistreamer volumio[1239]: info: [1772646193610] CoreMusicLibrary::Adding element Last_100 Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 01:43:13 rpistreamer volumio[1239]: info: [1772646193624] CoreMusicLibrary::Adding element Webradio Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 01:43:13 rpistreamer volumio[1239]: info: Initializing BBC Radios Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:13 rpistreamer volumio[1239]: info: Creating Spotify config file Mar 05 01:43:13 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:13 rpistreamer sudo[1402]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 05 01:43:13 rpistreamer sudo[1402]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 05 01:43:13 rpistreamer sudo[1402]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:14 rpistreamer volumio[1321]: Starting albumart workers Mar 05 01:43:14 rpistreamer volumio[1323]: Starting albumart workers Mar 05 01:43:14 rpistreamer volumio[1239]: info: Loading i18n strings for locale en Mar 05 01:43:14 rpistreamer volumio[1239]: info: Volumio Calling Home Mar 05 01:43:14 rpistreamer volumio[1324]: Starting albumart workers Mar 05 01:43:14 rpistreamer volumio[1239]: info: Discovery: adding 7e34c4f0-ee39-441c-99b9-fc337c1a9397 Mar 05 01:43:14 rpistreamer volumio[1239]: info: Discovery: Found device RPiStreamer Mar 05 01:43:14 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioGetState Mar 05 01:43:14 rpistreamer volumio[1239]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:14 rpistreamer volumio[1239]: info: Discovery: this is already registered, 7e34c4f0-ee39-441c-99b9-fc337c1a9397 Mar 05 01:43:14 rpistreamer volumio[1239]: info: Discovery: Found device RPiStreamer Mar 05 01:43:14 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioGetState Mar 05 01:43:14 rpistreamer volumio[1239]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:14 rpistreamer volumio[1239]: info: MPD Permissions set Mar 05 01:43:14 rpistreamer volumio[1239]: info: MPD Permissions set Mar 05 01:43:14 rpistreamer volumio[1239]: info: Spotify config file written Mar 05 01:43:15 rpistreamer systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Mar 05 01:43:15 rpistreamer systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:43:15 rpistreamer sudo[1426]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 05 01:43:15 rpistreamer sudo[1426]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:15 rpistreamer systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:43:15 rpistreamer go-librespot[1427]: go-librespot daemon starting... Mar 05 01:43:15 rpistreamer systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 05 01:43:15 rpistreamer volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 05 01:43:15 rpistreamer systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 05 01:43:15 rpistreamer systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:43:15 rpistreamer systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:43:15 rpistreamer go-librespot[1441]: go-librespot daemon starting... Mar 05 01:43:15 rpistreamer sudo[1426]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:15+08:00" level=info msg="running go-librespot 0.6.2" Mar 05 01:43:15 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:15+08:00" level=debug msg="app state loaded" Mar 05 01:43:15 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:15+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:15 rpistreamer volumio[1239]: info: No need to fix Spotify hosts Mar 05 01:43:15 rpistreamer volumio[1239]: info: Volumio called home Mar 05 01:43:15 rpistreamer volumio[1239]: info: Starting Shairport Sync Mar 05 01:43:15 rpistreamer volumio[1239]: info: Starting Shairport Sync Mar 05 01:43:15 rpistreamer volumio[1239]: info: Starting Shairport Sync Mar 05 01:43:15 rpistreamer sudo[1469]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 01:43:15 rpistreamer sudo[1469]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:15 rpistreamer sudo[1470]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 01:43:15 rpistreamer sudo[1470]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:15 rpistreamer sudo[1473]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 01:43:15 rpistreamer sudo[1473]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:15 rpistreamer systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 05 01:43:15 rpistreamer systemd[1]: shairport-sync.service: Deactivated successfully. Mar 05 01:43:15 rpistreamer systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 05 01:43:15 rpistreamer systemd[1]: shairport-sync.service: Consumed 1.848s CPU time. Mar 05 01:43:15 rpistreamer volumio[1239]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 05 01:43:15 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioGetState Mar 05 01:43:15 rpistreamer volumio[1239]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:15 rpistreamer systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 05 01:43:15 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:15+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 05 01:43:15 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:15+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 05 01:43:15 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:15+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 05 01:43:15 rpistreamer sudo[1469]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:15 rpistreamer sudo[1473]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:15 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:15+08:00" level=info msg="zeroconf server listening on port 33381" Mar 05 01:43:15 rpistreamer sudo[1470]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:15 rpistreamer volumio[1239]: info: Shairport-Sync Started Mar 05 01:43:15 rpistreamer volumio[1239]: Error adding Membership: Error: addMembership EINVAL Mar 05 01:43:15 rpistreamer volumio[1239]: info: Shairport-Sync Started Mar 05 01:43:15 rpistreamer volumio[1239]: info: Shairport-Sync Started Mar 05 01:43:16 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:16+08:00" level=debug msg="obtained new client token: AADQW4FNvOCl4eIwIs/BVeNSKbaWMYXrNgr2j5Hc/kAGrphbgTk17gs6f1JC9C+NKOY0PhmLqMuqY1sAo1OzJ0vqmZfUmC6+jUf8hzb333s2q2F4iSmhwM3kRKKp/484bpKUgXV2M5ba5Rg97Sj1IkLWu4Urun8lOVh9Iw8OT9KcT9cj3fN2F0LAfl7FJ1fbE/m2zFa+PwcKyJRlcr8YhEXmEa1SxsGOGqXie466Q8mO1IVU3s25D5lEHA==" Mar 05 01:43:17 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:17+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:43:17 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:17+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:17 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:17+08:00" level=debug msg="completed challenge" Mar 05 01:43:17 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:17+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:17 rpistreamer mpd[1421]: 2026-03-05T01:43:17 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 05 01:43:17 rpistreamer systemd[1]: Started mpd.service - Music Player Daemon. Mar 05 01:43:17 rpistreamer sudo[1379]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:17 rpistreamer sudo[1391]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:17 rpistreamer volumio[1239]: info: Completed starting Core Plugins Mar 05 01:43:17 rpistreamer volumio[1239]: info: ------------------------------------------- Mar 05 01:43:17 rpistreamer volumio[1239]: info: ----- MyVolumio plugins startup ---- Mar 05 01:43:17 rpistreamer volumio[1239]: info: ------------------------------------------- Mar 05 01:43:17 rpistreamer volumio[1239]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 05 01:43:17 rpistreamer volumio[1239]: error: MPD error: The expression evaluated to a falsy value: Mar 05 01:43:17 rpistreamer volumio[1239]: assert.ok(self.idling) Mar 05 01:43:17 rpistreamer volumio[1239]: error: The expression evaluated to a falsy value: Mar 05 01:43:17 rpistreamer volumio[1239]: assert.ok(self.idling) Mar 05 01:43:17 rpistreamer volumio[1239]: error: updateQueue error: null Mar 05 01:43:17 rpistreamer volumio[1239]: info: MPD running with PID1421 Mar 05 01:43:17 rpistreamer volumio[1239]: ,establishing connection Mar 05 01:43:17 rpistreamer volumio[1239]: error: updateQueue error: null Mar 05 01:43:18 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:18+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 05 01:43:18 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:18+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:18 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:18+08:00" level=debug msg="completed challenge" Mar 05 01:43:18 rpistreamer sudo[1517]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 01:43:18 rpistreamer sudo[1517]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:18 rpistreamer sudo[1517]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:18 rpistreamer sudo[1519]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 01:43:18 rpistreamer sudo[1519]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:18 rpistreamer sudo[1519]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:18 rpistreamer sudo[1522]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 05 01:43:18 rpistreamer sudo[1522]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:18 rpistreamer sudo[1522]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:18 rpistreamer volumio[1239]: info: Upmpdcli Daemon Started Mar 05 01:43:18 rpistreamer volumio[1239]: info: go-librespot daemon successfully initialized Mar 05 01:43:18 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:18+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:19 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:19+08:00" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 05 01:43:19 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:19+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:19 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:19+08:00" level=debug msg="completed challenge" Mar 05 01:43:19 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:19+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:20 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:20+08:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Mar 05 01:43:20 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:20+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:20 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:20+08:00" level=debug msg="completed challenge" Mar 05 01:43:21 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:21+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:21 rpistreamer volumio[1239]: info: Initializing connection to go-librespot Websocket Mar 05 01:43:21 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:21+08:00" level=debug msg="new websocket client" Mar 05 01:43:21 rpistreamer volumio[1239]: info: Connection to go-librespot Websocket established Mar 05 01:43:23 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:23+08:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.65.9:443: connect: connection refused" Mar 05 01:43:23 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:23+08:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 05 01:43:24 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:24+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:24 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:24+08:00" level=debug msg="completed challenge" Mar 05 01:43:24 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:24+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:24 rpistreamer volumio[1239]: info: Getting Spotify volume Mar 05 01:43:24 rpistreamer volumio[1239]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Mar 05 01:43:24 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioGetState Mar 05 01:43:24 rpistreamer volumio[1239]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:24 rpistreamer volumio[1239]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Mar 05 01:43:24 rpistreamer volumio[1239]: SPOTIFY: SPOTIFY VOLUME undefined Mar 05 01:43:24 rpistreamer volumio[1239]: SPOTIFY: VOLUMIO VOLUME 40 Mar 05 01:43:24 rpistreamer volumio[1239]: info: Aligning Spotify Volume to Volumio Volume Mar 05 01:43:24 rpistreamer volumio[1239]: info: CoreCommandRouter::volumioGetState Mar 05 01:43:24 rpistreamer volumio[1239]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:24 rpistreamer volumio[1239]: info: Setting Spotify Volume from Volumio: 40 Mar 05 01:43:24 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:24+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:43:25 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:25+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:25 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:25+08:00" level=debug msg="completed challenge" Mar 05 01:43:25 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:25+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:25 rpistreamer go-librespot[1442]: time="2026-03-05T01:43:25+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:25 rpistreamer systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 01:43:25 rpistreamer systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 01:43:25 rpistreamer volumio[1239]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 01:43:25 rpistreamer volumio[1239]: Error: socket hang up Mar 05 01:43:25 rpistreamer volumio[1239]: at connResetException (node:internal/errors:720:14) Mar 05 01:43:25 rpistreamer volumio[1239]: at Socket.socketOnEnd (node:_http_client:519:23) Mar 05 01:43:25 rpistreamer volumio[1239]: at Socket.emit (node:events:526:35) Mar 05 01:43:25 rpistreamer volumio[1239]: at endReadableNT (node:internal/streams/readable:1376:12) Mar 05 01:43:25 rpistreamer volumio[1239]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Mar 05 01:43:25 rpistreamer volumio[1239]: code: 'ECONNRESET', Mar 05 01:43:25 rpistreamer volumio[1239]: response: undefined Mar 05 01:43:25 rpistreamer volumio[1239]: } Mar 05 01:43:25 rpistreamer volumio[1239]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 01:43:26 rpistreamer sudo[1540]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-05 01:42' Mar 05 01:43:26 rpistreamer sudo[1540]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:26 rpistreamer sudo[1540]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:26 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:43:26] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Mar 05 01:43:26 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:43:26] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Mar 05 01:43:26 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:43:26.452+08:00 level=ERROR msg="failed reading message" component=volumio/socket error="websocket: close 1006 (abnormal closure): unexpected EOF" Mar 05 01:43:26 rpistreamer systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 05 01:43:26 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:43:26.455+08:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 05 01:43:26 rpistreamer systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 05 01:43:26 rpistreamer systemd[1]: volumio.service: Consumed 23.444s CPU time. Mar 05 01:43:26 rpistreamer systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 05 01:43:26 rpistreamer systemd[1]: dynamicswap.service: Deactivated successfully. Mar 05 01:43:26 rpistreamer systemd[1]: volumio.service: Scheduled restart job, restart counter is at 586. Mar 05 01:43:26 rpistreamer systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 05 01:43:26 rpistreamer systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 05 01:43:26 rpistreamer systemd[1]: volumio.service: Consumed 23.444s CPU time. Mar 05 01:43:26 rpistreamer systemd[1]: Started volumio.service - Volumio Backend Module. Mar 05 01:43:26 rpistreamer systemd[1]: dynamicswap.service: Deactivated successfully. Mar 05 01:43:27 rpistreamer volumio5-onboarding[28929]: time=2026-03-05T01:43:27.459+08:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 05 01:43:28 rpistreamer systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 05 01:43:28 rpistreamer systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:43:28 rpistreamer systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:43:28 rpistreamer go-librespot[1567]: go-librespot daemon starting... Mar 05 01:43:28 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:28+08:00" level=info msg="running go-librespot 0.6.2" Mar 05 01:43:28 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:28+08:00" level=debug msg="app state loaded" Mar 05 01:43:28 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:28+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 05 01:43:28 rpistreamer volumio[1552]: info: ------------------------------------------- Mar 05 01:43:28 rpistreamer volumio[1552]: info: ----- Volumio3 ---- Mar 05 01:43:28 rpistreamer volumio[1552]: info: ------------------------------------------- Mar 05 01:43:28 rpistreamer volumio[1552]: info: ----- System startup ---- Mar 05 01:43:28 rpistreamer volumio[1552]: info: ------------------------------------------- Mar 05 01:43:29 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:29+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 05 01:43:29 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:29+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 05 01:43:29 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:29+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 05 01:43:29 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:29+08:00" level=info msg="zeroconf server listening on port 38051" Mar 05 01:43:29 rpistreamer volumio[1552]: info: MYVOLUMIO Environment detected Mar 05 01:43:29 rpistreamer volumio[1552]: info: Plugin folders cleanup Mar 05 01:43:29 rpistreamer volumio[1552]: info: Scanning into folder /volumio/app/plugins/ Mar 05 01:43:29 rpistreamer volumio[1552]: info: Scanning category audio_interface Mar 05 01:43:29 rpistreamer volumio[1552]: info: Scanning category miscellanea Mar 05 01:43:29 rpistreamer volumio[1552]: info: Scanning category music_service Mar 05 01:43:29 rpistreamer volumio[1552]: info: Scanning category plugins.json Mar 05 01:43:29 rpistreamer volumio[1552]: info: Scanning category system_controller Mar 05 01:43:29 rpistreamer volumio[1552]: info: Scanning category user_interface Mar 05 01:43:29 rpistreamer volumio[1552]: info: Scanning into folder /data/plugins/ Mar 05 01:43:29 rpistreamer volumio[1552]: info: Scanning category music_service Mar 05 01:43:29 rpistreamer volumio[1552]: info: Scanning category system_hardware Mar 05 01:43:29 rpistreamer volumio[1552]: info: Plugin folders cleanup completed Mar 05 01:43:29 rpistreamer volumio[1552]: info: ------------------------------------------- Mar 05 01:43:29 rpistreamer volumio[1552]: info: ----- Core plugins startup ---- Mar 05 01:43:29 rpistreamer volumio[1552]: info: ------------------------------------------- Mar 05 01:43:29 rpistreamer volumio[1552]: info: Loading plugins from folder /volumio/app/plugins/ Mar 05 01:43:29 rpistreamer volumio[1552]: info: Adding plugin upnp to MyMusic Plugins Mar 05 01:43:29 rpistreamer volumio[1552]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 05 01:43:29 rpistreamer volumio[1552]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 05 01:43:29 rpistreamer volumio[1552]: info: Loading plugins from folder /data/plugins/ Mar 05 01:43:29 rpistreamer volumio[1552]: info: Loading plugin "system"... Mar 05 01:43:29 rpistreamer volumio[1552]: info: Loading plugin "appearance"... Mar 05 01:43:29 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:29+08:00" level=debug msg="obtained new client token: AADIQZ3mG4mAsKEYgfs4expBpem6OaSxaIEqFTLviWGKRdDK4VRtwZKAJcww5PSQ3D6S02aifK9svVpXe8Tv6KktKUhfYmoJ4TztO31C0LqUwyRNSpYmJclx5hhHYY1oTBDALDhV0VgehVa6j5SuHB5bBzRAhETQuRL2X7FFynQ66s+YmjPjdXosx9XSyTd8A84AIsoqr9Sf0GA3ucQq1An9g/o1U1HTCCrS1xuJbX6IZbchwqxt718S6g==" Mar 05 01:43:30 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:30+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:43:30 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:30+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:30 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:30+08:00" level=debug msg="completed challenge" Mar 05 01:43:30 rpistreamer volumio[1552]: info: Loading plugin "network"... Mar 05 01:43:30 rpistreamer volumio[1552]: info: Refreshing Cached IP Addresses Mar 05 01:43:30 rpistreamer sudo[1596]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 01:43:30 rpistreamer sudo[1596]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:30 rpistreamer sudo[1598]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 01:43:30 rpistreamer sudo[1598]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:30 rpistreamer sudo[1596]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:30 rpistreamer volumio[1552]: info: Loading plugin "services"... Mar 05 01:43:30 rpistreamer sudo[1598]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:30 rpistreamer volumio[1552]: info: Loading plugin "volumio5onboarding"... Mar 05 01:43:30 rpistreamer sudo[1606]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 05 01:43:30 rpistreamer sudo[1606]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:30 rpistreamer volumio[1552]: info: Loading plugin "alsa_controller"... Mar 05 01:43:31 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 01:43:31 rpistreamer volumio[1552]: info: Loading plugin "wizard"... Mar 05 01:43:31 rpistreamer volumio[1552]: info: Loading plugin "networkfs"... Mar 05 01:43:31 rpistreamer volumio[1552]: info: Starting Udev Watcher for removable devices Mar 05 01:43:31 rpistreamer volumio[1552]: info: Ignoring mount for partition: boot Mar 05 01:43:31 rpistreamer volumio[1552]: info: Ignoring mount for partition: volumio Mar 05 01:43:31 rpistreamer volumio[1552]: info: Ignoring mount for partition: volumio_data Mar 05 01:43:31 rpistreamer volumio[1552]: info: Mounting Device 689E-A36F Mar 05 01:43:31 rpistreamer sudo[1633]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/689E-A36F -o noatime Mar 05 01:43:31 rpistreamer sudo[1633]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:31 rpistreamer sudo[1633]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:31 rpistreamer volumio[1552]: mount: /media/689E-A36F: /dev/sda1 already mounted on /media/689E-A36F. Mar 05 01:43:31 rpistreamer volumio[1552]: dmesg(1) may have more information after failed mount system call. Mar 05 01:43:31 rpistreamer volumio[1552]: error: Failed to mount 689E-A36F: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/689E-A36F" -o noatime Mar 05 01:43:31 rpistreamer volumio[1552]: mount: /media/689E-A36F: /dev/sda1 already mounted on /media/689E-A36F. Mar 05 01:43:31 rpistreamer volumio[1552]: dmesg(1) may have more information after failed mount system call. Mar 05 01:43:31 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 01:43:31 rpistreamer volumio[1552]: info: Loading plugin "volumio_command_line_client"... Mar 05 01:43:31 rpistreamer volumio[1552]: info: Loading plugin "upnp"... Mar 05 01:43:31 rpistreamer volumio[1552]: info: [1772646211173] Starting Upmpd Daemon Mar 05 01:43:31 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 01:43:31 rpistreamer volumio[1552]: info: Loading plugin "my_music"... Mar 05 01:43:31 rpistreamer volumio[1552]: info: Loading plugin "mpd"... Mar 05 01:43:31 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:43:31] [connect] Successful connection Mar 05 01:43:31 rpistreamer volumio[1552]: info: Loading plugin "upnp_browser"... Mar 05 01:43:31 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:31+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:31 rpistreamer sudo[1606]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:32 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:32+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 05 01:43:32 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:32+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:32 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:32+08:00" level=debug msg="completed challenge" Mar 05 01:43:32 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:32+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:33 rpistreamer volumio[1552]: info: Starting UPNP Browser Mar 05 01:43:33 rpistreamer volumio[1552]: info: Loading plugin "alarm-clock"... Mar 05 01:43:33 rpistreamer volumio[1552]: info: Loading plugin "airplay_emulation"... Mar 05 01:43:33 rpistreamer volumio[1552]: info: Starting Shairport Sync Mar 05 01:43:33 rpistreamer volumio[1552]: info: Loading plugin "last_100"... Mar 05 01:43:33 rpistreamer volumio[1552]: info: Loading plugin "webradio"... Mar 05 01:43:33 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:33+08:00" level=debug msg="connected to ap-gae2.spotify.com:80" Mar 05 01:43:33 rpistreamer volumio[1552]: info: Loading plugin "i2s_dacs"... Mar 05 01:43:33 rpistreamer volumio[1552]: info: Loading plugin "volumiodiscovery"... Mar 05 01:43:33 rpistreamer volumio[1552]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 05 01:43:33 rpistreamer volumio[1552]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:43:33 rpistreamer volumio[1552]: *** WARNING *** For more information see Mar 05 01:43:33 rpistreamer volumio[1552]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 05 01:43:33 rpistreamer volumio[1552]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:43:33 rpistreamer volumio[1552]: *** WARNING *** For more information see Mar 05 01:43:33 rpistreamer node[1552]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 05 01:43:33 rpistreamer node[1552]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:43:33 rpistreamer node[1552]: *** WARNING *** For more information see Mar 05 01:43:33 rpistreamer node[1552]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 05 01:43:33 rpistreamer node[1552]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 01:43:33 rpistreamer node[1552]: *** WARNING *** For more information see Mar 05 01:43:33 rpistreamer volumio[1552]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 05 01:43:33 rpistreamer volumio[1552]: info: Discovery: Started advertising with name: RPiStreamer Mar 05 01:43:33 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 01:43:33 rpistreamer volumio[1552]: info: Loading plugin "spop"... Mar 05 01:43:33 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:33+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:33 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:33+08:00" level=debug msg="completed challenge" Mar 05 01:43:33 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:33+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:34 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:34+08:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Mar 05 01:43:34 rpistreamer volumio[1552]: info: Loading plugin "outputs"... Mar 05 01:43:34 rpistreamer volumio[1552]: info: Loading plugin "albumart"... Mar 05 01:43:34 rpistreamer volumio[1552]: info: Plugin example_plugin is not enabled Mar 05 01:43:34 rpistreamer volumio[1552]: info: Loading plugin "inputs"... Mar 05 01:43:34 rpistreamer volumio[1552]: info: Loading plugin "updater_comm"... Mar 05 01:43:34 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:34+08:00" level=debug msg="connected to ap-gue1.spotify.com:443" Mar 05 01:43:34 rpistreamer volumio[1552]: info: Plugin mpdemulation is not enabled Mar 05 01:43:34 rpistreamer volumio[1552]: info: Loading plugin "rest_api"... Mar 05 01:43:34 rpistreamer volumio[1552]: info: Loading plugin "websocket"... Mar 05 01:43:34 rpistreamer volumio[1552]: info: Starting Socket.io Server version 1.7.4 Mar 05 01:43:34 rpistreamer volumio[1552]: info: Loading plugin "Bluetoothremote"... Mar 05 01:43:35 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:35+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:35 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:35+08:00" level=debug msg="completed challenge" Mar 05 01:43:35 rpistreamer volumio[1552]: info: Applying required configuration parameters for plugin Bluetoothremote Mar 05 01:43:35 rpistreamer volumio[1552]: info: Loading i18n strings for locale en Mar 05 01:43:35 rpistreamer volumio[1552]: Updating browse sources language Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:43:35 rpistreamer volumio[1637]: Forking 3 albumart workers Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::initPlayerControls Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: Express server listening on port 3000 Mar 05 01:43:35 rpistreamer volumio[1552]: [Metrics] WebUI: 6s 935.84ms Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreStateMachine::resetVolumioState Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreStateMachine::getcurrentVolume Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 01:43:35 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:35+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:35 rpistreamer volumio[1552]: info: Volumio Network Manager: Network status updated: 2 Mar 05 01:43:35 rpistreamer volumio[1552]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreStateMachine::pushState Mar 05 01:43:35 rpistreamer volumio[1552]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioPushState Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreStateMachine::updateTrackBlock Mar 05 01:43:35 rpistreamer volumio[1552]: info: CorePlayQueue::getTrackBlock Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 01:43:35 rpistreamer volumio[1552]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 05 01:43:35 rpistreamer volumio[1552]: info: Received Get System Info Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 05 01:43:35 rpistreamer volumio[1552]: info: Discovery: Getting this device information Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioGetState Mar 05 01:43:35 rpistreamer volumio[1552]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 05 01:43:35 rpistreamer volumio-remote-updater[10231]: [2026-03-05 01:43:35] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1772646211 101 Mar 05 01:43:35 rpistreamer volumio[1552]: 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: 2 Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: Reloading queue from file Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreStateMachine::pushState Mar 05 01:43:35 rpistreamer volumio[1552]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioPushState Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreStateMachine::setRepeat true single undefined Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreStateMachine::pushState Mar 05 01:43:35 rpistreamer volumio[1552]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioPushState Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreStateMachine::setRandom false Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreStateMachine::pushState Mar 05 01:43:35 rpistreamer volumio[1552]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioPushState Mar 05 01:43:35 rpistreamer volumio[1552]: info: Setting Device type: Raspberry PI Mar 05 01:43:35 rpistreamer volumio[1552]: info: Completed loading Core Plugins Mar 05 01:43:35 rpistreamer volumio[1552]: info: Preparing to generate the ALSA configuration file Mar 05 01:43:35 rpistreamer volumio[1552]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 05 01:43:35 rpistreamer volumio[1552]: info: Reading ALSA contributions from plugins. Mar 05 01:43:35 rpistreamer volumio[1552]: info: Asound.conf file unchanged, so no further update is needed Mar 05 01:43:35 rpistreamer volumio[1552]: info: Output device has changed, restarting MPD Mar 05 01:43:35 rpistreamer volumio[1552]: info: Output device has changed, restarting Shairport Sync Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 01:43:35 rpistreamer volumio[1552]: info: ___________ START PLUGINS ___________ Mar 05 01:43:35 rpistreamer volumio[1552]: info: ControllerMpd::onStart: Initializing MPD Mar 05 01:43:35 rpistreamer sudo[1700]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 01:43:35 rpistreamer volumio[1552]: info: Creating MPD Configuration file Mar 05 01:43:35 rpistreamer sudo[1700]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:35 rpistreamer sudo[1700]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:35 rpistreamer sudo[1702]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 01:43:35 rpistreamer sudo[1702]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 01:43:35 rpistreamer volumio[1552]: info: [1772646215965] CoreMusicLibrary::Adding element Media Servers Mar 05 01:43:35 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:43:35 rpistreamer sudo[1708]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Mar 05 01:43:35 rpistreamer sudo[1708]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:35 rpistreamer volumio[1552]: info: UPNP Browser: Client initialized successfully Mar 05 01:43:36 rpistreamer systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 05 01:43:36 rpistreamer sudo[1714]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 01:43:36 rpistreamer sudo[1714]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:36 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:36 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:36 rpistreamer sudo[1712]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 01:43:36 rpistreamer sudo[1712]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:36 rpistreamer sudo[1712]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:36 rpistreamer volumio[1552]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 01:43:36 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:36 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:36 rpistreamer systemd[1]: mpd.service: Deactivated successfully. Mar 05 01:43:36 rpistreamer systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 05 01:43:36 rpistreamer systemd[1]: mpd.service: Consumed 3.960s CPU time. Mar 05 01:43:36 rpistreamer systemd[1]: mpd.socket: Deactivated successfully. Mar 05 01:43:36 rpistreamer systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 05 01:43:36 rpistreamer systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 05 01:43:36 rpistreamer volumio[1552]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 01:43:36 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 01:43:36 rpistreamer volumio[1552]: info: [1772646216155] CoreMusicLibrary::Adding element Last_100 Mar 05 01:43:36 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:43:36 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 01:43:36 rpistreamer volumio[1552]: info: [1772646216170] CoreMusicLibrary::Adding element Webradio Mar 05 01:43:36 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 01:43:36 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:36+08:00" level=debug msg="connected to ap-gew1.spotify.com:80" Mar 05 01:43:36 rpistreamer systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 05 01:43:36 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 01:43:36 rpistreamer systemd[1]: Starting mpd.service - Music Player Daemon... Mar 05 01:43:36 rpistreamer volumio[1552]: info: Initializing BBC Radios Mar 05 01:43:36 rpistreamer sudo[1708]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:36 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 01:43:36 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:36 rpistreamer volumio[1552]: info: Creating Spotify config file Mar 05 01:43:36 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:36 rpistreamer sudo[1727]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 05 01:43:36 rpistreamer sudo[1727]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 05 01:43:36 rpistreamer sudo[1727]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:36 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:36+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Mar 05 01:43:36 rpistreamer volumio[1552]: info: Loading i18n strings for locale en Mar 05 01:43:36 rpistreamer volumio[1552]: info: Volumio Calling Home Mar 05 01:43:37 rpistreamer volumio[1648]: Starting albumart workers Mar 05 01:43:37 rpistreamer go-librespot[1568]: time="2026-03-05T01:43:37+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Mar 05 01:43:37 rpistreamer volumio[1552]: info: Discovery: adding 7e34c4f0-ee39-441c-99b9-fc337c1a9397 Mar 05 01:43:37 rpistreamer volumio[1552]: info: Discovery: Found device RPiStreamer Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioGetState Mar 05 01:43:37 rpistreamer volumio[1552]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:37 rpistreamer volumio[1552]: info: Discovery: this is already registered, 7e34c4f0-ee39-441c-99b9-fc337c1a9397 Mar 05 01:43:37 rpistreamer volumio[1552]: info: Discovery: Found device RPiStreamer Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioGetState Mar 05 01:43:37 rpistreamer volumio[1552]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:37 rpistreamer volumio[1552]: info: MPD Permissions set Mar 05 01:43:37 rpistreamer volumio[1552]: info: MPD Permissions set Mar 05 01:43:37 rpistreamer volumio[1552]: info: Spotify config file written Mar 05 01:43:37 rpistreamer sudo[1747]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 05 01:43:37 rpistreamer volumio[1552]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 05 01:43:37 rpistreamer sudo[1747]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1649]: Starting albumart workers Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1647]: Starting albumart workers Mar 05 01:43:37 rpistreamer systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 05 01:43:37 rpistreamer systemd[1]: go-librespot-daemon.service: Killing process 1575 (go-librespot) with signal SIGKILL. Mar 05 01:43:37 rpistreamer systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 05 01:43:37 rpistreamer systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 05 01:43:37 rpistreamer go-librespot[1754]: go-librespot daemon starting... Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 01:43:37 rpistreamer volumio[1552]: info: No need to fix Spotify hosts Mar 05 01:43:37 rpistreamer sudo[1747]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:37 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:37+08:00" level=info msg="running go-librespot 0.6.2" Mar 05 01:43:37 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:37+08:00" level=debug msg="app state loaded" Mar 05 01:43:37 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:37+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 05 01:43:37 rpistreamer volumio[1552]: info: Volumio called home Mar 05 01:43:37 rpistreamer volumio[1552]: info: Starting Shairport Sync Mar 05 01:43:37 rpistreamer volumio[1552]: info: Starting Shairport Sync Mar 05 01:43:37 rpistreamer volumio[1552]: info: Starting Shairport Sync Mar 05 01:43:37 rpistreamer sudo[1771]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 01:43:37 rpistreamer sudo[1771]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:37 rpistreamer sudo[1773]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 01:43:38 rpistreamer sudo[1773]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:38 rpistreamer sudo[1769]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 01:43:38 rpistreamer sudo[1769]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:38 rpistreamer systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 05 01:43:38 rpistreamer systemd[1]: shairport-sync.service: Deactivated successfully. Mar 05 01:43:38 rpistreamer systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 05 01:43:38 rpistreamer systemd[1]: shairport-sync.service: Consumed 1.823s CPU time. Mar 05 01:43:38 rpistreamer systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 05 01:43:38 rpistreamer sudo[1771]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:38 rpistreamer sudo[1773]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:38 rpistreamer sudo[1769]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:38 rpistreamer volumio[1552]: info: Shairport-Sync Started Mar 05 01:43:38 rpistreamer volumio[1552]: Error adding Membership: Error: addMembership EINVAL Mar 05 01:43:38 rpistreamer volumio[1552]: info: Shairport-Sync Started Mar 05 01:43:38 rpistreamer volumio[1552]: info: Shairport-Sync Started Mar 05 01:43:38 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:38+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 05 01:43:38 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:38+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 05 01:43:38 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:38+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 05 01:43:38 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:38+08:00" level=info msg="zeroconf server listening on port 37493" Mar 05 01:43:38 rpistreamer volumio[1552]: info: CoreCommandRouter::volumioGetState Mar 05 01:43:38 rpistreamer volumio[1552]: info: CorePlayQueue::getTrack 0 Mar 05 01:43:38 rpistreamer volumio[1552]: info: An error occurred while refreshing Spotify Token Error: Bad Request Mar 05 01:43:38 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:38+08:00" level=debug msg="obtained new client token: AADt5O7JSjY+lWL8lPCVBI8HXiU8sjVXPsawif/KDjp/CnPgAlkRjc5pYFB8hC4aaEqFhSvtxn6J79/HVKKcYzqvVLxgwm6dKC5oh+w6fshRcMaaBGAyxc2X7NSmK5lB7ziLgrPN9aEUpVeETF5q/sWMKH4dhXRYTX0HSF0huHyP8dDOmXvwj6F+KmlSEJ4bUCr1Uukjro2Rp3O8EXC0JgUsKXROscGDZ5aCXjaaftkEKuHX5BML1vRotQ==" Mar 05 01:43:39 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:39+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:43:39 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:39+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:39 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:39+08:00" level=debug msg="completed challenge" Mar 05 01:43:40 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:40+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:40 rpistreamer mpd[1742]: 2026-03-05T01:43:40 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 05 01:43:40 rpistreamer systemd[1]: Started mpd.service - Music Player Daemon. Mar 05 01:43:40 rpistreamer sudo[1702]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:40 rpistreamer sudo[1714]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:40 rpistreamer volumio[1552]: info: Completed starting Core Plugins Mar 05 01:43:40 rpistreamer volumio[1552]: info: ------------------------------------------- Mar 05 01:43:40 rpistreamer volumio[1552]: info: ----- MyVolumio plugins startup ---- Mar 05 01:43:40 rpistreamer volumio[1552]: info: ------------------------------------------- Mar 05 01:43:40 rpistreamer volumio[1552]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 05 01:43:40 rpistreamer volumio[1552]: error: MPD error: The expression evaluated to a falsy value: Mar 05 01:43:40 rpistreamer volumio[1552]: assert.ok(self.idling) Mar 05 01:43:40 rpistreamer volumio[1552]: error: The expression evaluated to a falsy value: Mar 05 01:43:40 rpistreamer volumio[1552]: assert.ok(self.idling) Mar 05 01:43:40 rpistreamer volumio[1552]: info: MPD running with PID1742 Mar 05 01:43:40 rpistreamer volumio[1552]: ,establishing connection Mar 05 01:43:40 rpistreamer volumio[1552]: error: updateQueue error: null Mar 05 01:43:40 rpistreamer volumio[1552]: error: updateQueue error: null Mar 05 01:43:40 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:40+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 05 01:43:40 rpistreamer volumio[1552]: info: go-librespot daemon successfully initialized Mar 05 01:43:41 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:41+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:41 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:41+08:00" level=debug msg="completed challenge" Mar 05 01:43:41 rpistreamer sudo[1833]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 01:43:41 rpistreamer sudo[1833]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:41 rpistreamer sudo[1835]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 01:43:41 rpistreamer sudo[1835]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:41 rpistreamer sudo[1833]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:41 rpistreamer sudo[1835]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:41 rpistreamer sudo[1839]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 05 01:43:41 rpistreamer sudo[1839]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 05 01:43:41 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:41+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:41 rpistreamer sudo[1839]: pam_unix(sudo:session): session closed for user root Mar 05 01:43:41 rpistreamer volumio[1552]: info: Upmpdcli Daemon Started Mar 05 01:43:42 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:42+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.241.202:80: connect: connection refused" Mar 05 01:43:42 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:42+08: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" Mar 05 01:43:42 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:42+08:00" level=debug msg="connected to ap-gew1.spotify.com:443" Mar 05 01:43:42 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:42+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:42 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:42+08:00" level=debug msg="completed challenge" Mar 05 01:43:43 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:43+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:43 rpistreamer volumio[1552]: info: Initializing connection to go-librespot Websocket Mar 05 01:43:43 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:43+08:00" level=debug msg="new websocket client" Mar 05 01:43:43 rpistreamer volumio[1552]: info: Connection to go-librespot Websocket established Mar 05 01:43:44 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:44+08:00" level=debug msg="connected to ap-gew4.spotify.com:80" Mar 05 01:43:44 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:44+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:44 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:44+08:00" level=debug msg="completed challenge" Mar 05 01:43:44 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:44+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:45 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:45+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 05 01:43:45 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:45+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:45 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:45+08:00" level=debug msg="completed challenge" Mar 05 01:43:45 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:45+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:46 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:46+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 05 01:43:46 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:46+08:00" level=debug msg="completed keyexchange" Mar 05 01:43:46 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:46+08:00" level=debug msg="completed challenge" Mar 05 01:43:46 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:46+08:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:46 rpistreamer go-librespot[1760]: time="2026-03-05T01:43:46+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Mar 05 01:43:46 rpistreamer systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 05 01:43:46 rpistreamer systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 05 01:43:46 rpistreamer volumio[1552]: info: Getting Spotify volume Mar 05 01:43:46 rpistreamer volumio[1552]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 01:43:46 rpistreamer volumio[1552]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 05 01:43:46 rpistreamer volumio[1552]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 05 01:43:46 rpistreamer volumio[1552]: errno: -111, Mar 05 01:43:46 rpistreamer volumio[1552]: code: 'ECONNREFUSED', Mar 05 01:43:46 rpistreamer volumio[1552]: syscall: 'connect', Mar 05 01:43:46 rpistreamer volumio[1552]: address: '127.0.0.1', Mar 05 01:43:46 rpistreamer volumio[1552]: port: 9879, Mar 05 01:43:46 rpistreamer volumio[1552]: response: undefined Mar 05 01:43:46 rpistreamer volumio[1552]: } Mar 05 01:43:46 rpistreamer volumio[1552]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 01:43:47 rpistreamer sudo[1856]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-05 01:42' Mar 05 01:43:47 rpistreamer sudo[1856]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"