Apr 15 15:32:10 volumio go-librespot[2072]: time="2026-04-15T15:32:10+09:00" level=trace msg="sent dealer ping" Apr 15 15:32:10 volumio go-librespot[2072]: time="2026-04-15T15:32:10+09:00" level=trace msg="received dealer pong" Apr 15 15:32:36 volumio volumio[1823]: info: Starting Uninstall of plugin music_service - spop Apr 15 15:32:36 volumio volumio[1823]: info: Uninstalling plugin spop Apr 15 15:32:36 volumio go-librespot[2072]: time="2026-04-15T15:32:36+09:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Apr 15 15:32:36 volumio volumio[1823]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Apr 15 15:32:36 volumio volumio[1823]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 15 15:32:36 volumio volumio5-onboarding[2202]: time=2026-04-15T15:32:36.849+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:32:36 volumio volumio[1823]: info: Disabling plugin spop Apr 15 15:32:36 volumio volumio5-onboarding[2202]: time=2026-04-15T15:32:36.855+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:32:36 volumio volumio[1823]: info: Checking if uninstall.sh is present Apr 15 15:32:36 volumio volumio[1823]: info: Connection to go-librespot Websocket closed Apr 15 15:32:36 volumio sudo[27078]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service Apr 15 15:32:36 volumio sudo[27078]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 15:32:36 volumio volumio[1823]: info: Executing uninstall.sh Apr 15 15:32:36 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Apr 15 15:32:36 volumio systemd[1]: go-librespot-daemon.service: Killing process 2075 (go-librespot) with signal SIGKILL. Apr 15 15:32:36 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Apr 15 15:32:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Apr 15 15:32:36 volumio systemd[1]: go-librespot-daemon.service: Consumed 3.599s CPU time. Apr 15 15:32: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. Apr 15 15:32: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. Apr 15 15:32: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. Apr 15 15:32: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. Apr 15 15:32:36 volumio sudo[27078]: pam_unix(sudo:session): session closed for user root Apr 15 15:32:37 volumio sudo[27082]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/music_service/spop/uninstall.sh Apr 15 15:32:37 volumio sudo[27082]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 15:32:37 volumio sudo[27082]: pam_unix(sudo:session): session closed for user root Apr 15 15:32:37 volumio volumio[1823]: info: Uninstall script completed Apr 15 15:32:37 volumio volumio5-onboarding[2202]: time=2026-04-15T15:32:37.065+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:32:37 volumio volumio[1823]: info: Removing plugin spop from configuration Apr 15 15:32:37 volumio volumio[1823]: info: Successfully removed spop configuration files Apr 15 15:32:37 volumio volumio5-onboarding[2202]: time=2026-04-15T15:32:37.148+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:32:37 volumio volumio[1823]: info: Plugin folders cleanup Apr 15 15:32:37 volumio volumio[1823]: info: Scanning into folder /volumio/app/plugins/ Apr 15 15:32:37 volumio volumio[1823]: info: Scanning category audio_interface Apr 15 15:32:37 volumio volumio[1823]: info: Scanning category miscellanea Apr 15 15:32:37 volumio volumio[1823]: info: Scanning category music_service Apr 15 15:32:37 volumio volumio[1823]: info: Scanning category plugins.json Apr 15 15:32:37 volumio volumio[1823]: info: Scanning category system_controller Apr 15 15:32:37 volumio volumio[1823]: info: Scanning category user_interface Apr 15 15:32:37 volumio volumio[1823]: info: Scanning into folder /data/plugins/ Apr 15 15:32:37 volumio volumio[1823]: info: Scanning category music_service Apr 15 15:32:37 volumio volumio[1823]: info: Cleaning folder for spop Apr 15 15:32:38 volumio volumio[1823]: info: Plugin folders cleanup completed Apr 15 15:32:38 volumio volumio[1823]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 15 15:32:38 volumio volumio5-onboarding[2202]: time=2026-04-15T15:32:38.262+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:32:38 volumio volumio[1823]: info: [] Apr 15 15:32:38 volumio volumio[1823]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 15 15:32:55 volumio volumio[1823]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 15 15:33:04 volumio volumio[1823]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/download/spop/4.4.1/volumio/bookworm/armhf Apr 15 15:33:04 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:04.530+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:06 volumio volumio[1823]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/download/spop/4.4.1/volumio/bookworm/armhf Apr 15 15:33:06 volumio volumio[1823]: info: Folder /tmp/plugins removed Apr 15 15:33:06 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:06.428+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:07 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:07.735+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:07 volumio volumio[1823]: info: Check plugin dependencies Apr 15 15:33:07 volumio volumio[1823]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 15 15:33:07 volumio volumio[1823]: info: Checking if plugin already exists Apr 15 15:33:07 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:07.832+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:07 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:07.833+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:07 volumio volumio[1823]: info: Rename folder Apr 15 15:33:07 volumio volumio[1823]: info: Folder /tmp/downloaded_plugin.zip removed Apr 15 15:33:07 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:07.888+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:07 volumio volumio[1823]: info: Move to category Apr 15 15:33:08 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:08.650+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:08 volumio volumio[1823]: info: Checking if install.sh is present Apr 15 15:33:08 volumio volumio[1823]: info: Executing install.sh Apr 15 15:33:08 volumio sudo[27161]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/music_service/spop/install.sh Apr 15 15:33:08 volumio sudo[27161]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 15:33:08 volumio volumio[1823]: info: Installing Go-librespot Apr 15 15:33:08 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:08.728+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:08 volumio volumio[1823]: info: Checking old vollibrespot installs Apr 15 15:33:08 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:08.746+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:08 volumio systemd[1]: Reloading. Apr 15 15:33:10 volumio volumio[1823]: info: Downloading daemon Apr 15 15:33:10 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:10.982+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:13 volumio volumio[1823]: info: Creating directories Apr 15 15:33:13 volumio volumio[1823]: info: Creating data directory Apr 15 15:33:13 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:13.128+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:13 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:13.128+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:13 volumio volumio[1823]: info: Creating Start Script Apr 15 15:33:13 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:13.145+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:13 volumio systemd[1]: Reloading. Apr 15 15:33:15 volumio sudo[27161]: pam_unix(sudo:session): session closed for user root Apr 15 15:33:15 volumio volumio[1823]: Plugin install end detected on script Apr 15 15:33:15 volumio volumio[1823]: info: Install script completed Apr 15 15:33:15 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:15.241+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:15 volumio volumio[1823]: info: Adding reference to registry Apr 15 15:33:15 volumio volumio5-onboarding[2202]: time=2026-04-15T15:33:15.249+09:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Apr 15 15:33:15 volumio volumio[1823]: info: Done installing plugin. Apr 15 15:33:15 volumio volumio[1823]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 15 15:33:15 volumio volumio[1823]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 15 15:33:15 volumio volumio[1823]: info: Folder /tmp/plugins removed Apr 15 15:33:15 volumio volumio[1823]: info: Folder /tmp/downloaded_plugin.zip removed Apr 15 15:33:15 volumio volumio[1823]: info: Folder /data/temp removed Apr 15 15:33:20 volumio volumio[1823]: info: Enabling plugin spop Apr 15 15:33:20 volumio volumio[1823]: info: Loading plugin "spop"... Apr 15 15:33:20 volumio volumio[1823]: info: PLUGIN START: spop Apr 15 15:33:20 volumio volumio[1823]: info: Creating Spotify config file Apr 15 15:33:20 volumio volumio[1823]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 15:33:20 volumio volumio[1823]: info: Done. Apr 15 15:33:20 volumio volumio[1823]: info: Spotify config file written Apr 15 15:33:20 volumio volumio[1823]: info: No need to fix Spotify hosts Apr 15 15:33:20 volumio sudo[27231]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 15 15:33:20 volumio sudo[27231]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 15:33:20 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. Apr 15 15:33:20 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. Apr 15 15:33:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Apr 15 15:33:20 volumio go-librespot[27233]: go-librespot daemon starting... Apr 15 15:33:20 volumio sudo[27231]: pam_unix(sudo:session): session closed for user root Apr 15 15:33:20 volumio go-librespot[27234]: time="2026-04-15T15:33:20+09:00" level=info msg="running go-librespot 0.7.1" Apr 15 15:33:20 volumio go-librespot[27234]: time="2026-04-15T15:33:20+09:00" level=debug msg="no app state found" Apr 15 15:33:20 volumio go-librespot[27234]: time="2026-04-15T15:33:20+09:00" level=debug msg="stored credentials not found" Apr 15 15:33:20 volumio go-librespot[27234]: time="2026-04-15T15:33:20+09:00" level=info msg="generated new device id: b39e1ad3aea0639c0d42e50a821cca7ce22507ca" Apr 15 15:33:20 volumio go-librespot[27234]: time="2026-04-15T15:33:20+09:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 15 15:33:20 volumio go-librespot[27234]: time="2026-04-15T15:33:20+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 15 15:33:20 volumio go-librespot[27234]: time="2026-04-15T15:33:20+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Apr 15 15:33:20 volumio go-librespot[27234]: time="2026-04-15T15:33:20+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 15 15:33:20 volumio go-librespot[27234]: time="2026-04-15T15:33:20+09:00" level=info msg="zeroconf server listening on port 35179" Apr 15 15:33:20 volumio go-librespot[27234]: time="2026-04-15T15:33:20+09:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Apr 15 15:33:23 volumio volumio[1823]: info: go-librespot daemon successfully initialized Apr 15 15:33:26 volumio volumio[1823]: info: Initializing connection to go-librespot Websocket Apr 15 15:33:26 volumio go-librespot[27234]: time="2026-04-15T15:33:26+09:00" level=debug msg="new websocket client" Apr 15 15:33:26 volumio volumio[1823]: info: Connection to go-librespot Websocket established Apr 15 15:33:29 volumio volumio[1823]: info: Enabling plugin spop Apr 15 15:33:29 volumio volumio[1823]: info: Loading plugin "spop"... Apr 15 15:33:29 volumio volumio[1823]: info: PLUGIN START: spop Apr 15 15:33:29 volumio volumio[1823]: info: Creating Spotify config file Apr 15 15:33:29 volumio volumio[1823]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 15 15:33:29 volumio volumio[1823]: info: Done. Apr 15 15:33:29 volumio volumio[1823]: info: Spotify config file written Apr 15 15:33:29 volumio volumio[1823]: info: No need to fix Spotify hosts Apr 15 15:33:29 volumio sudo[27259]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 15 15:33:29 volumio sudo[27259]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 15:33:29 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Apr 15 15:33:29 volumio systemd[1]: go-librespot-daemon.service: Killing process 27242 (go-librespot) with signal SIGKILL. Apr 15 15:33:29 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Apr 15 15:33:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Apr 15 15:33:29 volumio volumio[1823]: info: Connection to go-librespot Websocket closed Apr 15 15:33:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Apr 15 15:33:29 volumio sudo[27259]: pam_unix(sudo:session): session closed for user root Apr 15 15:33:29 volumio go-librespot[27261]: go-librespot daemon starting... Apr 15 15:33:29 volumio volumio[1823]: info: Getting Spotify volume Apr 15 15:33:29 volumio volumio[1823]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 15 15:33:29 volumio go-librespot[27262]: time="2026-04-15T15:33:29+09:00" level=info msg="running go-librespot 0.7.1" Apr 15 15:33:29 volumio go-librespot[27262]: time="2026-04-15T15:33:29+09:00" level=debug msg="app state loaded" Apr 15 15:33:29 volumio go-librespot[27262]: time="2026-04-15T15:33:29+09:00" level=debug msg="stored credentials not found" Apr 15 15:33:29 volumio volumio[1823]: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 15 15:33:29 volumio volumio[1823]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Apr 15 15:33:29 volumio volumio[1823]: errno: -111, Apr 15 15:33:29 volumio volumio[1823]: code: 'ECONNREFUSED', Apr 15 15:33:29 volumio volumio[1823]: syscall: 'connect', Apr 15 15:33:29 volumio volumio[1823]: address: '127.0.0.1', Apr 15 15:33:29 volumio volumio[1823]: port: 9879, Apr 15 15:33:29 volumio volumio[1823]: response: undefined Apr 15 15:33:29 volumio volumio[1823]: } Apr 15 15:33:29 volumio volumio[1823]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 15 15:33:29 volumio go-librespot[27262]: time="2026-04-15T15:33:29+09:00" level=info msg="api server listening on 127.0.0.1:9879" Apr 15 15:33:29 volumio go-librespot[27262]: time="2026-04-15T15:33:29+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 15 15:33:29 volumio go-librespot[27262]: time="2026-04-15T15:33:29+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 15 15:33:29 volumio go-librespot[27262]: time="2026-04-15T15:33:29+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 15 15:33:29 volumio go-librespot[27262]: time="2026-04-15T15:33:29+09:00" level=info msg="zeroconf server listening on port 36473" Apr 15 15:33:29 volumio go-librespot[27262]: time="2026-04-15T15:33:29+09:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Apr 15 15:33:30 volumio sudo[27286]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-04-15 15:32' Apr 15 15:33:30 volumio sudo[27286]: 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"