Aug 31 14:33:00 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 31 14:33:00 volumio volumio[18655]: info: Received Get System Info Aug 31 14:33:00 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 14:33:00 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 14:33:00 volumio volumio[18655]: info: Discovery: Getting this device information Aug 31 14:33:00 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:33:00 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:33:00 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 14:33:01 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:33:01 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:33:01 volumio volumio[18655]: info: Listing playlists Aug 31 14:33:01 volumio volumio[18655]: info: Listing playlists Aug 31 14:33:07 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 31 14:33:11 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:33:11 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:33:13 volumio volumio[18655]: info: CALLMETHOD: system_controller system setLanguageTimezone [object Object] Aug 31 14:33:13 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , setLanguageTimezone Aug 31 14:33:13 volumio volumio[18655]: info: Setting timezone to Australia/Melbourne Aug 31 14:33:13 volumio sudo[29514]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/unlink /etc/localtime Aug 31 14:33:13 volumio sudo[29514]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 14:33:13 volumio sudo[29514]: pam_unix(sudo:session): session closed for user root Aug 31 14:33:13 volumio sudo[29518]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/ln -s /usr/share/zoneinfo/Australia/Melbourne /etc/localtime Aug 31 14:33:13 volumio sudo[29518]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 14:33:13 volumio sudo[29518]: pam_unix(sudo:session): session closed for user root Aug 31 14:33:13 volumio systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Aug 31 14:33:13 volumio systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Aug 31 14:33:13 volumio systemd[1]: Starting fstrim.service - Discard unused blocks on filesystems from /etc/fstab... Aug 31 14:33:13 volumio sudo[29523]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/localtime Aug 31 14:33:13 volumio sudo[29523]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 14:33:13 volumio systemd[1]: e2scrub_all.service: Deactivated successfully. Aug 31 14:33:13 volumio systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Aug 31 14:33:13 volumio systemd[1]: dpkg-db-backup.service: Deactivated successfully. Aug 31 14:33:13 volumio systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Aug 31 14:33:13 volumio sudo[29523]: pam_unix(sudo:session): session closed for user root Aug 31 14:33:13 volumio sudo[29535]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-timezone Australia/Melbourne Aug 31 14:33:13 volumio sudo[29535]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 14:33:13 volumio dbus-daemon[709]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.60435' (uid=0 pid=29536 comm="/usr/bin/timedatectl set-timezone Australia/Melbou") Aug 31 14:33:13 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... Aug 31 14:33:13 volumio fstrim[29526]: /boot: 273.1 MiB (286367744 bytes) trimmed on /dev/mmcblk0p1 Aug 31 14:33:13 volumio systemd[1]: fstrim.service: Deactivated successfully. Aug 31 14:33:13 volumio systemd[1]: Finished fstrim.service - Discard unused blocks on filesystems from /etc/fstab. Aug 31 14:33:14 volumio dbus-daemon[709]: [system] Successfully activated service 'org.freedesktop.timedate1' Aug 31 14:33:14 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. Aug 31 14:33:14 volumio sudo[29535]: pam_unix(sudo:session): session closed for user root Aug 31 14:33:14 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: appearance , setLanguage Aug 31 14:33:14 volumio volumio[18655]: info: Loading i18n strings for locale en Aug 31 14:33:14 volumio volumio5-onboarding[32166]: time=2026-08-31T14:33:14.253+10:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.0.205:38868 @ 0x23c8780" language=en Aug 31 14:33:14 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 31 14:33:14 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Aug 31 14:33:14 volumio volumio5-onboarding[32166]: time=2026-08-31T14:33:14.263+10:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.0.205:38868 @ 0x23c8780" timezone=Australia/Melbourne Aug 31 14:33:14 volumio volumio[18655]: Updating browse sources language Aug 31 14:33:14 volumio volumio[18655]: Cannot find translation for source Spotify Aug 31 14:33:14 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 14:33:14 volumio volumio[18655]: Cannot find translation for source Spotify Aug 31 14:33:14 volumio volumio[18655]: info: Fetching Streaming Services browse cache Aug 31 14:33:15 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 31 14:33:15 volumio volumio[18655]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 31 14:33:15 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 31 14:33:15 volumio volumio[18655]: info: Received Get System Version Aug 31 14:33:15 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 14:33:15 volumio volumio[18655]: info: Received Get System Info Aug 31 14:33:15 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 14:33:15 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 14:33:15 volumio volumio[18655]: info: Discovery: Getting this device information Aug 31 14:33:15 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:33:15 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:33:15 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 14:33:16 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 31 14:33:21 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:33:21 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:33:21 volumio volumio[18655]: info: Listing playlists Aug 31 14:33:21 volumio volumio[18655]: info: Listing playlists Aug 31 14:33:31 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:33:31 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:33:35 volumio volumio[18655]: info: CoreCommandRouter::volumioPlay Aug 31 14:33:35 volumio volumio[18655]: info: CoreStateMachine::play index undefined Aug 31 14:33:35 volumio volumio[18655]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 14:33:35 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:33:35 volumio volumio[18655]: info: CoreStateMachine::startPlaybackTimer Aug 31 14:33:35 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:33:35 volumio volumio[18655]: info: [1788150815792] ControllerSpotify::clearAddPlayTrack Aug 31 14:33:35 volumio volumio[18655]: info: Sending Spotify command with payload to local API: /player/play Aug 31 14:33:41 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:33:41 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:33:41 volumio volumio[18655]: info: Listing playlists Aug 31 14:33:41 volumio volumio[18655]: info: Listing playlists Aug 31 14:33:43 volumio volumio[18655]: info: CoreCommandRouter::volumioPrevious Aug 31 14:33:43 volumio volumio[18655]: info: CoreStateMachine::previous Aug 31 14:33:44 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: updater_comm , clearUpdateSchedule Aug 31 14:33:44 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 31 14:33:44 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Aug 31 14:33:44 volumio volumio-remote-updater[26104]: Test mode disabled Aug 31 14:33:44 volumio volumio-remote-updater[26104]: Alpha mode disabled Aug 31 14:33:44 volumio volumio-remote-updater[26104]: Alpha legacy test mode disabled Aug 31 14:33:44 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Aug 31 14:33:46 volumio volumio[18655]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 31 14:33:46 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 31 14:33:48 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 31 14:33:48 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 31 14:33:51 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:33:51 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:33:56 volumio volumio[18655]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 31 14:34:01 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:01 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:01 volumio volumio[18655]: info: Listing playlists Aug 31 14:34:01 volumio volumio[18655]: info: Listing playlists Aug 31 14:34:03 volumio volumio[18655]: info: Received OAUTH Data Aug 31 14:34:03 volumio volumio[18655]: info: Executing Spotify Oauth Login Aug 31 14:34:03 volumio volumio[18655]: info: Saving Spotify Refresh Token Aug 31 14:34:04 volumio sudo[29621]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 31 14:34:04 volumio sudo[29621]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 14:34:04 volumio sudo[29621]: pam_unix(sudo:session): session closed for user root Aug 31 14:34:04 volumio sudo[29623]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 31 14:34:04 volumio sudo[29623]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 14:34:04 volumio sudo[29623]: pam_unix(sudo:session): session closed for user root Aug 31 14:34:04 volumio volumio[18655]: verbose: New Socket.io Connection to 192.168.0.124 from 192.168.0.205 UA: Mozilla/5.0 (Linux; Android 14; motorola edge 30 pro Build/U1SHS34.1-177-8-3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.200 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::volumioGetVisibleSources Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:04 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 31 14:34:04 volumio volumio[18655]: info: Received Get System Info Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 14:34:04 volumio volumio[18655]: info: Discovery: Getting this device information Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:04 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:04 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:04 volumio volumio[18655]: info: Listing playlists Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 31 14:34:04 volumio volumio[18655]: info: New Spotify access tokenBQAJujskPr... Aug 31 14:34:04 volumio volumio[18655]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 31 14:34:04 volumio volumio[18655]: SPOTIFY: User informations: {"account_id":"4WUfjpyLQn","country":"AU","display_name":"Pauly","email":"cheezypeaz@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/5j8bujvimls87dxldi903kf5y"},"followers":{"href":null,"total":4},"href":"https://api.spotify.com/v1/users/5j8bujvimls87dxldi903kf5y","id":"5j8bujvimls87dxldi903kf5y","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee853ae7ed119bc37d48a757a835","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b823ae7ed119bc37d48a757a835","width":64}],"product":"premium","type":"user","uri":"spotify:user:5j8bujvimls87dxldi903kf5y"} Aug 31 14:34:04 volumio volumio[18655]: info: Creating Spotify config file Aug 31 14:34:04 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 14:34:04 volumio volumio[18655]: info: Spotify config file written Aug 31 14:34:05 volumio sudo[29628]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 31 14:34:05 volumio sudo[29628]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 14:34:05 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Aug 31 14:34:05 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Aug 31 14:34:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:05 volumio systemd[1]: go-librespot-daemon.service: Consumed 1min 28.999s CPU time. Aug 31 14:34:05 volumio volumio[18655]: info: Connection to go-librespot Websocket closed Aug 31 14:34:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:05 volumio go-librespot[29630]: go-librespot daemon starting... Aug 31 14:34:05 volumio sudo[29628]: pam_unix(sudo:session): session closed for user root Aug 31 14:34:05 volumio go-librespot[29631]: time="2026-08-31T14:34:05+10:00" level=info msg="running go-librespot 0.7.1" Aug 31 14:34:05 volumio go-librespot[29631]: time="2026-08-31T14:34:05+10:00" level=debug msg="app state loaded" Aug 31 14:34:05 volumio go-librespot[29631]: time="2026-08-31T14:34:05+10:00" level=debug msg="stored credentials not found" Aug 31 14:34:05 volumio go-librespot[29631]: time="2026-08-31T14:34:05+10:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 14:34:05 volumio volumio[18655]: info: New Spotify access tokenBQBTEwZPIZ... Aug 31 14:34:05 volumio volumio[18655]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 31 14:34:05 volumio go-librespot[29631]: time="2026-08-31T14:34:05+10:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 31 14:34:05 volumio go-librespot[29631]: time="2026-08-31T14:34:05+10:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 31 14:34:05 volumio go-librespot[29631]: time="2026-08-31T14:34:05+10:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 31 14:34:05 volumio go-librespot[29631]: time="2026-08-31T14:34:05+10:00" level=info msg="zeroconf server listening on port 39285" Aug 31 14:34:05 volumio go-librespot[29631]: time="2026-08-31T14:34:05+10:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 14:34:05 volumio volumio[18655]: SPOTIFY: User informations: {"account_id":"4WUfjpyLQn","country":"AU","display_name":"Pauly","email":"cheezypeaz@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/5j8bujvimls87dxldi903kf5y"},"followers":{"href":null,"total":4},"href":"https://api.spotify.com/v1/users/5j8bujvimls87dxldi903kf5y","id":"5j8bujvimls87dxldi903kf5y","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee853ae7ed119bc37d48a757a835","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b823ae7ed119bc37d48a757a835","width":64}],"product":"premium","type":"user","uri":"spotify:user:5j8bujvimls87dxldi903kf5y"} Aug 31 14:34:05 volumio volumio[18655]: info: Spotify Successfully logged in Aug 31 14:34:05 volumio volumio[18655]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 14:34:05 volumio volumio[18655]: info: [1788150845626] CoreMusicLibrary::Adding element Spotify Aug 31 14:34:05 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 14:34:05 volumio volumio[18655]: Cannot find translation for source Spotify Aug 31 14:34:05 volumio go-librespot[29631]: time="2026-08-31T14:34:05+10:00" level=debug msg="obtained new client token: AAFQLBmXGZR+u1ULD4a/bjtF9mh9f8iQz1B9FnqDuvmBn6vWt2uqid6OucUqel7+xBSbpquOYyqvUDnNkYlDJ2IhMGpBlB29Qne6/ZuuugGLk6rbNxDUc0LpvJ9Vwos163FceRkw9MEBNbQyYLZRYbkRYuyJww59T4697aiEDBRxEIHQqxm/nZ5iTAxh9JLq3iCYVisz5v2DqiXxtQRtgUPs3GRCLsoOMH1SFBV48Vnr3BPDKgSdwDGl" Aug 31 14:34:05 volumio go-librespot[29631]: time="2026-08-31T14:34:05+10:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 14:34:06 volumio go-librespot[29631]: time="2026-08-31T14:34:06+10:00" level=debug msg="completed keyexchange" Aug 31 14:34:06 volumio go-librespot[29631]: time="2026-08-31T14:34:06+10:00" level=debug msg="completed challenge" Aug 31 14:34:06 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 31 14:34:06 volumio go-librespot[29631]: time="2026-08-31T14:34:06+10:00" level=info msg="authenticated AP" username="5j*********************5y" Aug 31 14:34:06 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 31 14:34:06 volumio volumio[18655]: info: Received Get System Info Aug 31 14:34:06 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 14:34:06 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 14:34:06 volumio volumio[18655]: info: Discovery: Getting this device information Aug 31 14:34:06 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:06 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:06 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 14:34:06 volumio go-librespot[29631]: time="2026-08-31T14:34:06+10:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 14:34:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 14:34:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 14:34:07 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 31 14:34:07 volumio volumio[18655]: info: Received Get System Info Aug 31 14:34:07 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 14:34:07 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 14:34:07 volumio volumio[18655]: info: Discovery: Getting this device information Aug 31 14:34:07 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:07 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:07 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 14:34:08 volumio volumio[18655]: info: Initializing connection to go-librespot Websocket Aug 31 14:34:08 volumio volumio[18655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 14:34:08 volumio volumio[18655]: info: go-librespot daemon successfully initialized Aug 31 14:34:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Aug 31 14:34:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:09 volumio go-librespot[29640]: go-librespot daemon starting... Aug 31 14:34:09 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 31 14:34:09 volumio go-librespot[29641]: time="2026-08-31T14:34:09+10:00" level=info msg="running go-librespot 0.7.1" Aug 31 14:34:09 volumio go-librespot[29641]: time="2026-08-31T14:34:09+10:00" level=debug msg="app state loaded" Aug 31 14:34:09 volumio go-librespot[29641]: time="2026-08-31T14:34:09+10:00" level=debug msg="stored credentials not found" Aug 31 14:34:09 volumio go-librespot[29641]: time="2026-08-31T14:34:09+10:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 14:34:10 volumio go-librespot[29641]: time="2026-08-31T14:34:10+10: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]" Aug 31 14:34:10 volumio go-librespot[29641]: time="2026-08-31T14:34:10+10: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]" Aug 31 14:34:10 volumio go-librespot[29641]: time="2026-08-31T14:34:10+10: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]" Aug 31 14:34:10 volumio go-librespot[29641]: time="2026-08-31T14:34:10+10:00" level=info msg="zeroconf server listening on port 41035" Aug 31 14:34:10 volumio go-librespot[29641]: time="2026-08-31T14:34:10+10:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 14:34:10 volumio go-librespot[29641]: time="2026-08-31T14:34:10+10:00" level=debug msg="obtained new client token: AAF3sRhHMkQmt5ISy4jIThuyB03gzALv5ph2FESXty4c+DeLpaxhlX5hmZaEQYz8Rt7Xe/KlxTYJyeEEz4BjGP0yAGN2TCp0Up9/2HvPgi/Bc0zTd5soSqgcqKv7ph0mPwmASvpwHzAkWlAjq1/mh1WRgMbYZaOB1PRiCU/U7UrTeuQGrGzXJv5RFKWrKFaLlA4N430pHkc2NM7Rx36I5dL2/FZdIkf3fYeHRahq6P4BBwq63aCt1g==" Aug 31 14:34:10 volumio go-librespot[29641]: time="2026-08-31T14:34:10+10:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 14:34:10 volumio go-librespot[29641]: time="2026-08-31T14:34:10+10:00" level=debug msg="completed keyexchange" Aug 31 14:34:10 volumio go-librespot[29641]: time="2026-08-31T14:34:10+10:00" level=debug msg="completed challenge" Aug 31 14:34:10 volumio go-librespot[29641]: time="2026-08-31T14:34:10+10:00" level=info msg="authenticated AP" username="5j*********************5y" Aug 31 14:34:10 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 31 14:34:10 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 31 14:34:10 volumio systemd[1]: setdatetime-helper.service: Consumed 1.034s CPU time. Aug 31 14:34:10 volumio go-librespot[29641]: time="2026-08-31T14:34:10+10:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 14:34:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 14:34:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 14:34:11 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:11 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:11 volumio volumio[18655]: info: Initializing connection to go-librespot Websocket Aug 31 14:34:11 volumio volumio[18655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 14:34:11 volumio volumio[18655]: info: Initializing connection to go-librespot Websocket Aug 31 14:34:11 volumio volumio[18655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 14:34:12 volumio volumio[18655]: info: CoreCommandRouter::volumioPlay Aug 31 14:34:12 volumio volumio[18655]: info: CoreStateMachine::play index undefined Aug 31 14:34:12 volumio volumio[18655]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 14:34:12 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:12 volumio volumio[18655]: info: CoreStateMachine::startPlaybackTimer Aug 31 14:34:12 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:12 volumio volumio[18655]: info: [1788150852339] ControllerSpotify::clearAddPlayTrack Aug 31 14:34:12 volumio volumio[18655]: info: Sending Spotify command with payload to local API: /player/play Aug 31 14:34:12 volumio volumio[18655]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 14:34:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Aug 31 14:34:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:14 volumio go-librespot[29690]: go-librespot daemon starting... Aug 31 14:34:14 volumio volumio[18655]: info: Initializing connection to go-librespot Websocket Aug 31 14:34:14 volumio volumio[18655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 14:34:14 volumio go-librespot[29691]: time="2026-08-31T14:34:14+10:00" level=info msg="running go-librespot 0.7.1" Aug 31 14:34:14 volumio go-librespot[29691]: time="2026-08-31T14:34:14+10:00" level=debug msg="app state loaded" Aug 31 14:34:14 volumio go-librespot[29691]: time="2026-08-31T14:34:14+10:00" level=debug msg="stored credentials not found" Aug 31 14:34:14 volumio go-librespot[29691]: time="2026-08-31T14:34:14+10:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 14:34:14 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 31 14:34:14 volumio go-librespot[29691]: time="2026-08-31T14:34:14+10: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]" Aug 31 14:34:14 volumio go-librespot[29691]: time="2026-08-31T14:34:14+10: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]" Aug 31 14:34:14 volumio go-librespot[29691]: time="2026-08-31T14:34:14+10: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]" Aug 31 14:34:14 volumio go-librespot[29691]: time="2026-08-31T14:34:14+10:00" level=info msg="zeroconf server listening on port 35589" Aug 31 14:34:14 volumio go-librespot[29691]: time="2026-08-31T14:34:14+10:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 14:34:14 volumio go-librespot[29691]: time="2026-08-31T14:34:14+10:00" level=debug msg="obtained new client token: AAHqXVzt2685OB2Y9m1GrKScmJu0+cNRzffX8lUb9y56EohuutlUjjyT1pDxwkzzhNTWLy43dA5ly5G/m/DXT+X627NMDGTewSZ5hfmmVeO9tBhcIilMZLqI9XfaBryq2PQlzPFaDqxbcUGP41EW0NlGmeowzTGNivWRGMybnONLzAobsjbvIgUkn9mw4gk03Gn4onhg5clYqCcJIit4jp1OBeU6yiCOIfUZbFcQOspJMN0uW20n+zh5" Aug 31 14:34:14 volumio volumio[18655]: info: CoreCommandRouter::volumioPrevious Aug 31 14:34:14 volumio volumio[18655]: info: CoreStateMachine::previous Aug 31 14:34:14 volumio go-librespot[29691]: time="2026-08-31T14:34:14+10:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 14:34:15 volumio go-librespot[29691]: time="2026-08-31T14:34:15+10:00" level=debug msg="completed keyexchange" Aug 31 14:34:15 volumio go-librespot[29691]: time="2026-08-31T14:34:15+10:00" level=debug msg="completed challenge" Aug 31 14:34:15 volumio go-librespot[29691]: time="2026-08-31T14:34:15+10:00" level=info msg="authenticated AP" username="5j*********************5y" Aug 31 14:34:15 volumio go-librespot[29691]: time="2026-08-31T14:34:15+10:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 14:34:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 14:34:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 14:34:17 volumio volumio[18655]: info: Initializing connection to go-librespot Websocket Aug 31 14:34:17 volumio volumio[18655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 14:34:17 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:17.803+10:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.205:38868 @ 0x23c8780" latency=211.791611ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Aug 31 14:34:17 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:17.850+10:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s Aug 31 14:34:17 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:17.859+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=8.627062ms Aug 31 14:34:17 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:17.874+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=23.7089ms Aug 31 14:34:17 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:17.967+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=https://www.googleapis.com duration=115.62383ms Aug 31 14:34:18 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:18.095+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=https://functions.volumio.cloud duration=241.620761ms Aug 31 14:34:18 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:18.098+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=https://functions.volumio.cloud duration=246.137104ms Aug 31 14:34:18 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:18.126+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=http://pushupdates.volumio.org duration=274.742867ms Aug 31 14:34:18 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:18.183+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=https://securetoken.googleapis.com duration=332.36033ms Aug 31 14:34:18 volumio sudo[29702]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 31 14:34:18 volumio sudo[29702]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 14:34:18 volumio sudo[29702]: pam_unix(sudo:session): session closed for user root Aug 31 14:34:18 volumio sudo[29704]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 31 14:34:18 volumio sudo[29704]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 14:34:18 volumio sudo[29704]: pam_unix(sudo:session): session closed for user root Aug 31 14:34:18 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:18.236+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=385.094263ms Aug 31 14:34:18 volumio volumio[18655]: verbose: New Socket.io Connection to 192.168.0.124 from 192.168.0.205 UA: Mozilla/5.0 (Linux; Android 14; motorola edge 30 pro Build/U1SHS34.1-177-8-3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.200 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Aug 31 14:34:18 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:18.310+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=https://database.volumio.cloud duration=458.564343ms Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 31 14:34:18 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:18.336+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=485.289069ms Aug 31 14:34:18 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:18.395+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=https://google.com duration=543.658665ms Aug 31 14:34:18 volumio sudo[29708]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 31 14:34:18 volumio sudo[29708]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 14:34:18 volumio sudo[29708]: pam_unix(sudo:session): session closed for user root Aug 31 14:34:18 volumio sudo[29710]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 31 14:34:18 volumio sudo[29710]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 14:34:18 volumio sudo[29710]: pam_unix(sudo:session): session closed for user root Aug 31 14:34:18 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:18.555+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=http://plugins.volumio.org duration=702.708535ms Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 31 14:34:18 volumio volumio[18655]: verbose: New Socket.io Connection to 192.168.0.124 from 192.168.0.205 UA: Mozilla/5.0 (Linux; Android 14; motorola edge 30 pro Build/U1SHS34.1-177-8-3; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/151.0.7922.200 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Aug 31 14:34:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Aug 31 14:34:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:18 volumio go-librespot[29713]: go-librespot daemon starting... Aug 31 14:34:18 volumio go-librespot[29714]: time="2026-08-31T14:34:18+10:00" level=info msg="running go-librespot 0.7.1" Aug 31 14:34:18 volumio go-librespot[29714]: time="2026-08-31T14:34:18+10:00" level=debug msg="app state loaded" Aug 31 14:34:18 volumio go-librespot[29714]: time="2026-08-31T14:34:18+10:00" level=debug msg="stored credentials not found" Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 31 14:34:18 volumio go-librespot[29714]: time="2026-08-31T14:34:18+10:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 14:34:18 volumio volumio5-onboarding[32166]: time=2026-08-31T14:34:18.865+10:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.205:38868 @ 0x23c8780" latency=218.575807ms timeout=10s endpoint=http://cddb.volumio.org duration=1.012684285s Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::volumioGetVisibleSources Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:18 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 31 14:34:18 volumio volumio[18655]: info: Received Get System Info Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 14:34:18 volumio volumio[18655]: info: Discovery: Getting this device information Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:18 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:18 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:18 volumio volumio[18655]: info: Listing playlists Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 31 14:34:18 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 31 14:34:19 volumio go-librespot[29714]: time="2026-08-31T14:34:19+10: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]" Aug 31 14:34:19 volumio go-librespot[29714]: time="2026-08-31T14:34:19+10: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]" Aug 31 14:34:19 volumio go-librespot[29714]: time="2026-08-31T14:34:19+10: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]" Aug 31 14:34:19 volumio go-librespot[29714]: time="2026-08-31T14:34:19+10:00" level=info msg="zeroconf server listening on port 40153" Aug 31 14:34:19 volumio go-librespot[29714]: time="2026-08-31T14:34:19+10:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 14:34:19 volumio go-librespot[29714]: time="2026-08-31T14:34:19+10:00" level=debug msg="obtained new client token: AAGLOAO2IgGJb1qXDt2krx+ZOlK/VGdkofUcOIrkT/N9UdfEOgjihrUnvg5IUE6p3xF6K6X4vDxNGDGSnqnjoRetwSG9cvs/GmpET1tSdm16ZcWevcECfB0x9v0L/GLgNsoSiAk369OWoFYpY4y0VRs3grEH9wsa7W08LPItkuPDuGv6fvJDsVMaqouwbAkSVwPNqTEoFsnOVBLQCi8FLD1IoHLqfAwrXLx0opl+JvT+OUqF2LDy2pop" Aug 31 14:34:19 volumio go-librespot[29714]: time="2026-08-31T14:34:19+10:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 14:34:19 volumio go-librespot[29714]: time="2026-08-31T14:34:19+10:00" level=debug msg="completed keyexchange" Aug 31 14:34:19 volumio go-librespot[29714]: time="2026-08-31T14:34:19+10:00" level=debug msg="completed challenge" Aug 31 14:34:19 volumio go-librespot[29714]: time="2026-08-31T14:34:19+10:00" level=info msg="authenticated AP" username="5j*********************5y" Aug 31 14:34:20 volumio go-librespot[29714]: time="2026-08-31T14:34:20+10:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 14:34:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 14:34:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 14:34:20 volumio volumio[18655]: info: Initializing connection to go-librespot Websocket Aug 31 14:34:20 volumio volumio[18655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 14:34:20 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Aug 31 14:34:20 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 31 14:34:20 volumio volumio[18655]: info: Received Get System Info Aug 31 14:34:20 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 14:34:20 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 14:34:20 volumio volumio[18655]: info: Discovery: Getting this device information Aug 31 14:34:20 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:20 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:20 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 14:34:21 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:21 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:21 volumio volumio[18655]: info: Listing playlists Aug 31 14:34:21 volumio volumio[18655]: info: Listing playlists Aug 31 14:34:21 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 31 14:34:21 volumio volumio[18655]: info: Received Get System Info Aug 31 14:34:21 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 14:34:21 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 14:34:21 volumio volumio[18655]: info: Discovery: Getting this device information Aug 31 14:34:21 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:21 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:21 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 14:34:22 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 31 14:34:22 volumio volumio[18655]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 31 14:34:22 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 31 14:34:22 volumio volumio[18655]: info: Received Get System Version Aug 31 14:34:22 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 14:34:22 volumio volumio[18655]: info: Received Get System Info Aug 31 14:34:22 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 14:34:22 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 14:34:22 volumio volumio[18655]: info: Discovery: Getting this device information Aug 31 14:34:22 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:22 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:22 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 14:34:23 volumio volumio[18655]: info: CoreCommandRouter::volumioPlay Aug 31 14:34:23 volumio volumio[18655]: info: CoreStateMachine::play index undefined Aug 31 14:34:23 volumio volumio[18655]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 14:34:23 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:23 volumio volumio[18655]: info: CoreStateMachine::startPlaybackTimer Aug 31 14:34:23 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:23 volumio volumio[18655]: info: [1788150863091] ControllerSpotify::clearAddPlayTrack Aug 31 14:34:23 volumio volumio[18655]: info: Sending Spotify command with payload to local API: /player/play Aug 31 14:34:23 volumio volumio[18655]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 14:34:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Aug 31 14:34:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:23 volumio go-librespot[29738]: go-librespot daemon starting... Aug 31 14:34:23 volumio go-librespot[29739]: time="2026-08-31T14:34:23+10:00" level=info msg="running go-librespot 0.7.1" Aug 31 14:34:23 volumio go-librespot[29739]: time="2026-08-31T14:34:23+10:00" level=debug msg="app state loaded" Aug 31 14:34:23 volumio go-librespot[29739]: time="2026-08-31T14:34:23+10:00" level=debug msg="stored credentials not found" Aug 31 14:34:23 volumio volumio[18655]: info: Initializing connection to go-librespot Websocket Aug 31 14:34:23 volumio volumio[18655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 14:34:23 volumio go-librespot[29739]: time="2026-08-31T14:34:23+10:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 14:34:23 volumio go-librespot[29739]: time="2026-08-31T14:34:23+10:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 31 14:34:23 volumio go-librespot[29739]: time="2026-08-31T14:34:23+10:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 31 14:34:23 volumio go-librespot[29739]: time="2026-08-31T14:34:23+10:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 31 14:34:23 volumio go-librespot[29739]: time="2026-08-31T14:34:23+10:00" level=info msg="zeroconf server listening on port 44003" Aug 31 14:34:23 volumio go-librespot[29739]: time="2026-08-31T14:34:23+10:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 14:34:23 volumio go-librespot[29739]: time="2026-08-31T14:34:23+10:00" level=debug msg="obtained new client token: AAEWt416cQ3t1bnzwVn6+BcePmWXM2kmo+b9TlNIZIOA0feHG0NuFStXbiEZR0Dlf96Bn+mIEbPf74FlxMkdMOOkhDsX7NwoY7IVjk7R0lO1VPuZAuREPOULM3PK3DWdI93gX9wLJyw1IjCF39L5fYYmZOY0kx9a9KlnaFXHFwmPP2ZaKD2JbcVN9hSGDYgtJj39W4ZRUU0z/mSqHn+ioV4RIFguchKJIGBnpUQDeRA96Dsg43wwR1Pi" Aug 31 14:34:23 volumio go-librespot[29739]: time="2026-08-31T14:34:23+10:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 14:34:24 volumio go-librespot[29739]: time="2026-08-31T14:34:24+10:00" level=debug msg="completed keyexchange" Aug 31 14:34:24 volumio go-librespot[29739]: time="2026-08-31T14:34:24+10:00" level=debug msg="completed challenge" Aug 31 14:34:24 volumio go-librespot[29739]: time="2026-08-31T14:34:24+10:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Aug 31 14:34:24 volumio go-librespot[29739]: time="2026-08-31T14:34:24+10:00" level=debug msg="connected to ap-gae2.spotify.com:443" Aug 31 14:34:24 volumio go-librespot[29739]: time="2026-08-31T14:34:24+10:00" level=debug msg="completed keyexchange" Aug 31 14:34:24 volumio go-librespot[29739]: time="2026-08-31T14:34:24+10:00" level=debug msg="completed challenge" Aug 31 14:34:25 volumio go-librespot[29739]: time="2026-08-31T14:34:25+10:00" level=info msg="authenticated AP" username="5j*********************5y" Aug 31 14:34:25 volumio go-librespot[29739]: time="2026-08-31T14:34:25+10:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 14:34:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 14:34:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 14:34:26 volumio volumio[18655]: info: Initializing connection to go-librespot Websocket Aug 31 14:34:26 volumio volumio[18655]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 14:34:26 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 31 14:34:26 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 31 14:34:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Aug 31 14:34:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:28 volumio go-librespot[29748]: go-librespot daemon starting... Aug 31 14:34:28 volumio go-librespot[29749]: time="2026-08-31T14:34:28+10:00" level=info msg="running go-librespot 0.7.1" Aug 31 14:34:28 volumio go-librespot[29749]: time="2026-08-31T14:34:28+10:00" level=debug msg="app state loaded" Aug 31 14:34:28 volumio go-librespot[29749]: time="2026-08-31T14:34:28+10:00" level=debug msg="stored credentials not found" Aug 31 14:34:28 volumio go-librespot[29749]: time="2026-08-31T14:34:28+10:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 14:34:28 volumio volumio[18655]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 31 14:34:28 volumio go-librespot[29749]: time="2026-08-31T14:34:28+10: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]" Aug 31 14:34:28 volumio go-librespot[29749]: time="2026-08-31T14:34:28+10: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]" Aug 31 14:34:28 volumio go-librespot[29749]: time="2026-08-31T14:34:28+10: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]" Aug 31 14:34:28 volumio go-librespot[29749]: time="2026-08-31T14:34:28+10:00" level=info msg="zeroconf server listening on port 37425" Aug 31 14:34:28 volumio go-librespot[29749]: time="2026-08-31T14:34:28+10:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Aug 31 14:34:28 volumio go-librespot[29749]: time="2026-08-31T14:34:28+10:00" level=debug msg="obtained new client token: AAHuWj8Dcje02y9/8IHddGlh5UGqrbNdIBMUiJJf8IPyifc+AXZCM8Nt/cQwjTGphRRKhAvhLroSU1+JUmzt2WdpBLsKpU21Fmwyo9zZyyJYvM2CCzF7wj68KRDr9iPDA0L0SavETeDdNAhzn7r6tmhUcEsR9ifM/jTttyhj5hiXduNdexLiRMCrBJj5qkFyzcIXwlxxcOAnzlwlDTFOzFpuEQdWEAno9+nc7y0yAwgC5PIIOJaMuIV+" Aug 31 14:34:29 volumio go-librespot[29749]: time="2026-08-31T14:34:29+10:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Aug 31 14:34:29 volumio volumio[18655]: info: Initializing connection to go-librespot Websocket Aug 31 14:34:29 volumio go-librespot[29749]: time="2026-08-31T14:34:29+10:00" level=debug msg="new websocket client" Aug 31 14:34:29 volumio volumio[18655]: info: Connection to go-librespot Websocket established Aug 31 14:34:29 volumio go-librespot[29749]: time="2026-08-31T14:34:29+10:00" level=debug msg="completed keyexchange" Aug 31 14:34:29 volumio go-librespot[29749]: time="2026-08-31T14:34:29+10:00" level=debug msg="completed challenge" Aug 31 14:34:29 volumio go-librespot[29749]: time="2026-08-31T14:34:29+10:00" level=info msg="authenticated AP" username="5j*********************5y" Aug 31 14:34:29 volumio go-librespot[29749]: time="2026-08-31T14:34:29+10:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed authenticating with login5: INVALID_CREDENTIALS" Aug 31 14:34:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 31 14:34:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 31 14:34:29 volumio volumio[18655]: info: Connection to go-librespot Websocket closed Aug 31 14:34:30 volumio volumio[18655]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 31 14:34:31 volumio volumio[18655]: info: CoreCommandRouter::volumioGetState Aug 31 14:34:31 volumio volumio[18655]: info: CorePlayQueue::getTrack 0 Aug 31 14:34:32 volumio volumio[18655]: info: Getting Spotify volume Aug 31 14:34:32 volumio volumio[18655]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 14:34:32 volumio volumio[18655]: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 31 14:34:32 volumio volumio[18655]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Aug 31 14:34:32 volumio volumio[18655]: errno: -111, Aug 31 14:34:32 volumio volumio[18655]: code: 'ECONNREFUSED', Aug 31 14:34:32 volumio volumio[18655]: syscall: 'connect', Aug 31 14:34:32 volumio volumio[18655]: address: '127.0.0.1', Aug 31 14:34:32 volumio volumio[18655]: port: 9879, Aug 31 14:34:32 volumio volumio[18655]: response: undefined Aug 31 14:34:32 volumio volumio[18655]: } Aug 31 14:34:32 volumio volumio[18655]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 14:34:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Aug 31 14:34:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Aug 31 14:34:32 volumio go-librespot[29785]: go-librespot daemon starting... Aug 31 14:34:32 volumio go-librespot[29786]: time="2026-08-31T14:34:32+10:00" level=info msg="running go-librespot 0.7.1" Aug 31 14:34:32 volumio go-librespot[29786]: time="2026-08-31T14:34:32+10:00" level=debug msg="app state loaded" Aug 31 14:34:32 volumio go-librespot[29786]: time="2026-08-31T14:34:32+10:00" level=debug msg="stored credentials not found" Aug 31 14:34:32 volumio go-librespot[29786]: time="2026-08-31T14:34:32+10:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 31 14:34:33 volumio sudo[29796]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-31 14:33' Aug 31 14:34:33 volumio sudo[29796]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"