Apr 10 09:42:38 matts-music volumio[1478]: info: Received OAUTH Data Apr 10 09:42:38 matts-music volumio[1478]: info: Executing Spotify Oauth Login Apr 10 09:42:38 matts-music volumio[1478]: info: Saving Spotify Refresh Token Apr 10 09:42:38 matts-music volumio[1478]: info: New Spotify access tokenBQAlWTq7Ub... Apr 10 09:42:38 matts-music volumio[1478]: info: Spotify credentials grant success - running version from March 24, 2019 Apr 10 09:42:39 matts-music volumio[1478]: SPOTIFY: User informations: {"country":"US","display_name":"Quester","email":"questerfox@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31n6nh6ne7itvnlvs67p6wm5fzeq"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31n6nh6ne7itvnlvs67p6wm5fzeq","id":"31n6nh6ne7itvnlvs67p6wm5fzeq","images":[],"product":"premium","type":"user","uri":"spotify:user:31n6nh6ne7itvnlvs67p6wm5fzeq"} Apr 10 09:42:39 matts-music volumio[1478]: info: Creating Spotify config file Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 09:42:39 matts-music volumio[1478]: info: Spotify config file written Apr 10 09:42:39 matts-music sudo[3040]: volumio : unable to resolve host matts-music: System error Apr 10 09:42:39 matts-music sudo[3039]: volumio : unable to resolve host matts-music: System error Apr 10 09:42:39 matts-music sudo[3039]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 10 09:42:39 matts-music sudo[3039]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 09:42:39 matts-music sudo[3040]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 10 09:42:39 matts-music sudo[3040]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 09:42:39 matts-music sudo[3040]: pam_unix(sudo:session): session closed for user root Apr 10 09:42:39 matts-music sudo[3039]: pam_unix(sudo:session): session closed for user root Apr 10 09:42:39 matts-music volumio[1478]: verbose: New Socket.io Connection to 192.168.1.33 from 192.168.1.2 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/146.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Apr 10 09:42:39 matts-music sudo[3042]: volumio : unable to resolve host matts-music: System error Apr 10 09:42:39 matts-music sudo[3042]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 10 09:42:39 matts-music sudo[3042]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 09:42:39 matts-music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Apr 10 09:42:39 matts-music systemd[1]: go-librespot-daemon.service: Killing process 1947 (go-librespot) with signal SIGKILL. Apr 10 09:42:39 matts-music systemd[1]: go-librespot-daemon.service: Killing process 1997 (go-librespot) with signal SIGKILL. Apr 10 09:42:39 matts-music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Apr 10 09:42:39 matts-music volumio[1478]: info: Connection to go-librespot Websocket closed Apr 10 09:42:39 matts-music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:42:39 matts-music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:42:39 matts-music go-librespot[3046]: go-librespot daemon starting... Apr 10 09:42:39 matts-music sudo[3042]: pam_unix(sudo:session): session closed for user root Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=info msg="running go-librespot 0.7.1" Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=debug msg="app state loaded" Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=debug msg="stored credentials not found" Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 10 09:42:39 matts-music volumio[1478]: info: New Spotify access tokenBQBirWbGSW... Apr 10 09:42:39 matts-music volumio[1478]: info: Spotify credentials grant success - running version from March 24, 2019 Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetVisibleSources Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 10 09:42:39 matts-music volumio[1478]: info: Received Get System Info Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 10 09:42:39 matts-music volumio[1478]: info: Discovery: Getting this device information Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:42:39 matts-music volumio[1478]: info: Listing playlists Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=info msg="zeroconf server listening on port 33277" Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Apr 10 09:42:39 matts-music volumio[1478]: SPOTIFY: User informations: {"country":"US","display_name":"Quester","email":"questerfox@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31n6nh6ne7itvnlvs67p6wm5fzeq"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31n6nh6ne7itvnlvs67p6wm5fzeq","id":"31n6nh6ne7itvnlvs67p6wm5fzeq","images":[],"product":"premium","type":"user","uri":"spotify:user:31n6nh6ne7itvnlvs67p6wm5fzeq"} Apr 10 09:42:39 matts-music volumio[1478]: info: Spotify Successfully logged in Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 10 09:42:39 matts-music volumio[1478]: info: [1775828559628] CoreMusicLibrary::Adding element Spotify Apr 10 09:42:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 10 09:42:39 matts-music volumio[1478]: Cannot find translation for source Radio Paradise (RP2) Apr 10 09:42:39 matts-music volumio[1478]: Cannot find translation for source YouTube2 Apr 10 09:42:39 matts-music volumio[1478]: Cannot find translation for source Personal Radio Apr 10 09:42:39 matts-music volumio[1478]: Cannot find translation for source Randomizer Apr 10 09:42:39 matts-music volumio[1478]: Cannot find translation for source Spotify Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=debug msg="obtained new client token: AACfpt8vQpLAucX2DZLck+qIFEtNVl5QVSoDsM8l4UYEwsTNnB+TsykZ58NxE2TlDo+Kk3XW1FbWrCeH3O0Tno8IEMCRQVDe+Sd7TzTIp3pimWoZ30Olt/WYgkCnHiZqs0d2gpXzzSXO/F26oKM3qCbfdNF1xH4x0hrulccuMDGi2rJorXZ36Sytt+vUe5m4xti8TiufkjxHVQNZ9NtG4BgTunqdlaL4aB1zi7eZ1w2asONY5/Tu8FM=" Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=debug msg="completed keyexchange" Apr 10 09:42:39 matts-music go-librespot[3047]: time="2026-04-10T09:42:39-04:00" level=debug msg="completed challenge" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=info msg="authenticated AP" username="31************************eq" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=info msg="authenticated Login5" username="31************************eq" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=debug msg="stored credentials" username="31************************eq" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=debug msg="initializing zeroconf session" username="31************************eq" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=debug msg="dealer connection opened" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=trace msg="starting accesspoint recv loop" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=trace msg="starting dealer recv loop" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=trace msg="received accesspoint ping" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=debug msg="received connection id: NWEwOGM1YjMtZWMw...QzUyQTlCMERGMQ==" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=trace msg="received accesspoint pong ack" Apr 10 09:42:40 matts-music go-librespot[3047]: time="2026-04-10T09:42:40-04:00" level=debug msg="put connect state because NEW_DEVICE" Apr 10 09:42:41 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 10 09:42:41 matts-music volumio[1478]: info: Received Get System Info Apr 10 09:42:41 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 10 09:42:41 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 10 09:42:41 matts-music volumio[1478]: info: Discovery: Getting this device information Apr 10 09:42:41 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:42:41 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 10 09:42:41 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 10 09:42:41 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Apr 10 09:42:42 matts-music volumio[1478]: info: Initializing connection to go-librespot Websocket Apr 10 09:42:42 matts-music go-librespot[3047]: time="2026-04-10T09:42:42-04:00" level=debug msg="new websocket client" Apr 10 09:42:42 matts-music volumio[1478]: info: Connection to go-librespot Websocket established Apr 10 09:42:42 matts-music volumio[1478]: info: go-librespot daemon successfully initialized Apr 10 09:42:44 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 10 09:42:44 matts-music volumio[1478]: info: Received Get System Info Apr 10 09:42:44 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 10 09:42:44 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 10 09:42:44 matts-music volumio[1478]: info: Discovery: Getting this device information Apr 10 09:42:44 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:42:44 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 10 09:42:45 matts-music volumio[1478]: info: Getting Spotify volume Apr 10 09:42:45 matts-music volumio[1478]: info: Spotify volume: 100 Apr 10 09:42:45 matts-music volumio[1478]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Apr 10 09:42:45 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:42:45 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:42:45 matts-music volumio[1478]: SPOTIFY: SPOTIFY VOLUME 100 Apr 10 09:42:45 matts-music volumio[1478]: SPOTIFY: VOLUMIO VOLUME 46 Apr 10 09:42:45 matts-music volumio[1478]: SPOTIFY: DELTA VOLUME ENOUGH: true Apr 10 09:42:45 matts-music volumio[1478]: info: Setting Spotify Volume from Volumio: 46 Apr 10 09:42:45 matts-music volumio[1478]: info: Initializing connection to go-librespot Websocket Apr 10 09:42:45 matts-music go-librespot[3047]: time="2026-04-10T09:42:45-04:00" level=debug msg="new websocket client" Apr 10 09:42:45 matts-music volumio[1478]: info: Connection to go-librespot Websocket established Apr 10 09:42:46 matts-music volumio[1478]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Apr 10 09:42:46 matts-music volumio[1478]: info: Sending Spotify command with payload to local API: /player/volume Apr 10 09:42:46 matts-music go-librespot[3047]: time="2026-04-10T09:42:46-04:00" level=debug msg="update volume requested to 30146/65535" Apr 10 09:42:46 matts-music go-librespot[3047]: time="2026-04-10T09:42:46-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 10 09:42:46 matts-music go-librespot[3047]: time="2026-04-10T09:42:46-04:00" level=trace msg="emitting websocket event: volume" Apr 10 09:42:46 matts-music volumio[1478]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Apr 10 09:42:46 matts-music volumio[1478]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Apr 10 09:42:46 matts-music volumio[1478]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Apr 10 09:42:46 matts-music volumio[1478]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Apr 10 09:42:48 matts-music volumio[1478]: info: Getting Spotify volume Apr 10 09:42:48 matts-music volumio[1478]: info: Spotify volume: 46 Apr 10 09:42:48 matts-music volumio[1478]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Apr 10 09:42:48 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:42:48 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:42:49 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 10 09:42:57 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 10 09:42:57 matts-music volumio[1478]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Apr 10 09:42:57 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Apr 10 09:42:57 matts-music volumio[1478]: info: Received Get System Version Apr 10 09:42:57 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 10 09:42:57 matts-music volumio[1478]: info: Received Get System Info Apr 10 09:42:57 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 10 09:42:57 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 10 09:42:57 matts-music volumio[1478]: info: Discovery: Getting this device information Apr 10 09:42:57 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:42:57 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 10 09:43:10 matts-music go-librespot[3047]: time="2026-04-10T09:43:10-04:00" level=trace msg="sent dealer ping" Apr 10 09:43:10 matts-music go-librespot[3047]: time="2026-04-10T09:43:10-04:00" level=trace msg="received dealer pong" Apr 10 09:43:11 matts-music volumio[1478]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Apr 10 09:43:11 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Apr 10 09:43:11 matts-music volumio[1478]: info: Creating Spotify config file Apr 10 09:43:11 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 09:43:11 matts-music volumio[1478]: info: Spotify config file written Apr 10 09:43:11 matts-music sudo[3120]: volumio : unable to resolve host matts-music: System error Apr 10 09:43:11 matts-music sudo[3120]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 10 09:43:11 matts-music sudo[3120]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 09:43:11 matts-music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Apr 10 09:43:11 matts-music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Apr 10 09:43:11 matts-music volumio[1478]: info: Connection to go-librespot Websocket closed Apr 10 09:43:11 matts-music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:11 matts-music volumio[1478]: info: Connection to go-librespot Websocket closed Apr 10 09:43:11 matts-music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:11 matts-music go-librespot[3122]: go-librespot daemon starting... Apr 10 09:43:11 matts-music sudo[3120]: pam_unix(sudo:session): session closed for user root Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=info msg="running go-librespot 0.7.1" Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=debug msg="app state loaded" Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=info msg="zeroconf server listening on port 40727" Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params"},{"subscriptionId":7,"prop":"audio-codec-name"}] Apr 10 09:43:12 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Push Volumio state: {"status":"play","uri":"rp2/channel@id=0","title":"Chasing Cars","artist":"Sofi Tukker","album":"Chasing Cars","albumart":"https://img.radioparadise.com/covers/l/18625.jpg","trackType":"The Main Mix","duration":277.643,"service":"rp2","seek":277226.22900000005,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":46,"mute":false,"disableVolumeControl":false,"codec":"flac"} Apr 10 09:43:12 matts-music volumio[1478]: info: CoreCommandRouter::servicePushState Apr 10 09:43:12 matts-music volumio[1478]: info: CoreStateMachine::pushState Apr 10 09:43:12 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 10 09:43:12 matts-music volumio[1478]: info: CoreCommandRouter::volumioPushState Apr 10 09:43:12 matts-music volumio5-onboarding[1769]: time=2026-04-10T09:43:12.339-04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 277226.22900000005 into Go struct field State.seek of type int" Apr 10 09:43:12 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=debug msg="obtained new client token: AAC2ZkSjsvFe6G7wZl9THCWZHu1MmDTF6c2OvguSlI2ymNrFSM9WKqIiJOh9koPn4wu6u8M442m8XE7xj3vxBzLBJ1DnQV4KHPL/v0OZWZqVuWyf96AASOBTn7IsBmfdXQsjInE29My7KywZ7lQZPfO0+g69sHlARTAigFgjizekqN17Lq1MCGoCGvnuuf9FSa35rYpPHwBX3KYfZMmHt7BqaN5tbwyrpTo3fNMa7iUL8NOELpv0fAc=" Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=debug msg="completed keyexchange" Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=debug msg="completed challenge" Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=info msg="authenticated AP" username="31************************eq" Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] About to reach end of stream in current block. Going to obtain next block. Apr 10 09:43:12 matts-music volumio[1478]: verbose: [rp2] Waiting for player to stop before fetching next block... Apr 10 09:43:12 matts-music volumio[1478]: verbose: [rp2] Waiting for player event "stopped"... Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration"},{"subscriptionId":3,"prop":"idle-active","data":true},{"subscriptionId":8,"prop":"media-title"},{"subscriptionId":9,"prop":"metadata"}] Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Player status "stopped" - skip unset volatile because unset condition is "manual" Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Player status "stopped" - skip unset volatile because unset condition is "manual" Apr 10 09:43:12 matts-music volumio[1478]: verbose: [rp2] Received player event "stopped"... Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Player status "stopped" - skip unset volatile because unset condition is "manual" Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Player status "stopped" - skip unset volatile because unset condition is "manual" Apr 10 09:43:12 matts-music volumio[1478]: verbose: [rp2] API: https://api.radioparadise.com/api/play?source=24&event=2860637&elapsed=1&bitrate=4&action=play&player_id=********&info=true&chan=0&slice_num=7&episode_id=0&audio_type=M Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=info msg="authenticated Login5" username="31************************eq" Apr 10 09:43:12 matts-music go-librespot[3123]: time="2026-04-10T09:43:12-04:00" level=debug msg="initializing zeroconf session" username="31************************eq" Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] Obtained updated block Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] ------------- Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] Block summary Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] ------------- Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] Stream URL: https://audio-geo.radioparadise.com/promos/0/4/2206.flac?2860638 Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] Tracks: Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] 0. Listener-supported (0:05 | elapsed: 0s) Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Player status "stopped" - skip unset volatile because unset condition is "manual" Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] Going to start playback of current track Apr 10 09:43:12 matts-music volumio[1478]: verbose: [rp2] Waiting for player event "playing"... Apr 10 09:43:12 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Send IPC command: {"command":["set_property","loop-file","no"],"request_id":20} Apr 10 09:43:12 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Got response for command #20: {"request_id":20,"error":"success"} Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Push Volumio state: {"status":"pause","albumart":"https://img.radioparadise.com/covers/l/104.jpg","uri":"rp2/channel@id=0","seek":0,"duration":5.925,"service":"rp2","stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":46,"mute":false,"disableVolumeControl":false,"title":"Listener-supported","artist":"Commercial-free","codec":"flac","trackType":"The Main Mix"} Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::servicePushState Apr 10 09:43:13 matts-music volumio[1478]: info: CoreStateMachine::pushState Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::volumioPushState Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Send IPC command: {"command":["loadfile","https://audio-geo.radioparadise.com/promos/0/4/2206.flac?2860638","replace","start=0"],"request_id":21} Apr 10 09:43:13 matts-music volumio5-onboarding[1769]: time=2026-04-10T09:43:13.007-04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 5.925 into Go struct field State.duration of type int" Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Got response for command #21: {"data":{"playlist_entry_id":3},"request_id":21,"error":"success"} Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Status update -> property-change events: [{"subscriptionId":3,"prop":"idle-active","data":false},{"subscriptionId":8,"prop":"media-title","data":"2206.flac?2860638"}] Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Send IPC command: {"command":["set_property","pause",false],"request_id":22} Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Push Volumio state: {"status":"play","uri":"rp2/channel@id=0","title":"Listener-supported","artist":"Commercial-free","albumart":"https://img.radioparadise.com/covers/l/104.jpg","trackType":"The Main Mix","duration":5.925,"service":"rp2","seek":0,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":46,"mute":false,"disableVolumeControl":false,"codec":"flac"} Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::servicePushState Apr 10 09:43:13 matts-music volumio[1478]: info: CoreStateMachine::pushState Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::volumioPushState Apr 10 09:43:13 matts-music volumio[1478]: verbose: [rp2] Received player event "playing"... Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] Started playback of "Listener-supported" - estimated finish time: 4/10/2026, 9:43:18 AM Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:13 matts-music volumio[1478]: verbose: [rp2] After "Listener-supported", prepare to fetch the next block in 5s (4/10/2026, 9:43:18 AM) Apr 10 09:43:13 matts-music volumio5-onboarding[1769]: time=2026-04-10T09:43:13.026-04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 5.925 into Go struct field State.duration of type int" Apr 10 09:43:13 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:13 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Got response for command #22: {"request_id":22,"error":"success"} Apr 10 09:43:13 matts-music volumio[1478]: info: touch_display: Setting screensaver timeout to 120 seconds. Apr 10 09:43:13 matts-music go-librespot[3123]: time="2026-04-10T09:43:13-04:00" level=debug msg="dealer connection opened" Apr 10 09:43:13 matts-music go-librespot[3123]: time="2026-04-10T09:43:13-04:00" level=trace msg="starting accesspoint recv loop" Apr 10 09:43:13 matts-music go-librespot[3123]: time="2026-04-10T09:43:13-04:00" level=trace msg="starting dealer recv loop" Apr 10 09:43:13 matts-music go-librespot[3123]: time="2026-04-10T09:43:13-04:00" level=trace msg="received accesspoint ping" Apr 10 09:43:13 matts-music go-librespot[3123]: time="2026-04-10T09:43:13-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 10 09:43:13 matts-music go-librespot[3123]: time="2026-04-10T09:43:13-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 10 09:43:13 matts-music go-librespot[3123]: time="2026-04-10T09:43:13-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 10 09:43:13 matts-music go-librespot[3123]: time="2026-04-10T09:43:13-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 10 09:43:13 matts-music go-librespot[3123]: time="2026-04-10T09:43:13-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 10 09:43:13 matts-music go-librespot[3123]: time="2026-04-10T09:43:13-04:00" level=debug msg="received connection id: OTNlODEzZDUtZTAw...NzYwRUMyMDM1Ng==" Apr 10 09:43:13 matts-music go-librespot[3123]: time="2026-04-10T09:43:13-04:00" level=trace msg="received accesspoint pong ack" Apr 10 09:43:13 matts-music go-librespot[3123]: time="2026-04-10T09:43:13-04:00" level=debug msg="put connect state because NEW_DEVICE" Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) (+) Audio --aid=1 (flac 2ch 44100Hz) Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration","data":5.924717},{"subscriptionId":7,"prop":"audio-codec-name","data":"flac"}] Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Status update -> property-change events: [{"subscriptionId":9,"prop":"metadata","data":{}}] Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) AO: [alsa] 44100Hz stereo 2ch s16 Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params","data":{"samplerate":44100,"channel-count":2,"channels":"stereo","hr-channels":"stereo","format":"s16"}}] Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:13 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Push Volumio state: {"status":"play","uri":"rp2/channel@id=0","title":"Listener-supported","artist":"Commercial-free","albumart":"https://img.radioparadise.com/covers/l/104.jpg","trackType":"The Main Mix - ","duration":5.925,"samplerate":"44.1 kHz","bitdepth":"16-bit","channels":2,"service":"rp2","seek":0,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":46,"mute":false,"disableVolumeControl":false,"codec":"flac"} Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::servicePushState Apr 10 09:43:13 matts-music volumio[1478]: info: CoreStateMachine::pushState Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::volumioPushState Apr 10 09:43:13 matts-music volumio5-onboarding[1769]: time=2026-04-10T09:43:13.602-04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 5.925 into Go struct field State.duration of type int" Apr 10 09:43:13 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:13 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:14 matts-music volumio[1478]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Apr 10 09:43:14 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Apr 10 09:43:14 matts-music volumio[1478]: info: Creating Spotify config file Apr 10 09:43:14 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 09:43:14 matts-music volumio[1478]: info: Spotify config file written Apr 10 09:43:14 matts-music sudo[3139]: volumio : unable to resolve host matts-music: System error Apr 10 09:43:14 matts-music sudo[3139]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 10 09:43:14 matts-music sudo[3139]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 09:43:14 matts-music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Apr 10 09:43:14 matts-music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Apr 10 09:43:14 matts-music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:14 matts-music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:14 matts-music go-librespot[3141]: go-librespot daemon starting... Apr 10 09:43:14 matts-music sudo[3139]: pam_unix(sudo:session): session closed for user root Apr 10 09:43:14 matts-music go-librespot[3142]: time="2026-04-10T09:43:14-04:00" level=info msg="running go-librespot 0.7.1" Apr 10 09:43:14 matts-music go-librespot[3142]: time="2026-04-10T09:43:14-04:00" level=debug msg="app state loaded" Apr 10 09:43:14 matts-music go-librespot[3142]: time="2026-04-10T09:43:14-04:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 10 09:43:14 matts-music volumio[1478]: info: Initializing connection to go-librespot Websocket Apr 10 09:43:14 matts-music go-librespot[3142]: time="2026-04-10T09:43:14-04:00" level=debug msg="new websocket client" Apr 10 09:43:14 matts-music volumio[1478]: info: Connection to go-librespot Websocket established Apr 10 09:43:14 matts-music volumio[1478]: info: go-librespot daemon successfully initialized Apr 10 09:43:15 matts-music volumio[1478]: verbose: [rp2] Checking if next track interval requires adjusting (1/1)... Apr 10 09:43:15 matts-music volumio[1478]: verbose: [rp2] Recalculated next track interval exceeds current by 692.567ms. Going to re-adjust. Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=info msg="zeroconf server listening on port 37737" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=debug msg="obtained new client token: AAAKW8qOoYKvWuVUTl0FlGTIoCsohfELsoT3i9k56aG2XOT6EFXooP+frreo/LUCAXZ7v33ji8oJK6aMZvFmeKWOWEQ2UGMYsaWoWR8LrHvaLy+VdvQlU0Jmn4g8BYTVEkFMT4nUkJnC0PbaHM3jAPxnDa3ZXpQ0uNriYVWS2dpW0xrZznqwBiFh9NMdYW0hyxSCv/qXbrN338MKSGy+1hk8HCtzNI10JcS70JCISSVSlM90yr/V" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=debug msg="completed keyexchange" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=debug msg="completed challenge" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=info msg="authenticated AP" username="31************************eq" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=info msg="authenticated Login5" username="31************************eq" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=debug msg="initializing zeroconf session" username="31************************eq" Apr 10 09:43:15 matts-music volumio[1478]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Apr 10 09:43:15 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Apr 10 09:43:15 matts-music volumio[1478]: info: Creating Spotify config file Apr 10 09:43:15 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 09:43:15 matts-music volumio[1478]: info: Spotify config file written Apr 10 09:43:15 matts-music sudo[3153]: volumio : unable to resolve host matts-music: System error Apr 10 09:43:15 matts-music sudo[3153]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 10 09:43:15 matts-music sudo[3153]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=debug msg="dealer connection opened" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=trace msg="starting accesspoint recv loop" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=trace msg="starting dealer recv loop" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=trace msg="received accesspoint ping" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 10 09:43:15 matts-music go-librespot[3142]: time="2026-04-10T09:43:15-04:00" level=debug msg="received connection id: MmVkMjQ2ZmItYjI1...QTREODc2NjIxQQ==" Apr 10 09:43:16 matts-music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Apr 10 09:43:16 matts-music systemd[1]: go-librespot-daemon.service: Killing process 3147 (go-librespot) with signal SIGKILL. Apr 10 09:43:16 matts-music volumio[1478]: info: Connection to go-librespot Websocket closed Apr 10 09:43:16 matts-music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Apr 10 09:43:16 matts-music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:16 matts-music go-librespot[3155]: go-librespot daemon starting... Apr 10 09:43:16 matts-music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:16 matts-music sudo[3153]: pam_unix(sudo:session): session closed for user root Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=info msg="running go-librespot 0.7.1" Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=debug msg="app state loaded" Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=info msg="zeroconf server listening on port 43967" Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=debug msg="obtained new client token: AACdwPTCFdnamwUzEomL/q3kEgDTs/nWiwvW6ig5K7slG0C133vpwg7RhsjvB84iSQLIjbx0HOyQj9dpGE3++KgKtq/1A3C7THigvUq4acPiHr/ydxSiedhp3uQ3pM/66kIEthh2ZqimEKWSfQqUzokkfD+QDmeqO9SChuj/6R+FyAvPjghh8KPd+4ZteLUgiYzzloyFN5IoSNOgN+N3gYEnKR0mGzsmFK1mQkvTqL8FnNoXIgxiJQc=" Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=debug msg="completed keyexchange" Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=debug msg="completed challenge" Apr 10 09:43:16 matts-music go-librespot[3156]: time="2026-04-10T09:43:16-04:00" level=info msg="authenticated AP" username="31************************eq" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=info msg="authenticated Login5" username="31************************eq" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=debug msg="initializing zeroconf session" username="31************************eq" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=debug msg="dealer connection opened" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=trace msg="starting accesspoint recv loop" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=trace msg="starting dealer recv loop" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=trace msg="received accesspoint ping" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=debug msg="received connection id: N2Q5YTcwOWYtM2Yy...ODJGQjUwMUI5NQ==" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=trace msg="received accesspoint pong ack" Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=debug msg="put connect state because NEW_DEVICE" Apr 10 09:43:17 matts-music volumio[1478]: info: go-librespot daemon successfully initialized Apr 10 09:43:17 matts-music volumio[1478]: info: Getting Spotify volume Apr 10 09:43:17 matts-music volumio[1478]: info: Spotify volume: 100 Apr 10 09:43:17 matts-music volumio[1478]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Apr 10 09:43:17 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:17 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:17 matts-music volumio[1478]: SPOTIFY: SPOTIFY VOLUME 100 Apr 10 09:43:17 matts-music volumio[1478]: SPOTIFY: VOLUMIO VOLUME 46 Apr 10 09:43:17 matts-music volumio[1478]: SPOTIFY: DELTA VOLUME ENOUGH: true Apr 10 09:43:17 matts-music volumio[1478]: info: Setting Spotify Volume from Volumio: 46 Apr 10 09:43:17 matts-music volumio[1478]: info: Initializing connection to go-librespot Websocket Apr 10 09:43:17 matts-music go-librespot[3156]: time="2026-04-10T09:43:17-04:00" level=debug msg="new websocket client" Apr 10 09:43:17 matts-music volumio[1478]: info: Connection to go-librespot Websocket established Apr 10 09:43:19 matts-music volumio[1478]: info: Initializing connection to go-librespot Websocket Apr 10 09:43:19 matts-music go-librespot[3156]: time="2026-04-10T09:43:19-04:00" level=debug msg="new websocket client" Apr 10 09:43:19 matts-music volumio[1478]: info: Connection to go-librespot Websocket established Apr 10 09:43:19 matts-music volumio[1478]: info: go-librespot daemon successfully initialized Apr 10 09:43:19 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params"},{"subscriptionId":7,"prop":"audio-codec-name"}] Apr 10 09:43:19 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:19 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Push Volumio state: {"status":"play","uri":"rp2/channel@id=0","title":"Listener-supported","artist":"Commercial-free","albumart":"https://img.radioparadise.com/covers/l/104.jpg","trackType":"The Main Mix","duration":5.925,"service":"rp2","seek":5596.688999999999,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":46,"mute":false,"disableVolumeControl":false,"codec":"flac"} Apr 10 09:43:19 matts-music volumio[1478]: info: CoreCommandRouter::servicePushState Apr 10 09:43:19 matts-music volumio[1478]: info: CoreStateMachine::pushState Apr 10 09:43:19 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 10 09:43:19 matts-music volumio[1478]: info: CoreCommandRouter::volumioPushState Apr 10 09:43:19 matts-music volumio5-onboarding[1769]: time=2026-04-10T09:43:19.251-04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 5596.688999999999 into Go struct field State.seek of type int" Apr 10 09:43:19 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Apr 10 09:43:19 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:19 matts-music volumio[1478]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Apr 10 09:43:19 matts-music volumio[1478]: info: Sending Spotify command with payload to local API: /player/volume Apr 10 09:43:19 matts-music go-librespot[3156]: time="2026-04-10T09:43:19-04:00" level=debug msg="update volume requested to 30146/65535" Apr 10 09:43:19 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration"},{"subscriptionId":3,"prop":"idle-active","data":true}] Apr 10 09:43:19 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Player status "stopped" - skip unset volatile because unset condition is "manual" Apr 10 09:43:19 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Player status "stopped" - skip unset volatile because unset condition is "manual" Apr 10 09:43:19 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Status update -> property-change events: [{"subscriptionId":8,"prop":"media-title"},{"subscriptionId":9,"prop":"metadata"}] Apr 10 09:43:19 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Player status "stopped" - skip unset volatile because unset condition is "manual" Apr 10 09:43:19 matts-music volumio[1478]: info: [rp2] About to reach end of stream in current block. Going to obtain next block. Apr 10 09:43:19 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Player status "stopped" - skip unset volatile because unset condition is "manual" Apr 10 09:43:19 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Player status "stopped" - skip unset volatile because unset condition is "manual" Apr 10 09:43:19 matts-music volumio[1478]: verbose: [rp2] API: https://api.radioparadise.com/api/play?source=24&event=2860638&elapsed=1&bitrate=4&action=play&player_id=********&info=true&chan=0&slice_num=0&episode_id=0&audio_type=P Apr 10 09:43:19 matts-music go-librespot[3156]: time="2026-04-10T09:43:19-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 10 09:43:19 matts-music go-librespot[3156]: time="2026-04-10T09:43:19-04:00" level=trace msg="emitting websocket event: volume" Apr 10 09:43:19 matts-music volumio[1478]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Apr 10 09:43:19 matts-music volumio[1478]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Apr 10 09:43:19 matts-music volumio[1478]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Apr 10 09:43:19 matts-music volumio[1478]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Apr 10 09:43:20 matts-music volumio[1478]: info: Initializing connection to go-librespot Websocket Apr 10 09:43:20 matts-music go-librespot[3156]: time="2026-04-10T09:43:20-04:00" level=debug msg="new websocket client" Apr 10 09:43:20 matts-music volumio[1478]: info: Connection to go-librespot Websocket established Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] Obtained updated block Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] ------------- Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] Block summary Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] ------------- Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] Stream URL: https://audio-geo.radioparadise.com/chan/0/x/2102/4/b/2102-0.flac Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] Tracks: Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] 0. Helicopters (w/ Greentea Peng) (3:50 | elapsed: 0s) Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] 1. Cold Little Heart (9:46 | elapsed: 3m 50s) Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] 2. The White Winds (2:45 | elapsed: 13m 37s) Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] 3. In My Own Way (6:33 | elapsed: 16m 22s) Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] 4. Yemanja (3:57 | elapsed: 22m 55s) Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Player status "stopped" - skip unset volatile because unset condition is "manual" Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] Going to start playback of current track Apr 10 09:43:20 matts-music volumio[1478]: verbose: [rp2] Waiting for player event "playing"... Apr 10 09:43:20 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Send IPC command: {"command":["set_property","loop-file","no"],"request_id":23} Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Got response for command #23: {"request_id":23,"error":"success"} Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Push Volumio state: {"status":"pause","albumart":"https://img.radioparadise.com/covers/l/27316.jpg","uri":"rp2/channel@id=0","seek":0,"duration":230.838,"service":"rp2","stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":46,"mute":false,"disableVolumeControl":false,"title":"Helicopters (w/ Greentea Peng)","artist":"Ezra Collective","album":"War Records sampler","codec":"flac","trackType":"The Main Mix"} Apr 10 09:43:20 matts-music volumio[1478]: info: CoreCommandRouter::servicePushState Apr 10 09:43:20 matts-music volumio[1478]: info: CoreStateMachine::pushState Apr 10 09:43:20 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 10 09:43:20 matts-music volumio[1478]: info: CoreCommandRouter::volumioPushState Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Send IPC command: {"command":["loadfile","https://audio-geo.radioparadise.com/chan/0/x/2102/4/b/2102-0.flac","replace","start=0"],"request_id":24} Apr 10 09:43:20 matts-music volumio5-onboarding[1769]: time=2026-04-10T09:43:20.853-04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 230.838 into Go struct field State.duration of type int" Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Got response for command #24: {"data":{"playlist_entry_id":4},"request_id":24,"error":"success"} Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Status update -> property-change events: [{"subscriptionId":3,"prop":"idle-active","data":false},{"subscriptionId":8,"prop":"media-title","data":"2102-0.flac"}] Apr 10 09:43:20 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Send IPC command: {"command":["set_property","pause",false],"request_id":25} Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Push Volumio state: {"status":"play","uri":"rp2/channel@id=0","title":"Helicopters (w/ Greentea Peng)","artist":"Ezra Collective","album":"War Records sampler","albumart":"https://img.radioparadise.com/covers/l/27316.jpg","trackType":"The Main Mix","duration":230.838,"service":"rp2","seek":0,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":46,"mute":false,"disableVolumeControl":false,"codec":"flac"} Apr 10 09:43:20 matts-music volumio[1478]: info: CoreCommandRouter::servicePushState Apr 10 09:43:20 matts-music volumio[1478]: info: CoreStateMachine::pushState Apr 10 09:43:20 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 10 09:43:20 matts-music volumio[1478]: info: CoreCommandRouter::volumioPushState Apr 10 09:43:20 matts-music volumio[1478]: verbose: [rp2] Received player event "playing"... Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] Started playback of "Helicopters (w/ Greentea Peng)" - estimated finish time: 4/10/2026, 9:47:11 AM Apr 10 09:43:20 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:20 matts-music volumio[1478]: verbose: [rp2] After "Helicopters (w/ Greentea Peng)", the next track will start in 3m 50s (4/10/2026, 9:47:11 AM) Apr 10 09:43:20 matts-music volumio[1478]: verbose: [rp2] API: https://api.radioparadise.com/api/update_history?source=24&song_id=61392&chan=0&player_id=********&event=2860639&type=M&slice_num=0&episode_id=0&time_relative=-0&play_position_millis=0&playtime_secs=1775828601 Apr 10 09:43:20 matts-music volumio5-onboarding[1769]: time=2026-04-10T09:43:20.867-04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 230.838 into Go struct field State.duration of type int" Apr 10 09:43:20 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:20 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:20 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Got response for command #25: {"request_id":25,"error":"success"} Apr 10 09:43:20 matts-music volumio[1478]: info: touch_display: Setting screensaver timeout to 120 seconds. Apr 10 09:43:21 matts-music volumio[1478]: info: Getting Spotify volume Apr 10 09:43:21 matts-music volumio[1478]: info: Spotify volume: 46 Apr 10 09:43:21 matts-music volumio[1478]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Apr 10 09:43:21 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:21 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:21 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) (+) Audio --aid=1 (flac 2ch 44100Hz) Apr 10 09:43:21 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Status update -> property-change events: [{"subscriptionId":2,"prop":"duration","data":1612.989002},{"subscriptionId":7,"prop":"audio-codec-name","data":"flac"},{"subscriptionId":9,"prop":"metadata","data":{}}] Apr 10 09:43:21 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:21 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) AO: [alsa] 44100Hz stereo 2ch s16 Apr 10 09:43:21 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Status update -> property-change events: [{"subscriptionId":6,"prop":"audio-params","data":{"samplerate":44100,"channel-count":2,"channels":"stereo","hr-channels":"stereo","format":"s16"}}] Apr 10 09:43:21 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:21 matts-music volumio[1478]: info: [rp2] [mpv] (PID: 2336) Push Volumio state: {"status":"play","uri":"rp2/channel@id=0","title":"Helicopters (w/ Greentea Peng)","artist":"Ezra Collective","album":"War Records sampler","albumart":"https://img.radioparadise.com/covers/l/27316.jpg","trackType":"The Main Mix - ","duration":230.838,"samplerate":"44.1 kHz","bitdepth":"16-bit","channels":2,"service":"rp2","seek":0,"stream":false,"repeat":false,"repeatSingle":false,"random":false,"volume":46,"mute":false,"disableVolumeControl":false,"codec":"flac"} Apr 10 09:43:21 matts-music volumio[1478]: info: CoreCommandRouter::servicePushState Apr 10 09:43:21 matts-music volumio[1478]: info: CoreStateMachine::pushState Apr 10 09:43:21 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 10 09:43:21 matts-music volumio[1478]: info: CoreCommandRouter::volumioPushState Apr 10 09:43:21 matts-music volumio5-onboarding[1769]: time=2026-04-10T09:43:21.459-04:00 level=ERROR msg="failed to unmarshal pushState event" component=volumio/socket error="json: cannot unmarshal number 230.838 into Go struct field State.duration of type int" Apr 10 09:43:21 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:21 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:22 matts-music volumio[1478]: info: Getting Spotify volume Apr 10 09:43:22 matts-music volumio[1478]: info: Spotify volume: 46 Apr 10 09:43:22 matts-music volumio[1478]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Apr 10 09:43:22 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:22 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:22 matts-music volumio[1478]: info: Initializing connection to go-librespot Websocket Apr 10 09:43:22 matts-music go-librespot[3156]: time="2026-04-10T09:43:22-04:00" level=debug msg="new websocket client" Apr 10 09:43:22 matts-music volumio[1478]: info: Connection to go-librespot Websocket established Apr 10 09:43:22 matts-music volumio[1478]: verbose: [rp2] Checking if next track interval requires adjusting (1/5)... Apr 10 09:43:22 matts-music volumio[1478]: verbose: [rp2] Recalculated next track interval exceeds current by 714.7390000000014ms. Going to re-adjust. Apr 10 09:43:23 matts-music volumio[1478]: info: Getting Spotify volume Apr 10 09:43:23 matts-music volumio[1478]: info: Spotify volume: 46 Apr 10 09:43:23 matts-music volumio[1478]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Apr 10 09:43:23 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:23 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:24 matts-music volumio[1478]: verbose: [rp2] Checking if next track interval requires adjusting (2/5)... Apr 10 09:43:24 matts-music volumio[1478]: verbose: [rp2] Next track interval is accurate Apr 10 09:43:25 matts-music volumio[1478]: info: Getting Spotify volume Apr 10 09:43:25 matts-music volumio[1478]: info: Spotify volume: 46 Apr 10 09:43:25 matts-music volumio[1478]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Apr 10 09:43:25 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:25 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:26 matts-music volumio[1478]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Apr 10 09:43:26 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Apr 10 09:43:26 matts-music volumio[1478]: info: Creating Spotify config file Apr 10 09:43:26 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 09:43:26 matts-music volumio[1478]: info: Spotify config file written Apr 10 09:43:26 matts-music sudo[3186]: volumio : unable to resolve host matts-music: System error Apr 10 09:43:26 matts-music sudo[3186]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 10 09:43:26 matts-music sudo[3186]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 09:43:26 matts-music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Apr 10 09:43:26 matts-music systemd[1]: go-librespot-daemon.service: Killing process 3157 (go-librespot) with signal SIGKILL. Apr 10 09:43:26 matts-music volumio[1478]: info: Connection to go-librespot Websocket closed Apr 10 09:43:26 matts-music systemd[1]: go-librespot-daemon.service: Killing process 3159 (go-librespot) with signal SIGKILL. Apr 10 09:43:26 matts-music systemd[1]: go-librespot-daemon.service: Killing process 3160 (go-librespot) with signal SIGKILL. Apr 10 09:43:26 matts-music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Apr 10 09:43:26 matts-music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:26 matts-music volumio[1478]: info: Connection to go-librespot Websocket closed Apr 10 09:43:26 matts-music volumio[1478]: info: Connection to go-librespot Websocket closed Apr 10 09:43:26 matts-music volumio[1478]: info: Connection to go-librespot Websocket closed Apr 10 09:43:26 matts-music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:26 matts-music go-librespot[3188]: go-librespot daemon starting... Apr 10 09:43:26 matts-music sudo[3186]: pam_unix(sudo:session): session closed for user root Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=info msg="running go-librespot 0.7.1" Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=debug msg="app state loaded" Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=info msg="zeroconf server listening on port 42569" Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=debug msg="obtained new client token: AACtn0jdcE0All8VFqlySYZLCE/VKZj0srWvVTSP8+xTFUO3st7Vw2rekPDBFLl4/WMNvx8Ux8bioUc/a5/n4DqlunhTKe8EzPaprYwmc/DKnzB5qjka+tfCkptmdIZieLEXlg7X8NIKLYvieEGbAukDnCcS6EV8Vz1LAuH+cfcea7wGxFUd0GPj3ekkefo727aBli9PsFoJl4RcF8HpC+TsK1xeu/ujeRAGZW6lnMbHQ8XWYqm2hyg=" Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=debug msg="completed keyexchange" Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=debug msg="completed challenge" Apr 10 09:43:26 matts-music volumio[1478]: verbose: [rp2] Checking if next track interval requires adjusting (3/5)... Apr 10 09:43:26 matts-music volumio[1478]: verbose: [rp2] Next track interval is accurate Apr 10 09:43:26 matts-music go-librespot[3189]: time="2026-04-10T09:43:26-04:00" level=info msg="authenticated AP" username="31************************eq" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=info msg="authenticated Login5" username="31************************eq" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=debug msg="initializing zeroconf session" username="31************************eq" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=debug msg="dealer connection opened" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=trace msg="starting accesspoint recv loop" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=trace msg="starting dealer recv loop" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=trace msg="received accesspoint ping" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=debug msg="received connection id: NjA0YzBmNWQtY2Qz...NERDMDAzMUQ2NQ==" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=trace msg="received accesspoint pong ack" Apr 10 09:43:27 matts-music go-librespot[3189]: time="2026-04-10T09:43:27-04:00" level=debug msg="put connect state because NEW_DEVICE" Apr 10 09:43:28 matts-music volumio[1478]: verbose: [rp2] Checking if next track interval requires adjusting (4/5)... Apr 10 09:43:28 matts-music volumio[1478]: verbose: [rp2] Next track interval is accurate Apr 10 09:43:29 matts-music volumio[1478]: info: Initializing connection to go-librespot Websocket Apr 10 09:43:29 matts-music go-librespot[3189]: time="2026-04-10T09:43:29-04:00" level=debug msg="new websocket client" Apr 10 09:43:29 matts-music volumio[1478]: info: Connection to go-librespot Websocket established Apr 10 09:43:29 matts-music volumio[1478]: info: go-librespot daemon successfully initialized Apr 10 09:43:30 matts-music volumio[1478]: verbose: [rp2] Checking if next track interval requires adjusting (5/5)... Apr 10 09:43:30 matts-music volumio[1478]: verbose: [rp2] Next track interval is accurate Apr 10 09:43:31 matts-music volumio[1478]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Apr 10 09:43:31 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Apr 10 09:43:31 matts-music volumio[1478]: info: Creating Spotify config file Apr 10 09:43:31 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 09:43:31 matts-music volumio[1478]: info: Spotify config file written Apr 10 09:43:32 matts-music sudo[3215]: volumio : unable to resolve host matts-music: System error Apr 10 09:43:32 matts-music sudo[3215]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 10 09:43:32 matts-music sudo[3215]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 09:43:32 matts-music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Apr 10 09:43:32 matts-music systemd[1]: go-librespot-daemon.service: Killing process 3192 (go-librespot) with signal SIGKILL. Apr 10 09:43:32 matts-music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Apr 10 09:43:32 matts-music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:32 matts-music volumio[1478]: info: Connection to go-librespot Websocket closed Apr 10 09:43:32 matts-music go-librespot[3217]: go-librespot daemon starting... Apr 10 09:43:32 matts-music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:32 matts-music sudo[3215]: pam_unix(sudo:session): session closed for user root Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=info msg="running go-librespot 0.7.1" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=debug msg="app state loaded" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 10 09:43:32 matts-music volumio[1478]: info: Getting Spotify volume Apr 10 09:43:32 matts-music volumio[1478]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Apr 10 09:43:32 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:32 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:32 matts-music volumio[1478]: info: Initializing connection to go-librespot Websocket Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=debug msg="new websocket client" Apr 10 09:43:32 matts-music volumio[1478]: info: Connection to go-librespot Websocket established Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=info msg="zeroconf server listening on port 42405" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=debug msg="obtained new client token: AACJmwGeUQwZx9V3Gexfh85Bl3kH8g08byN0nN8G9iFOAsYfm1QfBXQ0V1UKzJj1LZQeQlrmjem1IlmcHXaU2pdIrYAuDZ6uuGF3eAAFXYpCU2z02E/dRqK3HMCThjNvUIpabObk8JNoCoCMikHWUDlbXC6/jz/LbocbZ+1jefeXSNpxPXgmRfUpiH+XTJpiLAH9W8l8uqTHTE+UCi/AHsZGzGV+KR58MF1L4SLXTsvQdFbZTKbmcvI=" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=debug msg="completed keyexchange" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=debug msg="completed challenge" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=info msg="authenticated AP" username="31************************eq" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=info msg="authenticated Login5" username="31************************eq" Apr 10 09:43:32 matts-music go-librespot[3218]: time="2026-04-10T09:43:32-04:00" level=debug msg="initializing zeroconf session" username="31************************eq" Apr 10 09:43:33 matts-music go-librespot[3218]: time="2026-04-10T09:43:33-04:00" level=debug msg="dealer connection opened" Apr 10 09:43:33 matts-music go-librespot[3218]: time="2026-04-10T09:43:33-04:00" level=trace msg="starting accesspoint recv loop" Apr 10 09:43:33 matts-music go-librespot[3218]: time="2026-04-10T09:43:33-04:00" level=trace msg="starting dealer recv loop" Apr 10 09:43:33 matts-music go-librespot[3218]: time="2026-04-10T09:43:33-04:00" level=trace msg="received accesspoint ping" Apr 10 09:43:33 matts-music go-librespot[3218]: time="2026-04-10T09:43:33-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 10 09:43:33 matts-music go-librespot[3218]: time="2026-04-10T09:43:33-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 10 09:43:33 matts-music volumio[1478]: info: Spotify volume: 100 Apr 10 09:43:33 matts-music go-librespot[3218]: time="2026-04-10T09:43:33-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 10 09:43:33 matts-music go-librespot[3218]: time="2026-04-10T09:43:33-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 10 09:43:33 matts-music go-librespot[3218]: time="2026-04-10T09:43:33-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 10 09:43:33 matts-music go-librespot[3218]: time="2026-04-10T09:43:33-04:00" level=debug msg="received connection id: M2IxNTJhYTYtZGVk...QzBBM0RCQTU1NQ==" Apr 10 09:43:33 matts-music go-librespot[3218]: time="2026-04-10T09:43:33-04:00" level=trace msg="received accesspoint pong ack" Apr 10 09:43:33 matts-music go-librespot[3218]: time="2026-04-10T09:43:33-04:00" level=debug msg="put connect state because NEW_DEVICE" Apr 10 09:43:33 matts-music kernel: drm-rp1-dsi 1f00130000.dsi: [drm] rp1dsi: Command time (outvact): 33 Apr 10 09:43:33 matts-music kernel: drm-rp1-dsi 1f00130000.dsi: [drm] rp1dsi: Nominal Byte clock 90000000 DPI clock 30000000 (parent rate 90000000) Apr 10 09:43:35 matts-music volumio[1478]: info: Initializing connection to go-librespot Websocket Apr 10 09:43:35 matts-music go-librespot[3218]: time="2026-04-10T09:43:35-04:00" level=debug msg="new websocket client" Apr 10 09:43:35 matts-music volumio[1478]: info: Connection to go-librespot Websocket established Apr 10 09:43:35 matts-music volumio[1478]: info: go-librespot daemon successfully initialized Apr 10 09:43:35 matts-music volumio[1478]: info: Getting Spotify volume Apr 10 09:43:35 matts-music volumio[1478]: info: Spotify volume: 100 Apr 10 09:43:35 matts-music volumio[1478]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Apr 10 09:43:35 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:35 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:35 matts-music volumio[1478]: SPOTIFY: SPOTIFY VOLUME 100 Apr 10 09:43:35 matts-music volumio[1478]: SPOTIFY: VOLUMIO VOLUME 46 Apr 10 09:43:35 matts-music volumio[1478]: SPOTIFY: DELTA VOLUME ENOUGH: true Apr 10 09:43:35 matts-music volumio[1478]: info: Setting Spotify Volume from Volumio: 46 Apr 10 09:43:36 matts-music volumio[1478]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Apr 10 09:43:36 matts-music volumio[1478]: info: Sending Spotify command with payload to local API: /player/volume Apr 10 09:43:36 matts-music go-librespot[3218]: time="2026-04-10T09:43:36-04:00" level=debug msg="update volume requested to 30146/65535" Apr 10 09:43:36 matts-music go-librespot[3218]: time="2026-04-10T09:43:36-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 10 09:43:36 matts-music go-librespot[3218]: time="2026-04-10T09:43:36-04:00" level=trace msg="emitting websocket event: volume" Apr 10 09:43:36 matts-music volumio[1478]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Apr 10 09:43:36 matts-music volumio[1478]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Apr 10 09:43:36 matts-music volumio[1478]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Apr 10 09:43:36 matts-music volumio[1478]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Apr 10 09:43:38 matts-music volumio[1478]: info: Getting Spotify volume Apr 10 09:43:38 matts-music volumio[1478]: info: Spotify volume: 46 Apr 10 09:43:38 matts-music volumio[1478]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Apr 10 09:43:38 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:38 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:38 matts-music volumio[1478]: info: Initializing connection to go-librespot Websocket Apr 10 09:43:38 matts-music go-librespot[3218]: time="2026-04-10T09:43:38-04:00" level=debug msg="new websocket client" Apr 10 09:43:38 matts-music volumio[1478]: info: Connection to go-librespot Websocket established Apr 10 09:43:39 matts-music volumio[1478]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Apr 10 09:43:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Apr 10 09:43:39 matts-music volumio[1478]: info: Creating Spotify config file Apr 10 09:43:39 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 09:43:39 matts-music volumio[1478]: info: Spotify config file written Apr 10 09:43:39 matts-music sudo[3243]: volumio : unable to resolve host matts-music: System error Apr 10 09:43:39 matts-music sudo[3243]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 10 09:43:39 matts-music sudo[3243]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 09:43:39 matts-music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Apr 10 09:43:39 matts-music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Apr 10 09:43:39 matts-music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:39 matts-music volumio[1478]: info: Connection to go-librespot Websocket closed Apr 10 09:43:39 matts-music volumio[1478]: info: Connection to go-librespot Websocket closed Apr 10 09:43:39 matts-music volumio[1478]: info: Connection to go-librespot Websocket closed Apr 10 09:43:39 matts-music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:39 matts-music go-librespot[3245]: go-librespot daemon starting... Apr 10 09:43:39 matts-music sudo[3243]: pam_unix(sudo:session): session closed for user root Apr 10 09:43:39 matts-music go-librespot[3246]: time="2026-04-10T09:43:39-04:00" level=info msg="running go-librespot 0.7.1" Apr 10 09:43:39 matts-music go-librespot[3246]: time="2026-04-10T09:43:39-04:00" level=debug msg="app state loaded" Apr 10 09:43:39 matts-music go-librespot[3246]: time="2026-04-10T09:43:39-04:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 10 09:43:40 matts-music go-librespot[3246]: time="2026-04-10T09:43:40-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 10 09:43:40 matts-music go-librespot[3246]: time="2026-04-10T09:43:40-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 10 09:43:40 matts-music go-librespot[3246]: time="2026-04-10T09:43:40-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 10 09:43:40 matts-music go-librespot[3246]: time="2026-04-10T09:43:40-04:00" level=info msg="zeroconf server listening on port 41665" Apr 10 09:43:40 matts-music go-librespot[3246]: time="2026-04-10T09:43:40-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Apr 10 09:43:40 matts-music go-librespot[3246]: time="2026-04-10T09:43:40-04:00" level=debug msg="obtained new client token: AADs08y/3XjxSbRkLLACYE2Ryi/xhtCe6Wxg6FZPlSfjhhe9WVVr0FQ5OlP2sU1ANtOnydRJnOatqmN4tursqAopK2qRu0K8KVT6Mbn5I/+AuGUGDOAtO9oLlf02i/lv3TS1kLizS9qHXVWHyN5puCkXxZwUCtxc56ELd45Ps3JcwJEWTFu5q+MrQZ0s3nUjhLFOrniUIQEsb4HMl4bUaVD6pfF1tCif+UCJ5lTskR4r2jrNzEfwCFE=" Apr 10 09:43:40 matts-music volumio[1478]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Apr 10 09:43:40 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Apr 10 09:43:40 matts-music volumio[1478]: info: Creating Spotify config file Apr 10 09:43:40 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 09:43:40 matts-music volumio[1478]: info: Spotify config file written Apr 10 09:43:40 matts-music sudo[3257]: volumio : unable to resolve host matts-music: System error Apr 10 09:43:40 matts-music sudo[3257]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 10 09:43:40 matts-music sudo[3257]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 09:43:40 matts-music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Apr 10 09:43:40 matts-music systemd[1]: go-librespot-daemon.service: Killing process 3247 (go-librespot) with signal SIGKILL. Apr 10 09:43:40 matts-music systemd[1]: go-librespot-daemon.service: Killing process 3249 (go-librespot) with signal SIGKILL. Apr 10 09:43:40 matts-music systemd[1]: go-librespot-daemon.service: Killing process 3250 (go-librespot) with signal SIGKILL. Apr 10 09:43:40 matts-music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Apr 10 09:43:40 matts-music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:40 matts-music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:40 matts-music go-librespot[3259]: go-librespot daemon starting... Apr 10 09:43:40 matts-music sudo[3257]: pam_unix(sudo:session): session closed for user root Apr 10 09:43:40 matts-music go-librespot[3260]: time="2026-04-10T09:43:40-04:00" level=info msg="running go-librespot 0.7.1" Apr 10 09:43:40 matts-music go-librespot[3260]: time="2026-04-10T09:43:40-04:00" level=debug msg="app state loaded" Apr 10 09:43:40 matts-music go-librespot[3260]: time="2026-04-10T09:43:40-04:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 10 09:43:41 matts-music volumio[1478]: info: Getting Spotify volume Apr 10 09:43:41 matts-music volumio[1478]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Apr 10 09:43:41 matts-music volumio[1478]: info: CoreCommandRouter::volumioGetState Apr 10 09:43:41 matts-music volumio[1478]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Apr 10 09:43:41 matts-music go-librespot[3260]: time="2026-04-10T09:43:41-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 10 09:43:41 matts-music go-librespot[3260]: time="2026-04-10T09:43:41-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 10 09:43:41 matts-music go-librespot[3260]: time="2026-04-10T09:43:41-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 10 09:43:41 matts-music go-librespot[3260]: time="2026-04-10T09:43:41-04:00" level=info msg="zeroconf server listening on port 36289" Apr 10 09:43:41 matts-music go-librespot[3260]: time="2026-04-10T09:43:41-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Apr 10 09:43:41 matts-music go-librespot[3260]: time="2026-04-10T09:43:41-04:00" level=debug msg="obtained new client token: AACTjHFGvzg1oXSC07MQKWygFw4yZ/Lz6EX1lEMF09QKEOyfaVZOF8VgOb70CcsytqZydjlg91s91ZecfIqdvBu1+n0opPyzmEh/5FKXfx6gkLNNqlEnE3Jz2+awgYsXU3tIly1EHZJZcqwsTqXZjG302O/X+Iz0k7wqu9m306CUXLqWE8YHcrc2IlgmikWGPGQHGV/uJRlbEz3IFC14ZzpleTqWrqJ3KFyhZbrcEu4V7QpOJxvlpig=" Apr 10 09:43:41 matts-music volumio[1478]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Apr 10 09:43:41 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Apr 10 09:43:41 matts-music volumio[1478]: info: Creating Spotify config file Apr 10 09:43:41 matts-music volumio[1478]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 10 09:43:41 matts-music volumio[1478]: info: Spotify config file written Apr 10 09:43:41 matts-music go-librespot[3260]: time="2026-04-10T09:43:41-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Apr 10 09:43:41 matts-music sudo[3270]: volumio : unable to resolve host matts-music: System error Apr 10 09:43:41 matts-music sudo[3270]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 10 09:43:41 matts-music sudo[3270]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 10 09:43:41 matts-music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Apr 10 09:43:41 matts-music systemd[1]: go-librespot-daemon.service: Killing process 3265 (go-librespot) with signal SIGKILL. Apr 10 09:43:41 matts-music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Apr 10 09:43:41 matts-music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:41 matts-music volumio[1478]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 10 09:43:41 matts-music volumio[1478]: Error: socket hang up Apr 10 09:43:41 matts-music volumio[1478]: at connResetException (node:internal/errors:720:14) Apr 10 09:43:41 matts-music volumio[1478]: at Socket.socketOnEnd (node:_http_client:519:23) Apr 10 09:43:41 matts-music volumio[1478]: at Socket.emit (node:events:526:35) Apr 10 09:43:41 matts-music volumio[1478]: at endReadableNT (node:internal/streams/readable:1376:12) Apr 10 09:43:41 matts-music volumio[1478]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Apr 10 09:43:41 matts-music volumio[1478]: code: 'ECONNRESET', Apr 10 09:43:41 matts-music volumio[1478]: response: undefined Apr 10 09:43:41 matts-music volumio[1478]: } Apr 10 09:43:41 matts-music volumio[1478]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 10 09:43:41 matts-music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Apr 10 09:43:41 matts-music go-librespot[3272]: go-librespot daemon starting... Apr 10 09:43:41 matts-music sudo[3270]: pam_unix(sudo:session): session closed for user root Apr 10 09:43:41 matts-music go-librespot[3284]: time="2026-04-10T09:43:41-04:00" level=info msg="running go-librespot 0.7.1" Apr 10 09:43:41 matts-music go-librespot[3284]: time="2026-04-10T09:43:41-04:00" level=debug msg="app state loaded" Apr 10 09:43:41 matts-music go-librespot[3284]: time="2026-04-10T09:43:41-04:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 10 09:43:41 matts-music sudo[3294]: volumio : unable to resolve host matts-music: System error Apr 10 09:43:41 matts-music sudo[3294]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-04-10 09:42' Apr 10 09:43:41 matts-music sudo[3294]: 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"