Jan 26 23:26:01 volumio go-librespot[1341]: time="2026-01-26T23:26:01+01:00" level=debug msg="spclient request returned bad gateway, retrying..." Jan 26 23:26:27 volumio go-librespot[1341]: time="2026-01-26T23:26:27+01:00" level=trace msg="sent dealer ping" Jan 26 23:26:27 volumio go-librespot[1341]: time="2026-01-26T23:26:27+01:00" level=trace msg="received dealer pong" Jan 26 23:26:46 volumio volumio[936]: verbose: New Socket.io Connection to 192.168.1.98:3000 from 192.168.1.77 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 26 23:26:46 volumio volumio[936]: info: Discovery: Getting this device information Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 26 23:26:46 volumio volumio[936]: info: Discovery: Getting this device information Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 26 23:26:46 volumio volumio[936]: info: Discovery: Getting this device information Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableLanguages Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Jan 26 23:26:46 volumio volumio[936]: verbose: New Socket.io Connection to 192.168.1.98:3000 from 192.168.1.77 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork Jan 26 23:26:46 volumio sudo[31274]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0 Jan 26 23:26:46 volumio sudo[31274]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:26:46 volumio sudo[31274]: pam_unix(sudo:session): session closed for user root Jan 26 23:26:46 volumio sudo[31279]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Jan 26 23:26:46 volumio sudo[31279]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:26:46 volumio sudo[31286]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Jan 26 23:26:46 volumio sudo[31286]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jan 26 23:26:46 volumio sudo[31293]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Jan 26 23:26:46 volumio sudo[31293]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:26:46 volumio sudo[31279]: pam_unix(sudo:session): session closed for user root Jan 26 23:26:46 volumio sudo[31301]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 26 23:26:46 volumio sudo[31301]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:26:46 volumio sudo[31302]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 26 23:26:46 volumio sudo[31302]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:26:46 volumio sudo[31301]: pam_unix(sudo:session): session closed for user root Jan 26 23:26:46 volumio sudo[31286]: pam_unix(sudo:session): session closed for user root Jan 26 23:26:46 volumio sudo[31293]: pam_unix(sudo:session): session closed for user root Jan 26 23:26:46 volumio sudo[31302]: pam_unix(sudo:session): session closed for user root Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 26 23:26:46 volumio volumio[936]: info: Discovery: Getting this device information Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 26 23:26:46 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:26:47 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 26 23:26:47 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 26 23:26:47 volumio volumio[936]: info: Discovery: Getting this device information Jan 26 23:26:47 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:26:47 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 26 23:26:47 volumio volumio[936]: verbose: New Socket.io Connection to 192.168.1.98:3000 from 192.168.1.77 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Jan 26 23:26:47 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jan 26 23:26:47 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jan 26 23:26:47 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jan 26 23:26:47 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jan 26 23:26:48 volumio sudo[31321]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 26 23:26:48 volumio sudo[31321]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:26:48 volumio sudo[31321]: pam_unix(sudo:session): session closed for user root Jan 26 23:26:48 volumio sudo[31323]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 26 23:26:48 volumio sudo[31323]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:26:48 volumio sudo[31323]: pam_unix(sudo:session): session closed for user root Jan 26 23:26:48 volumio volumio[936]: verbose: New Socket.io Connection to 192.168.1.98 from 192.168.1.77 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 7 Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 26 23:26:48 volumio sudo[31335]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 26 23:26:48 volumio sudo[31335]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:26:48 volumio sudo[31335]: pam_unix(sudo:session): session closed for user root Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jan 26 23:26:48 volumio sudo[31337]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 26 23:26:48 volumio sudo[31337]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:26:48 volumio sudo[31337]: pam_unix(sudo:session): session closed for user root Jan 26 23:26:48 volumio volumio[936]: verbose: New Socket.io Connection to 192.168.1.98 from 192.168.1.77 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 7 Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::volumioGetVisibleSources Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 26 23:26:48 volumio volumio[936]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jan 26 23:26:48 volumio volumio[936]: info: Received Get System Info Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 26 23:26:48 volumio volumio[936]: info: Discovery: Getting this device information Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:26:48 volumio volumio[936]: info: Listing playlists Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jan 26 23:26:48 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 26 23:26:49 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jan 26 23:26:50 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jan 26 23:26:50 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 26 23:26:50 volumio volumio[936]: info: Received Get System Info Jan 26 23:26:50 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 26 23:26:50 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 26 23:26:50 volumio volumio[936]: info: Discovery: Getting this device information Jan 26 23:26:50 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:26:50 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 26 23:26:52 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 26 23:26:52 volumio volumio[936]: info: Received Get System Info Jan 26 23:26:52 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 26 23:26:52 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 26 23:26:52 volumio volumio[936]: info: Discovery: Getting this device information Jan 26 23:26:52 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:26:52 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 26 23:26:52 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 26 23:26:52 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 26 23:26:52 volumio volumio[936]: info: Discovery: Getting this device information Jan 26 23:26:52 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:26:52 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 26 23:26:52 volumio volumio[936]: verbose: New Socket.io Connection to 192.168.1.98:3000 from 192.168.1.77 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Jan 26 23:26:52 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jan 26 23:26:52 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jan 26 23:26:53 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 26 23:26:53 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jan 26 23:26:57 volumio go-librespot[1341]: time="2026-01-26T23:26:57+01:00" level=trace msg="sent dealer ping" Jan 26 23:26:57 volumio go-librespot[1341]: time="2026-01-26T23:26:57+01:00" level=trace msg="received dealer pong" Jan 26 23:26:58 volumio go-librespot[1341]: time="2026-01-26T23:26:58+01:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Jan 26 23:26:58 volumio volumio[936]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Jan 26 23:26:58 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 26 23:26:58 volumio volumio[936]: Cannot find translation for source TIDAL Jan 26 23:26:58 volumio volumio[936]: info: Disabling plugin spop Jan 26 23:26:58 volumio volumio[936]: info: Done. Jan 26 23:26:58 volumio volumio[936]: info: Connection to go-librespot Websocket closed Jan 26 23:26:58 volumio sudo[31363]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service Jan 26 23:26:58 volumio sudo[31363]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:26:58 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 26 23:26:58 volumio systemd[1]: go-librespot-daemon.service: Killing process 9137 (go-librespot) with signal SIGKILL. Jan 26 23:26:58 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 26 23:26:58 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 26 23:26:58 volumio systemd[1]: go-librespot-daemon.service: Consumed 41min 32.571s CPU time. Jan 26 23:26:58 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 26 23:26:58 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 26 23:26:58 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 26 23:26:58 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 26 23:26:58 volumio sudo[31363]: pam_unix(sudo:session): session closed for user root Jan 26 23:26:58 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 26 23:26:59 volumio volumio[936]: info: Enabling plugin spop Jan 26 23:26:59 volumio volumio[936]: info: Loading plugin "spop"... Jan 26 23:26:59 volumio volumio[936]: info: PLUGIN START: spop Jan 26 23:26:59 volumio volumio[936]: info: Creating Spotify config file Jan 26 23:26:59 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 26 23:26:59 volumio volumio[936]: info: Done. Jan 26 23:26:59 volumio volumio[936]: info: Spotify config file written Jan 26 23:26:59 volumio volumio[936]: info: No need to fix Spotify hosts Jan 26 23:26:59 volumio sudo[31366]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 26 23:26:59 volumio sudo[31366]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:26:59 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 26 23:26:59 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 26 23:26:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 26 23:26:59 volumio go-librespot[31368]: go-librespot daemon starting... Jan 26 23:26:59 volumio sudo[31366]: pam_unix(sudo:session): session closed for user root Jan 26 23:26:59 volumio go-librespot[31369]: time="2026-01-26T23:26:59+01:00" level=info msg="running go-librespot 0.6.2" Jan 26 23:26:59 volumio go-librespot[31369]: time="2026-01-26T23:26:59+01:00" level=debug msg="app state loaded" Jan 26 23:26:59 volumio go-librespot[31369]: time="2026-01-26T23:26:59+01:00" level=debug msg="stored credentials not found" Jan 26 23:26:59 volumio go-librespot[31369]: time="2026-01-26T23:26:59+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 26 23:27:00 volumio go-librespot[31369]: time="2026-01-26T23:27:00+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 26 23:27:00 volumio go-librespot[31369]: time="2026-01-26T23:27:00+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 26 23:27:00 volumio go-librespot[31369]: time="2026-01-26T23:27:00+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 26 23:27:00 volumio go-librespot[31369]: time="2026-01-26T23:27:00+01:00" level=info msg="zeroconf server listening on port 39609" Jan 26 23:27:02 volumio volumio[936]: info: go-librespot daemon successfully initialized Jan 26 23:27:05 volumio volumio[936]: info: Initializing connection to go-librespot Websocket Jan 26 23:27:05 volumio go-librespot[31369]: time="2026-01-26T23:27:05+01:00" level=debug msg="new websocket client" Jan 26 23:27:05 volumio volumio[936]: info: Connection to go-librespot Websocket established Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="obtained new client token: AABs3GC2/B6F/m/SMOUgGGwLcE/gMqssXLX2YuQDrOnNkZ+dHLxSBPCPzb7xD2mQpLU1JsyfJl8KP275aoLLyn8WvD7sK+S3bJWr/6NA8NFTKBdioCd/4NYIuX0qOtYcUYE1h2LUJQSYpH01UHQW87Jj4154PnpGdAo8xc3Wlfu9811ykxeIodzvovMrmjpg7rt+cFEvmKL3Xismt0l0SgZ8oCclXdShQWCuJvDlWVM5beYbIs0B6rI=" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="completed keyexchange" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="completed challenge" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=info msg="authenticated AP" username="ru******20" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=info msg="authenticated Login5" username="ru******20" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=info msg="accepted zeroconf from iPhone" username="ru******20" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="dealer connection opened" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=trace msg="starting accesspoint recv loop" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=trace msg="starting dealer recv loop" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=trace msg="received accesspoint ping" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="received connection id: MjM0ZjE3NDctNzIz...QUEwRThCMkJGMw==" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=trace msg="received accesspoint pong ack" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="put connect state because NEW_DEVICE" Jan 26 23:27:06 volumio go-librespot[31369]: time="2026-01-26T23:27:06+01:00" level=debug msg="handling transfer player command from 975e040d428a2fe36ab847c191cd32a0dc7a7eb4" Jan 26 23:27:07 volumio go-librespot[31369]: time="2026-01-26T23:27:07+01:00" level=debug msg="resolved context of track" uri="spotify:station:track:59tcQJiHwApzE4h6yVnL9i" Jan 26 23:27:07 volumio go-librespot[31369]: time="2026-01-26T23:27:07+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:station:track:59tcQJiHwApzE4h6yVnL9i" Jan 26 23:27:07 volumio go-librespot[31369]: time="2026-01-26T23:27:07+01:00" level=trace msg="loading context page from radio-apollo/v3/tracks/spotify:station:track:59tcQJiHwApzE4h6yVnL9i?salt=290978&autoplay=false&count=50&isVideo=false&prev_tracks=59tcQJiHwApzE4h6yVnL9i,3tcB32nXoEIlkYBKzrO3j5,25kGCuGWAYfyoz7RozlTpO,1HRAT7mZlnFimeVUB4yOQ3,0NVsz5lExNqzVDznhdPlU8,4PgGR3M1TPpUoiuLPaac8H,31nRdOt2oJmsJ3UJPLh9Sp,04Z0PiiSaVutpzurloGRe2,17UhIHDTEcKkrqFbEa3aPo,6WuUxpyAislVIyLICI7zOY,2Pt6aiOl3Fe9uph8ULnR4N,2wF5jnXSY4BMza03KP6LYg,7z40FeBqt9U0DaDQxEmxUV,6ehIR06LyOCstWZ3YRW5F1,2ZAGAFgLMHsB42NxIHCRnf,16ikmfoT1249gG3pzPvnYt,4qteT7Cqwb6HdcO8dta8Kt,5PtUOPlg9luI1XB0j7GQrq,6lsGZBXAJ4GFLF6UXdfXs5,7jiOsno0Dc4l0fRORRaZif,1VD8kfTLRwQErMZkLtHjcP,5PsGfCv1s5iEwEy27e2poj,4C2aiAVTTVyZbCQZst5Xu1,69qGhVe4CbzDi5uBeWPPdO,7C23d5jyOZiXIjBiqvBEDp,7LbA9VWwvTHV9kjucCZkHZ,0bFDDU8ETywjcjKAHRsWDH,5oaZZp6I2WTmFi3Sj0DRDM,3xTZpkPtRwNZ4XSyx53cuo,383MxeoXVw7bdeBKEz68Po,0KhE0wtVBlLL3NFhcqIyKp,0MkT4TZlArPSzoYZpFMMd5,0D56OFZwt2Y1MmcJlieYjA,3r5FpV71EiUgOvTIWDxiCY,4nr0dChikzW0GQM7m1e0r8,7bGNpO1s8gb8bNljF4B3SO,02oAqE4RUmemtnHDBMgkWl,2qrVYBy2PArMwQRVZxFWzz,47MvdRV6TXVJNjII4uBH5V,5KrUt55R9EGl9ZMl8BL8kV,2zv6rwVJdNQGKgyaYPaPBy,1tykSwsQcWkCACAj0jyLwe,40ZyjIUgYqzXxvatRgrJKv,6e65fH1wClamA2QPI5HUi3,7EDGRYnkrkbxQmZPHdZ6Lr,6IBpFG2LU2udYofIuROp3w,0NsFXBxpfDO4BFrCHDlJeB,0YPFkkRv6ZfzlcLnnU5QpX,5Ia2NSuBTCMfF1bNiwbaGS,6CnI0qWDR9CSOkHSTNPmOc&minimal=true" uri="spotify:station:track:59tcQJiHwApzE4h6yVnL9i" Jan 26 23:27:07 volumio go-librespot[31369]: time="2026-01-26T23:27:07+01:00" level=debug msg="spclient request returned bad gateway, retrying..." Jan 26 23:27:07 volumio go-librespot[31369]: time="2026-01-26T23:27:07+01:00" level=debug msg="spclient request returned bad gateway, retrying..." Jan 26 23:27:08 volumio go-librespot[31369]: time="2026-01-26T23:27:08+01:00" level=debug msg="spclient request returned bad gateway, retrying..." Jan 26 23:27:08 volumio volumio[936]: info: Getting Spotify volume Jan 26 23:27:08 volumio volumio[936]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jan 26 23:27:08 volumio go-librespot[31369]: time="2026-01-26T23:27:08+01:00" level=debug msg="spclient request returned bad gateway, retrying..." Jan 26 23:27:08 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:27:08 volumio volumio[936]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 26 23:27:11 volumio go-librespot[31369]: time="2026-01-26T23:27:11+01:00" level=debug msg="spclient request returned bad gateway, retrying..." Jan 26 23:27:11 volumio go-librespot[31369]: time="2026-01-26T23:27:11+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 700" Jan 26 23:27:11 volumio go-librespot[31369]: time="2026-01-26T23:27:11+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 370" Jan 26 23:27:11 volumio go-librespot[31369]: time="2026-01-26T23:27:11+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1629" Jan 26 23:27:12 volumio go-librespot[31369]: time="2026-01-26T23:27:12+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1243" Jan 26 23:27:14 volumio go-librespot[31369]: time="2026-01-26T23:27:14+01:00" level=debug msg="spclient request returned bad gateway, retrying..." Jan 26 23:27:18 volumio go-librespot[31369]: time="2026-01-26T23:27:18+01:00" level=debug msg="spclient request returned bad gateway, retrying..." Jan 26 23:27:21 volumio go-librespot[31369]: time="2026-01-26T23:27:21+01:00" level=debug msg="spclient request returned bad gateway, retrying..." Jan 26 23:27:23 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Jan 26 23:27:25 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Jan 26 23:27:25 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Jan 26 23:27:25 volumio systemd[1]: setdatetime-helper.service: Consumed 1.115s CPU time. Jan 26 23:27:26 volumio volumio[936]: verbose: New Socket.io Connection to 192.168.1.98 from 192.168.1.77 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 7 Jan 26 23:27:26 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 26 23:27:26 volumio volumio[936]: info: CoreCommandRouter::volumioGetVisibleSources Jan 26 23:27:26 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 26 23:27:26 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:27:26 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jan 26 23:27:26 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 26 23:27:26 volumio volumio[936]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jan 26 23:27:26 volumio volumio[936]: info: Received Get System Info Jan 26 23:27:26 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 26 23:27:26 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 26 23:27:26 volumio volumio[936]: info: Discovery: Getting this device information Jan 26 23:27:26 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:27:26 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 26 23:27:26 volumio volumio[936]: info: CoreCommandRouter::volumioGetState Jan 26 23:27:26 volumio volumio[936]: info: Listing playlists Jan 26 23:27:26 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jan 26 23:27:29 volumio go-librespot[31369]: time="2026-01-26T23:27:29+01:00" level=debug msg="spclient request returned bad gateway, retrying..." Jan 26 23:27:36 volumio go-librespot[31369]: time="2026-01-26T23:27:36+01:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Jan 26 23:27:36 volumio volumio[936]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Jan 26 23:27:36 volumio volumio[936]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 26 23:27:36 volumio volumio[936]: Cannot find translation for source TIDAL Jan 26 23:27:36 volumio volumio[936]: info: Disabling plugin spop Jan 26 23:27:36 volumio volumio[936]: info: Done. Jan 26 23:27:36 volumio volumio[936]: info: Connection to go-librespot Websocket closed Jan 26 23:27:36 volumio sudo[31492]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service Jan 26 23:27:36 volumio sudo[31492]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 26 23:27:36 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 26 23:27:36 volumio systemd[1]: go-librespot-daemon.service: Killing process 31377 (go-librespot) with signal SIGKILL. Jan 26 23:27:36 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 26 23:27:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 26 23:27:36 volumio volumio[936]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 26 23:27:36 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 26 23:27:36 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 26 23:27:36 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 26 23:27:36 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jan 26 23:27:36 volumio volumio[936]: Error: socket hang up Jan 26 23:27:36 volumio volumio[936]: at connResetException (node:internal/errors:720:14) Jan 26 23:27:36 volumio volumio[936]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 26 23:27:36 volumio volumio[936]: at Socket.emit (node:events:526:35) Jan 26 23:27:36 volumio volumio[936]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 26 23:27:36 volumio volumio[936]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 26 23:27:36 volumio volumio[936]: code: 'ECONNRESET', Jan 26 23:27:36 volumio volumio[936]: response: undefined Jan 26 23:27:36 volumio volumio[936]: } Jan 26 23:27:36 volumio volumio[936]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 26 23:27:36 volumio sudo[31492]: pam_unix(sudo:session): session closed for user root Jan 26 23:27:37 volumio sudo[31510]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-26 23:26' Jan 26 23:27:37 volumio sudo[31510]: 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="b05a530ca81d05eb9a84d0acf82089f0a60b8ee6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 25 09:13:19 UTC 2025" VOLUMIO_VERSION="4.084" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="792f09af7488531aecd1aadcaa9b175e"