Dec 08 20:46:00 volumio607 go-librespot[1646]: time="2025-12-08T20:46:00+08:00" level=debug msg="fetched chunk 9/14, size: 524288" uri="spotify:track:6HiVEUKnYXmKewUXGsGplE" Dec 08 20:46:09 volumio607 volumio[1323]: verbose: New Socket.io Connection to 192.168.1.18:3000 from 192.168.1.19 UA: Dart/3.9 (dart:io) Engine version: 3 Transport: websocket Total Clients: 5 Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 08 20:46:09 volumio607 volumio[1323]: info: Discovery: Getting this device information Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 08 20:46:09 volumio607 volumio[1323]: info: Discovery: Getting this device information Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableLanguages Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork Dec 08 20:46:09 volumio607 sudo[7328]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0 Dec 08 20:46:09 volumio607 sudo[7328]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 20:46:09 volumio607 sudo[7333]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Dec 08 20:46:09 volumio607 sudo[7333]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 20:46:09 volumio607 sudo[7328]: pam_unix(sudo:session): session closed for user root Dec 08 20:46:09 volumio607 sudo[7333]: pam_unix(sudo:session): session closed for user root Dec 08 20:46:09 volumio607 sudo[7340]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Dec 08 20:46:09 volumio607 sudo[7346]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0 Dec 08 20:46:09 volumio607 sudo[7340]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 20:46:09 volumio607 sudo[7346]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 20:46:09 volumio607 sudo[7340]: pam_unix(sudo:session): session closed for user root Dec 08 20:46:09 volumio607 sudo[7346]: pam_unix(sudo:session): session closed for user root Dec 08 20:46:09 volumio607 sudo[7351]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 08 20:46:09 volumio607 sudo[7351]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 20:46:09 volumio607 sudo[7355]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 08 20:46:09 volumio607 sudo[7355]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 20:46:09 volumio607 sudo[7351]: pam_unix(sudo:session): session closed for user root Dec 08 20:46:09 volumio607 sudo[7355]: pam_unix(sudo:session): session closed for user root Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 08 20:46:09 volumio607 volumio[1323]: info: Discovery: Getting this device information Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 08 20:46:09 volumio607 volumio[1323]: info: Discovery: Getting this device information Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 08 20:46:09 volumio607 volumio[1323]: verbose: New Socket.io Connection to 192.168.1.18:3000 from 192.168.1.19 UA: Dart/3.9 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 08 20:46:09 volumio607 volumio[1323]: info: Discovery: Getting this device information Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:09 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 08 20:46:09 volumio607 volumio[1323]: verbose: New Socket.io Connection to 192.168.1.18:3000 from 192.168.1.19 UA: Dart/3.9 (dart:io) Engine version: 3 Transport: websocket Total Clients: 6 Dec 08 20:46:10 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Dec 08 20:46:10 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Dec 08 20:46:11 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Dec 08 20:46:11 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Dec 08 20:46:11 volumio607 sudo[7361]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 08 20:46:11 volumio607 sudo[7361]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 20:46:11 volumio607 sudo[7361]: pam_unix(sudo:session): session closed for user root Dec 08 20:46:11 volumio607 sudo[7363]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 08 20:46:11 volumio607 sudo[7363]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 20:46:11 volumio607 sudo[7363]: pam_unix(sudo:session): session closed for user root Dec 08 20:46:11 volumio607 volumio[1323]: verbose: New Socket.io Connection to 192.168.1.18 from 192.168.1.19 UA: Mozilla/5.0 (Linux; Android 12; LMR-LX9 Build/HUAWEILMR-L29; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/114.0.5735.196 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Dec 08 20:46:11 volumio607 go-librespot[1646]: time="2025-12-08T20:46:11+08:00" level=debug msg="fetched chunk 10/14, size: 524288" uri="spotify:track:6HiVEUKnYXmKewUXGsGplE" Dec 08 20:46:11 volumio607 sudo[7367]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 08 20:46:11 volumio607 sudo[7367]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 20:46:11 volumio607 sudo[7367]: pam_unix(sudo:session): session closed for user root Dec 08 20:46:11 volumio607 sudo[7369]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 08 20:46:11 volumio607 sudo[7369]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 20:46:11 volumio607 sudo[7369]: pam_unix(sudo:session): session closed for user root Dec 08 20:46:11 volumio607 volumio[1323]: verbose: New Socket.io Connection to 192.168.1.18 from 192.168.1.19 UA: Mozilla/5.0 (Linux; Android 12; LMR-LX9 Build/HUAWEILMR-L29; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/114.0.5735.196 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Dec 08 20:46:11 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetVisibleSources Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetQueue Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreStateMachine::getQueue Dec 08 20:46:12 volumio607 volumio[1323]: info: CorePlayQueue::getQueue Dec 08 20:46:12 volumio607 volumio[1323]: info: Listing playlists Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 08 20:46:12 volumio607 volumio[1323]: info: Received Get System Info Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 08 20:46:12 volumio607 volumio[1323]: info: Discovery: Getting this device information Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 08 20:46:12 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 08 20:46:13 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 08 20:46:13 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 08 20:46:13 volumio607 volumio[1323]: info: Received Get System Info Dec 08 20:46:13 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 08 20:46:13 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 08 20:46:13 volumio607 volumio[1323]: info: Discovery: Getting this device information Dec 08 20:46:13 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:13 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 08 20:46:13 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 08 20:46:15 volumio607 volumio[1323]: Searching all installed plugins Dec 08 20:46:15 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 20:46:15 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: , search Dec 08 20:46:15 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: mpd , search Dec 08 20:46:15 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Dec 08 20:46:15 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Dec 08 20:46:15 volumio607 volumio[1323]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Dec 08 20:46:15 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: webradio , search Dec 08 20:46:16 volumio607 go-librespot[1646]: time="2025-12-08T20:46:16+08:00" level=trace msg="sent dealer ping" Dec 08 20:46:16 volumio607 go-librespot[1646]: time="2025-12-08T20:46:16+08:00" level=trace msg="received dealer pong" Dec 08 20:46:16 volumio607 volumio[1323]: info: All search sources collected, pushing search results Dec 08 20:46:17 volumio607 volumio[1323]: Searching all installed plugins Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: , search Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: mpd , search Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Dec 08 20:46:17 volumio607 volumio[1323]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: webradio , search Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 08 20:46:17 volumio607 volumio[1323]: info: Received Get System Info Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 08 20:46:17 volumio607 volumio[1323]: info: Discovery: Getting this device information Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 08 20:46:17 volumio607 volumio[1323]: info: All search sources collected, pushing search results Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 08 20:46:17 volumio607 volumio[1323]: info: Discovery: Getting this device information Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:17 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 08 20:46:18 volumio607 volumio[1323]: verbose: New Socket.io Connection to 192.168.1.18:3000 from 192.168.1.19 UA: Dart/3.9 (dart:io) Engine version: 3 Transport: websocket Total Clients: 8 Dec 08 20:46:18 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Dec 08 20:46:18 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Dec 08 20:46:21 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 08 20:46:24 volumio607 go-librespot[1646]: time="2025-12-08T20:46:24+08:00" level=debug msg="fetched chunk 11/14, size: 524288" uri="spotify:track:6HiVEUKnYXmKewUXGsGplE" Dec 08 20:46:30 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 08 20:46:30 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 08 20:46:31 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 08 20:46:31 volumio607 volumio[1323]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 08 20:46:31 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 08 20:46:31 volumio607 volumio[1323]: info: Received Get System Version Dec 08 20:46:31 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 08 20:46:31 volumio607 volumio[1323]: info: Received Get System Info Dec 08 20:46:31 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 08 20:46:31 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 08 20:46:31 volumio607 volumio[1323]: info: Discovery: Getting this device information Dec 08 20:46:31 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:31 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 08 20:46:32 volumio607 go-librespot[1646]: time="2025-12-08T20:46:32+08:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Dec 08 20:46:32 volumio607 volumio[1323]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Dec 08 20:46:32 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 20:46:32 volumio607 volumio[1323]: info: Disabling plugin spop Dec 08 20:46:32 volumio607 volumio[1323]: info: Done. Dec 08 20:46:32 volumio607 sudo[7406]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service Dec 08 20:46:32 volumio607 sudo[7406]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 20:46:32 volumio607 volumio[1323]: info: Connection to go-librespot Websocket closed Dec 08 20:46:32 volumio607 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 08 20:46:32 volumio607 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 08 20:46:32 volumio607 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 20:46:32 volumio607 systemd[1]: go-librespot-daemon.service: Consumed 50.238s CPU time. Dec 08 20:46:32 volumio607 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. Dec 08 20:46:32 volumio607 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. Dec 08 20:46:32 volumio607 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. Dec 08 20:46:32 volumio607 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. Dec 08 20:46:32 volumio607 sudo[7406]: pam_unix(sudo:session): session closed for user root Dec 08 20:46:33 volumio607 volumio[1323]: info: Enabling plugin spop Dec 08 20:46:33 volumio607 volumio[1323]: info: Loading plugin "spop"... Dec 08 20:46:33 volumio607 volumio[1323]: info: PLUGIN START: spop Dec 08 20:46:33 volumio607 volumio[1323]: info: Creating Spotify config file Dec 08 20:46:33 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 20:46:33 volumio607 volumio[1323]: info: Done. Dec 08 20:46:33 volumio607 volumio[1323]: info: Spotify config file written Dec 08 20:46:33 volumio607 volumio[1323]: info: No need to fix Spotify hosts Dec 08 20:46:33 volumio607 sudo[7412]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 08 20:46:33 volumio607 sudo[7412]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 20:46:33 volumio607 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. Dec 08 20:46:33 volumio607 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. Dec 08 20:46:33 volumio607 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 20:46:33 volumio607 go-librespot[7414]: go-librespot daemon starting... Dec 08 20:46:33 volumio607 sudo[7412]: pam_unix(sudo:session): session closed for user root Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=info msg="running go-librespot 0.4.0" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=debug msg="app state loaded" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=info msg="zeroconf server listening on port 45391" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=debug msg="obtained new client token: AABwnCoKdaD4x3Ne5f7b+HncgJwkJbR3pL6D81ZIBACHIeTMvvrhPtnPO4k3iwTHpH6JiWKJYfWGFjWqyZanS9cEsWAsdmaf0wvaN5T5dCm1fWvKFVKmjL0kpCNBjIo9eJm/irL3OK5e0CH/N/W3f2JGRARJi7+PPOrO0EaQYzl74KrmAd48+gF5YRxE/0gMiSaVz1Xx6Uwg/cr31i6Tw0FtXR0jUx413UOaKJfAc9oZ+Zw6Y+LzGbc8sg==" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=debug msg="completed keyexchange" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=debug msg="completed challenge" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=info msg="authenticated AP" username="31************************2a" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=info msg="authenticated Login5" username="31************************2a" Dec 08 20:46:33 volumio607 go-librespot[7415]: time="2025-12-08T20:46:33+08:00" level=debug msg="initializing zeroconf session" username="31************************2a" Dec 08 20:46:34 volumio607 go-librespot[7415]: time="2025-12-08T20:46:34+08:00" level=debug msg="dealer connection opened" Dec 08 20:46:34 volumio607 go-librespot[7415]: time="2025-12-08T20:46:34+08:00" level=trace msg="starting accesspoint recv loop" Dec 08 20:46:34 volumio607 go-librespot[7415]: time="2025-12-08T20:46:34+08:00" level=trace msg="starting dealer recv loop" Dec 08 20:46:34 volumio607 go-librespot[7415]: time="2025-12-08T20:46:34+08:00" level=trace msg="received accesspoint ping" Dec 08 20:46:34 volumio607 go-librespot[7415]: time="2025-12-08T20:46:34+08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 08 20:46:34 volumio607 go-librespot[7415]: time="2025-12-08T20:46:34+08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 08 20:46:34 volumio607 go-librespot[7415]: time="2025-12-08T20:46:34+08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 08 20:46:34 volumio607 go-librespot[7415]: time="2025-12-08T20:46:34+08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 08 20:46:34 volumio607 go-librespot[7415]: time="2025-12-08T20:46:34+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 08 20:46:34 volumio607 go-librespot[7415]: time="2025-12-08T20:46:34+08:00" level=debug msg="received connection id: ZDI0OGZiMjQtYzY4...NUNEMEUzN0UwMw==" Dec 08 20:46:34 volumio607 volumio[1323]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 08 20:46:34 volumio607 volumio[1323]: SPOTIFY: BQAMg2QVX-fgLGCed7gbkmd1BDfKrjUDL8BA2aqzh_e0UjcjAW45vWE52WsXtspgUm7saR0_S022KL22AWUWTcVxzHTTAkokTb93QvZFxyyjfr6F70r1RExlD6ejrlVbygo2JpV51EGtvxV4KvHE0URi4KqlhaknC40p_Bm6cz93RTh048d9vRuv-JvbVJL5mvUCdKNUgJfrkuKdKE-vbbmGRhXjSZ9_EX3MePkzeWrvLnsTDjZiPIc0K4VNIH461rICONnq0Bmi-pwQt9jLbCW9ejMY-yznrhI3fcZjiZhfwdgS0xjnkp_eznXX Dec 08 20:46:34 volumio607 volumio[1323]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 08 20:46:34 volumio607 volumio[1323]: info: New Spotify access token = BQAMg2QVX-fgLGCed7gbkmd1BDfKrjUDL8BA2aqzh_e0UjcjAW45vWE52WsXtspgUm7saR0_S022KL22AWUWTcVxzHTTAkokTb93QvZFxyyjfr6F70r1RExlD6ejrlVbygo2JpV51EGtvxV4KvHE0URi4KqlhaknC40p_Bm6cz93RTh048d9vRuv-JvbVJL5mvUCdKNUgJfrkuKdKE-vbbmGRhXjSZ9_EX3MePkzeWrvLnsTDjZiPIc0K4VNIH461rICONnq0Bmi-pwQt9jLbCW9ejMY-yznrhI3fcZjiZhfwdgS0xjnkp_eznXX Dec 08 20:46:34 volumio607 volumio[1323]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 08 20:46:34 volumio607 go-librespot[7415]: time="2025-12-08T20:46:34+08:00" level=trace msg="received accesspoint pong ack" Dec 08 20:46:34 volumio607 go-librespot[7415]: time="2025-12-08T20:46:34+08:00" level=debug msg="put connect state because NEW_DEVICE" Dec 08 20:46:34 volumio607 volumio[1323]: SPOTIFY: User informations: {"country":"SG","display_name":"WK","email":"twk92@yahoo.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31tecvs7pg7lifbhzvgxjsctjp2a"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31tecvs7pg7lifbhzvgxjsctjp2a","id":"31tecvs7pg7lifbhzvgxjsctjp2a","images":[],"product":"premium","type":"user","uri":"spotify:user:31tecvs7pg7lifbhzvgxjsctjp2a"} Dec 08 20:46:34 volumio607 volumio[1323]: info: Spotify Successfully logged in Dec 08 20:46:34 volumio607 volumio[1323]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 20:46:34 volumio607 volumio[1323]: info: [1765197994209] CoreMusicLibrary::Adding element Spotify Dec 08 20:46:34 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 20:46:34 volumio607 volumio[1323]: Cannot find translation for source Spotify Dec 08 20:46:36 volumio607 volumio[1323]: info: go-librespot daemon successfully initialized Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 08 20:46:37 volumio607 volumio[1323]: info: Retrieving Cloud Streaming UI Dec 08 20:46:37 volumio607 volumio[1323]: info: Getting Tidal Cloud Configuration Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 08 20:46:37 volumio607 volumio[1323]: info: Getting Qobuz Cloud Configuration Dec 08 20:46:37 volumio607 volumio[1323]: info: Asking plugin for UI Config Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 08 20:46:37 volumio607 volumio[1323]: info: Getting Spotify Cloud Configuration Dec 08 20:46:37 volumio607 volumio[1323]: info: Asking plugin for UI Config Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 08 20:46:37 volumio607 volumio[1323]: info: Saving Spotify Acccount Dec 08 20:46:37 volumio607 volumio[1323]: info: Got Tidal Cloud Configuration Dec 08 20:46:37 volumio607 volumio[1323]: info: Got it Dec 08 20:46:37 volumio607 volumio[1323]: info: Got it Dec 08 20:46:37 volumio607 volumio[1323]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 08 20:46:37 volumio607 volumio[1323]: error: Error retrieving Highresaudio conf: TypeError: Cannot read properties of undefined (reading 'onSave') Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetBrowseSources Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetBrowseSources Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetBrowseSources Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 08 20:46:37 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Dec 08 20:46:39 volumio607 volumio[1323]: info: Initializing connection to go-librespot Websocket Dec 08 20:46:39 volumio607 go-librespot[7415]: time="2025-12-08T20:46:39+08:00" level=debug msg="new websocket client" Dec 08 20:46:39 volumio607 volumio[1323]: info: Connection to go-librespot Websocket established Dec 08 20:46:42 volumio607 volumio[1323]: info: Getting Spotify volume Dec 08 20:46:42 volumio607 volumio[1323]: info: Spotify volume: 100 Dec 08 20:46:42 volumio607 volumio[1323]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Dec 08 20:46:42 volumio607 volumio[1323]: info: CoreCommandRouter::volumioGetState Dec 08 20:46:42 volumio607 volumio[1323]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50 Dec 08 20:46:42 volumio607 volumio[1323]: SPOTIFY: SPOTIFY VOLUME 100 Dec 08 20:46:42 volumio607 volumio[1323]: SPOTIFY: VOLUMIO VOLUME 50 Dec 08 20:46:42 volumio607 volumio[1323]: SPOTIFY: DELTA VOLUME ENOUGH: true Dec 08 20:46:42 volumio607 volumio[1323]: info: Setting Spotify Volume from Volumio: 50 Dec 08 20:46:43 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Dec 08 20:46:43 volumio607 volumio[1323]: info: In handleBrowseUri, curUri=spotify Dec 08 20:46:43 volumio607 volumio[1323]: info: Preload queue cleared Dec 08 20:46:43 volumio607 volumio[1323]: info: Preload queue cleared Dec 08 20:46:43 volumio607 volumio[1323]: info: Preload queue cleared Dec 08 20:46:43 volumio607 volumio[1323]: info: Preload queue cleared Dec 08 20:46:43 volumio607 volumio[1323]: SPOTIFY: SETTING SPOTIFY VOLUME 50 Dec 08 20:46:43 volumio607 volumio[1323]: info: Sending Spotify command with payload to local API: /player/volume Dec 08 20:46:43 volumio607 go-librespot[7415]: time="2025-12-08T20:46:43+08:00" level=debug msg="update volume requested to 32767/65535" Dec 08 20:46:44 volumio607 go-librespot[7415]: time="2025-12-08T20:46:44+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 08 20:46:44 volumio607 go-librespot[7415]: time="2025-12-08T20:46:44+08:00" level=trace msg="emitting websocket event: volume" Dec 08 20:46:44 volumio607 volumio[1323]: SPOTIFY: received: {"type":"volume","data":{"value":50,"max":100}} Dec 08 20:46:44 volumio607 volumio[1323]: SPOTIFY: RECEIVED SPOTIFY VOLUME 50 Dec 08 20:46:57 volumio607 volumio[1323]: Searching plugin music_service/spop Dec 08 20:46:57 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 08 20:46:57 volumio607 volumio[1323]: info: All search sources collected, pushing search results Dec 08 20:47:04 volumio607 go-librespot[7415]: time="2025-12-08T20:47:04+08:00" level=trace msg="sent dealer ping" Dec 08 20:47:04 volumio607 go-librespot[7415]: time="2025-12-08T20:47:04+08:00" level=trace msg="received dealer pong" Dec 08 20:47:07 volumio607 volumio[1323]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Dec 08 20:47:07 volumio607 volumio[1323]: info: In handleBrowseUri, curUri=spotify:artist:7wk5ZVDUupsDzHU0NrOozD Dec 08 20:47:08 volumio607 volumio[1323]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 08 20:47:08 volumio607 volumio[1323]: TypeError: Cannot read properties of undefined (reading 'url') Dec 08 20:47:08 volumio607 volumio[1323]: at /data/plugins/music_service/spop/index.js:2449:60 Dec 08 20:47:08 volumio607 volumio[1323]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Dec 08 20:47:08 volumio607 volumio[1323]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 08 20:47:08 volumio607 sudo[7500]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-08 20:46' Dec 08 20:47:08 volumio607 sudo[7500]: 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="ec1ce6b3390e13e82b9cc0453f957c4f5298419e" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="8bcc10c3dbcbcb349e9887dc0527d54876b32688" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon Nov 17 16:31:40 UTC 2025" VOLUMIO_VERSION="4.071" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5fbe1bcf6936184712979c0bfaf061f2"