Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 22 14:00:00 volumio volumio[14987]: info: Adding plugin bluetooth to MyMusic Plugins Dec 22 14:00:00 volumio volumio[14987]: info: Adding plugin multiroom to MyMusic Plugins Dec 22 14:00:00 volumio volumio[14987]: info: Adding plugin metavolumio to MyMusic Plugins Dec 22 14:00:00 volumio volumio[14987]: info: Adding plugin cd_controller to MyMusic Plugins Dec 22 14:00:00 volumio volumio[14987]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 22 14:00:00 volumio volumio[14987]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 22 14:00:00 volumio volumio[14987]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 22 14:00:00 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:00 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:00 volumio volumio[14987]: info: Starting MyVolumio Remote Streaming Endpoints Dec 22 14:00:00 volumio volumio[14987]: info: MyVolumio login type: Token Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 22 14:00:00 volumio volumio[14987]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 22 14:00:01 volumio volumio[14987]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 22 14:00:01 volumio volumio[14987]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 22 14:00:01 volumio volumio[14987]: info: Streaming services startup Dec 22 14:00:01 volumio volumio[14987]: info: Starting Streaming Daemon Dec 22 14:00:01 volumio sudo[15322]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 22 14:00:01 volumio volumio[14987]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 22 14:00:01 volumio sudo[15322]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:01 volumio sudo[15322]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:01 volumio volumio[14987]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:01 volumio volumio[14987]: error: Cannot start Volumio Streaming Daemon Dec 22 14:00:01 volumio volumio[14987]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 22 14:00:01 volumio volumio[14987]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 22 14:00:01 volumio volumio[14987]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:01 volumio volumio[14987]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 22 14:00:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 22 14:00:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:01 volumio go-librespot[15328]: go-librespot daemon starting... Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=debug msg="app state loaded" Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=info msg="zeroconf server listening on port 40253" Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=debug msg="obtained new client token: AADqAL5pb9LuoX0UD/bE7D0HodcVqZEjDnxD82awiHAeKQWKbj1OVbSuPWf3wy9zUTALvjEuk1n1Jm8eJV40YmtMoGeqWm9jtDqayZqlmRSCg6hT3LaunoOkyLxaDasthdlBfhYqa2R/KTpzicks/aZNthjEwQqAshNd+C3Ei6UhuPLs7ZeFFKducEWCvPgCu3O6n3pyYlZFbfctO637UAChLWbMpd9K9WQd5a07yl6BQL9wTRbDdVxH3Q==" Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=debug msg="completed challenge" Dec 22 14:00:01 volumio go-librespot[15329]: time="2025-12-22T14:00:01+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:01 volumio volumio[14987]: info: MyVolumio token set successfully Dec 22 14:00:01 volumio volumio[14987]: info: MYVOLUMIO: Adding device Dec 22 14:00:01 volumio volumio[14987]: info: MYVOLUMIO: Evaluating Server Dec 22 14:00:01 volumio volumio[14987]: info: MyVolumio status changed Dec 22 14:00:01 volumio volumio[14987]: info: Streaming services startup Dec 22 14:00:01 volumio volumio[14987]: info: Starting Streaming Daemon Dec 22 14:00:01 volumio volumio[14987]: info: Removing browser output: myVolumio user plan is not superstar Dec 22 14:00:01 volumio volumio[14987]: info: Removing audio output: Dec 22 14:00:01 volumio volumio[14987]: info: Stoppping Tunnel 1 Dec 22 14:00:01 volumio sudo[15357]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 22 14:00:01 volumio sudo[15357]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:01 volumio sudo[15359]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 22 14:00:01 volumio sudo[15359]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:01 volumio sudo[15357]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:01 volumio volumio[14987]: error: Cannot start Volumio Streaming Daemon Dec 22 14:00:01 volumio volumio[14987]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 22 14:00:01 volumio volumio[14987]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 22 14:00:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:01 volumio sudo[15359]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:01 volumio volumio[14987]: info: Remote SSH Stopped Dec 22 14:00:02 volumio volumio[14987]: info: Setting Geolocation for MyVolumio to eu11 Dec 22 14:00:02 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:02 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:02 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:02 volumio volumio[14987]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 22 14:00:03 volumio volumio[14987]: info: Updating MyVolumio device info Dec 22 14:00:03 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:03 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:03 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:03 volumio volumio[14987]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 22 14:00:04 volumio volumio[14987]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:04 volumio volumio[14987]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 22 14:00:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:04 volumio go-librespot[15362]: go-librespot daemon starting... Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+01:00" level=debug msg="app state loaded" Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+01:00" level=info msg="zeroconf server listening on port 38089" Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+01:00" level=debug msg="obtained new client token: AAB9anplqpuRcuKpwzyLp/ob15ExuvVGAtVfujciarztpVidry0pb6uheTsUTo3OGIkpNS2A6kQii3/sLIhf3Sv2xyLdgxRi12w1fzlnZeixq1AvCpcfsqY2Lzv5BG7vwR0Qg8oaU1//mZeWvN/qQ3Znle5ZwIiTx41RBCjKfxbAdiC0V8uJB1WjewstwOKngkVS0Qgc5D/rX9DVW7NUnMUYPIwOj3Vzxxv+aYsHp1JvD4P0V2XgJBCmhg==" Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+01:00" level=debug msg="completed challenge" Dec 22 14:00:04 volumio go-librespot[15363]: time="2025-12-22T14:00:04+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:06 volumio volumio[14987]: info: MYVOLUMIO: Adding device Dec 22 14:00:06 volumio volumio[14987]: info: MYVOLUMIO: Evaluating Server Dec 22 14:00:06 volumio volumio[14987]: info: Setting Geolocation for MyVolumio to eu10 Dec 22 14:00:06 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:06 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:06 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:07 volumio volumio[14987]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:07 volumio volumio[14987]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:07 volumio volumio[14987]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 22 14:00:07 volumio volumio[14987]: info: Updating MyVolumio device info Dec 22 14:00:07 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:07 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:07 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 22 14:00:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:08 volumio go-librespot[15389]: go-librespot daemon starting... Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+01:00" level=debug msg="app state loaded" Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+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-gae2.spotify.com:80]" Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+01:00" level=info msg="zeroconf server listening on port 46379" Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+01:00" level=debug msg="obtained new client token: AAC4qNuU/JzxL/AvDUJ2Ps8U1UbeRxx7l9mjl8KxbT323aHZdUH7FI8m7RAJYF2MUfp8WtCEdVwsUH9Ys9U/d4ZBbhpOUy0AvxIRsfBxmgNrXRQLKWNv4Q28xyR3t8Bns1VHSFKb6SaP9fA8EntKZlQLeUCGqREo/g0xmUkAQOzneo1KF/emm1R8a1tWYQogJTAsXaV5n0DhWnfOB8YAPRaTHoj9VU6FQ82vQsbaaMTmzzlZQtZ7WDA=" Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+01:00" level=debug msg="completed challenge" Dec 22 14:00:08 volumio go-librespot[15390]: time="2025-12-22T14:00:08+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:08 volumio volumio[14987]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 22 14:00:10 volumio volumio[14987]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:10 volumio volumio[14987]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 22 14:00:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:11 volumio go-librespot[15411]: go-librespot daemon starting... Dec 22 14:00:11 volumio go-librespot[15412]: time="2025-12-22T14:00:11+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:11 volumio go-librespot[15412]: time="2025-12-22T14:00:11+01:00" level=debug msg="app state loaded" Dec 22 14:00:11 volumio go-librespot[15412]: time="2025-12-22T14:00:11+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:11 volumio go-librespot[15412]: time="2025-12-22T14:00:11+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:11 volumio go-librespot[15412]: time="2025-12-22T14:00:11+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-gae2.spotify.com:80]" Dec 22 14:00:11 volumio go-librespot[15412]: time="2025-12-22T14:00:11+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:11 volumio go-librespot[15412]: time="2025-12-22T14:00:11+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:11 volumio go-librespot[15412]: time="2025-12-22T14:00:11+01:00" level=info msg="zeroconf server listening on port 44025" Dec 22 14:00:11 volumio go-librespot[15412]: time="2025-12-22T14:00:11+01:00" level=debug msg="obtained new client token: AACxeMVmK/rdx8qMG7ZUNviM7IZT7WJbqwMAQFPXWx08Fot71Ad2XKfK3sKuEf46/hoZLX4udbbOjqxbHxDjejGm5/z3oMO3gsGhRjJR8FQZyM/hxS+fI/IfWXOfq6nWSwo3iefq195BRLrotC0WETVVkHtdZA3nOiayFuVIomboSyA0utz8LrI8EmDQZqtc3CEVNJ1ACGXVddYGolqbrZsOSV3xOMXr8I4u5XR0c3a3BrypzEkKAN3Edw==" Dec 22 14:00:11 volumio go-librespot[15412]: time="2025-12-22T14:00:11+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:13 volumio volumio[14987]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:13 volumio go-librespot[15412]: time="2025-12-22T14:00:13+01:00" level=debug msg="new websocket client" Dec 22 14:00:13 volumio volumio[14987]: info: Connection to go-librespot Websocket established Dec 22 14:00:13 volumio go-librespot[15412]: time="2025-12-22T14:00:13+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:13 volumio go-librespot[15412]: time="2025-12-22T14:00:13+01:00" level=debug msg="completed challenge" Dec 22 14:00:13 volumio go-librespot[15412]: time="2025-12-22T14:00:13+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:13 volumio volumio[14987]: info: Connection to go-librespot Websocket closed Dec 22 14:00:15 volumio volumio[14987]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 22 14:00:15 volumio volumio[14987]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Dec 22 14:00:15 volumio volumio[14987]: info: CoreCommandRouter::volumioGetState Dec 22 14:00:15 volumio volumio[14987]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:16 volumio volumio[14987]: info: Getting Spotify volume Dec 22 14:00:16 volumio volumio[14987]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 22 14:00:16 volumio volumio[14987]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:16 volumio volumio[14987]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 22 14:00:16 volumio volumio[14987]: errno: -111, Dec 22 14:00:16 volumio volumio[14987]: code: 'ECONNREFUSED', Dec 22 14:00:16 volumio volumio[14987]: syscall: 'connect', Dec 22 14:00:16 volumio volumio[14987]: address: '127.0.0.1', Dec 22 14:00:16 volumio volumio[14987]: port: 9879, Dec 22 14:00:16 volumio volumio[14987]: response: undefined Dec 22 14:00:16 volumio volumio[14987]: } Dec 22 14:00:16 volumio volumio[14987]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 22 14:00:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 22 14:00:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:16 volumio go-librespot[15434]: go-librespot daemon starting... Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+01:00" level=debug msg="app state loaded" Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:16 volumio sudo[15443]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-22 13:59' Dec 22 14:00:16 volumio sudo[15443]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+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]" Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+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]" Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+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]" Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+01:00" level=info msg="zeroconf server listening on port 37697" Dec 22 14:00:16 volumio sudo[15443]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:16 volumio volumio-remote-updater[994]: [2025-12-22 14:00:16] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 22 14:00:16 volumio volumio-remote-updater[994]: [2025-12-22 14:00:16] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 22 14:00:16 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+01:00" level=debug msg="obtained new client token: AAAAr/EohBEpBx6e2cwm5L2MijY912djmdzeMqUs6qTPnZ+J+z7WhavQjkmqRaHVN1R+mCJ0bCsywae0A2p4xIHy/UGJ3GgqG9+1vin8gUe3WRGHR689geNpxgtWdl3gUg5Gip6u9mjhIwBC7Xbd9oEnidKPT7VE6+CVglv9SNLoD/p2cfxqgla6ZdrnMmcPtiTt/wXwChg4USNStv2uP1uENLRzTIHXrAPk855mETZhTZmSA9kLWaIVZw==" Dec 22 14:00:16 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 22 14:00:16 volumio systemd[1]: volumio.service: Consumed 8.686s CPU time. Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:16 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 22 14:00:16 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+01:00" level=debug msg="completed challenge" Dec 22 14:00:16 volumio go-librespot[15435]: time="2025-12-22T14:00:16+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:16 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 25. Dec 22 14:00:16 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 22 14:00:16 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 22 14:00:16 volumio systemd[1]: volumio.service: Consumed 8.686s CPU time. Dec 22 14:00:16 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 22 14:00:16 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 22 14:00:17 volumio volumio[15460]: info: ------------------------------------------- Dec 22 14:00:17 volumio volumio[15460]: info: ----- Volumio3 ---- Dec 22 14:00:17 volumio volumio[15460]: info: ------------------------------------------- Dec 22 14:00:17 volumio volumio[15460]: info: ----- System startup ---- Dec 22 14:00:17 volumio volumio[15460]: info: ------------------------------------------- Dec 22 14:00:17 volumio volumio[15460]: info: MYVOLUMIO Environment detected Dec 22 14:00:17 volumio volumio[15460]: info: Plugin folders cleanup Dec 22 14:00:17 volumio volumio[15460]: info: Scanning into folder /volumio/app/plugins/ Dec 22 14:00:17 volumio volumio[15460]: info: Scanning category audio_interface Dec 22 14:00:17 volumio volumio[15460]: info: Scanning category miscellanea Dec 22 14:00:17 volumio volumio[15460]: info: Scanning category music_service Dec 22 14:00:17 volumio volumio[15460]: info: Scanning category plugins.json Dec 22 14:00:17 volumio volumio[15460]: info: Scanning category system_controller Dec 22 14:00:17 volumio volumio[15460]: info: Scanning category user_interface Dec 22 14:00:17 volumio volumio[15460]: info: Scanning into folder /data/plugins/ Dec 22 14:00:17 volumio volumio[15460]: info: Scanning category music_service Dec 22 14:00:17 volumio volumio[15460]: info: Plugin folders cleanup completed Dec 22 14:00:17 volumio volumio[15460]: info: ------------------------------------------- Dec 22 14:00:17 volumio volumio[15460]: info: ----- Core plugins startup ---- Dec 22 14:00:17 volumio volumio[15460]: info: ------------------------------------------- Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugins from folder /volumio/app/plugins/ Dec 22 14:00:17 volumio volumio[15460]: info: Adding plugin upnp to MyMusic Plugins Dec 22 14:00:17 volumio volumio[15460]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 22 14:00:17 volumio volumio[15460]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugins from folder /data/plugins/ Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugin "system"... Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugin "appearance"... Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugin "network"... Dec 22 14:00:17 volumio volumio[15460]: info: Refreshing Cached IP Addresses Dec 22 14:00:17 volumio sudo[15488]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 22 14:00:17 volumio sudo[15488]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:17 volumio sudo[15490]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 22 14:00:17 volumio sudo[15488]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:17 volumio sudo[15490]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:17 volumio sudo[15490]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugin "services"... Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugin "alsa_controller"... Dec 22 14:00:17 volumio sudo[15499]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 22 14:00:17 volumio sudo[15499]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:17 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugin "wizard"... Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugin "networkfs"... Dec 22 14:00:17 volumio volumio[15460]: info: Starting Udev Watcher for removable devices Dec 22 14:00:17 volumio volumio[15460]: info: Ignoring mount for partition: boot Dec 22 14:00:17 volumio volumio[15460]: info: Ignoring mount for partition: volumio Dec 22 14:00:17 volumio volumio[15460]: info: Ignoring mount for partition: volumio_data Dec 22 14:00:17 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugin "volumio_command_line_client"... Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugin "upnp"... Dec 22 14:00:17 volumio volumio[15460]: info: [1766408417936] Starting Upmpd Daemon Dec 22 14:00:17 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugin "my_music"... Dec 22 14:00:17 volumio volumio[15460]: info: Loading plugin "mpd"... Dec 22 14:00:18 volumio volumio[15460]: info: Loading plugin "upnp_browser"... Dec 22 14:00:18 volumio volumio[15460]: info: Starting UPNP Browser Dec 22 14:00:18 volumio volumio[15460]: info: Loading plugin "alarm-clock"... Dec 22 14:00:18 volumio volumio[15460]: info: Loading plugin "airplay_emulation"... Dec 22 14:00:18 volumio volumio[15460]: info: Starting Shairport Sync Dec 22 14:00:18 volumio volumio[15460]: info: Loading plugin "last_100"... Dec 22 14:00:18 volumio volumio[15460]: info: Loading plugin "webradio"... Dec 22 14:00:18 volumio volumio[15460]: info: Loading plugin "i2s_dacs"... Dec 22 14:00:18 volumio volumio[15460]: info: Loading plugin "volumiodiscovery"... Dec 22 14:00:18 volumio volumio[15460]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 22 14:00:18 volumio volumio[15460]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 22 14:00:18 volumio volumio[15460]: *** WARNING *** For more information see Dec 22 14:00:18 volumio volumio[15460]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 22 14:00:18 volumio volumio[15460]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 22 14:00:18 volumio volumio[15460]: *** WARNING *** For more information see Dec 22 14:00:18 volumio node[15460]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 22 14:00:18 volumio node[15460]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 22 14:00:18 volumio node[15460]: *** WARNING *** For more information see Dec 22 14:00:18 volumio node[15460]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 22 14:00:18 volumio node[15460]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 22 14:00:18 volumio node[15460]: *** WARNING *** For more information see Dec 22 14:00:18 volumio volumio[15460]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 22 14:00:18 volumio volumio[15460]: info: Discovery: Started advertising with name: Volumio Dec 22 14:00:18 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 22 14:00:18 volumio volumio[15460]: info: Loading plugin "spop"... Dec 22 14:00:18 volumio volumio[15460]: info: Loading plugin "ytmusic"... Dec 22 14:00:19 volumio volumio[15460]: info: Loading plugin "outputs"... Dec 22 14:00:19 volumio volumio[15460]: info: Loading plugin "albumart"... Dec 22 14:00:19 volumio volumio[15460]: info: Plugin example_plugin is not enabled Dec 22 14:00:19 volumio volumio[15460]: info: Loading plugin "inputs"... Dec 22 14:00:19 volumio volumio[15460]: info: Loading plugin "updater_comm"... Dec 22 14:00:19 volumio volumio[15460]: info: Plugin mpdemulation is not enabled Dec 22 14:00:19 volumio volumio[15460]: info: Loading plugin "rest_api"... Dec 22 14:00:19 volumio volumio[15460]: info: Loading plugin "websocket"... Dec 22 14:00:19 volumio volumio[15460]: info: Starting Socket.io Server version 1.7.4 Dec 22 14:00:19 volumio volumio[15460]: info: Loading i18n strings for locale de Dec 22 14:00:19 volumio volumio[15460]: Updating browse sources language Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::initPlayerControls Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: Express server listening on port 3000 Dec 22 14:00:19 volumio volumio[15460]: [Metrics] WebUI: 1s 989.14ms Dec 22 14:00:19 volumio volumio[15460]: info: CoreStateMachine::resetVolumioState Dec 22 14:00:19 volumio volumio[15460]: info: CoreStateMachine::getcurrentVolume Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::volumioRetrievevolume Dec 22 14:00:19 volumio volumio[15460]: info: Volumio Network Manager: Network status updated: 1 Dec 22 14:00:19 volumio volumio[15460]: verbose: New Socket.io Connection to 10.3.0.14 from 10.3.0.12 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Dec 22 14:00:19 volumio volumio[15460]: info: CoreStateMachine::pushState Dec 22 14:00:19 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::volumioPushState Dec 22 14:00:19 volumio volumio[15460]: info: CoreStateMachine::updateTrackBlock Dec 22 14:00:19 volumio volumio[15520]: Forking 3 albumart workers Dec 22 14:00:19 volumio volumio[15460]: info: CorePlayQueue::getTrackBlock Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::volumioRetrievevolume Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: Executing start script for DAC Volumio Zero ES9039 DAC Dec 22 14:00:19 volumio volumio[15460]: info: Reloading queue from file Dec 22 14:00:19 volumio volumio[15460]: info: CoreStateMachine::setRepeat null single undefined Dec 22 14:00:19 volumio volumio[15460]: info: CoreStateMachine::pushState Dec 22 14:00:19 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::volumioPushState Dec 22 14:00:19 volumio volumio[15460]: info: CoreStateMachine::setRandom null Dec 22 14:00:19 volumio volumio[15460]: info: CoreStateMachine::pushState Dec 22 14:00:19 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::volumioPushState Dec 22 14:00:19 volumio volumio[15460]: info: Setting Device type: Raspberry PI Dec 22 14:00:19 volumio volumio[15460]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 22 14:00:19 volumio volumio[15460]: info: USB Boot Capable - System SBC Revision found in cpuinfo: d04171 Dec 22 14:00:19 volumio volumio[15460]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 22 14:00:19 volumio sudo[15573]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cset -y 1 0x48 0x00 0x02 Dec 22 14:00:19 volumio sudo[15573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:19 volumio volumio[15460]: info: CoreStateMachine::pushState Dec 22 14:00:19 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::volumioPushState Dec 22 14:00:19 volumio sudo[15573]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:19 volumio volumio[15460]: info: DAC script executed Dec 22 14:00:19 volumio volumio[15460]: info: Completed loading Core Plugins Dec 22 14:00:19 volumio volumio[15460]: info: Preparing to generate the ALSA configuration file Dec 22 14:00:19 volumio volumio[15460]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Dec 22 14:00:19 volumio volumio[15460]: info: Reading ALSA contributions from plugins. Dec 22 14:00:19 volumio volumio[15460]: info: Asound.conf file unchanged, so no further update is needed Dec 22 14:00:19 volumio volumio[15460]: info: Output device has changed, restarting MPD Dec 22 14:00:19 volumio volumio[15460]: info: Output device has changed, restarting Shairport Sync Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:19 volumio sudo[15588]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 22 14:00:19 volumio sudo[15588]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:19 volumio sudo[15589]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 22 14:00:19 volumio sudo[15589]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:19 volumio sudo[15588]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:19 volumio volumio[15460]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 22 14:00:19 volumio volumio[15460]: info: ___________ START PLUGINS ___________ Dec 22 14:00:19 volumio volumio[15460]: info: ControllerMpd::onStart: Initializing MPD Dec 22 14:00:19 volumio volumio[15460]: info: Creating MPD Configuration file Dec 22 14:00:19 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 22 14:00:19 volumio volumio[15460]: info: [1766408419331] CoreMusicLibrary::Adding element Medienserver Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:00:19 volumio volumio[15460]: info: UPNP Browser: Client initialized successfully Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:19 volumio sudo[15601]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 22 14:00:19 volumio sudo[15601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:19 volumio sudo[15601]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:19 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 22 14:00:19 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 22 14:00:19 volumio volumio[15460]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 22 14:00:19 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 22 14:00:19 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 22 14:00:19 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:19 volumio sudo[15600]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 22 14:00:19 volumio sudo[15600]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:19 volumio volumio[15460]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 22 14:00:19 volumio volumio[15460]: info: [1766408419369] CoreMusicLibrary::Adding element Last_100 Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 22 14:00:19 volumio volumio[15460]: info: [1766408419373] CoreMusicLibrary::Adding element Webradio Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 22 14:00:19 volumio volumio[15460]: info: Initializing BBC Radios Dec 22 14:00:19 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 22 14:00:19 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 22 14:00:19 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 22 14:00:19 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 22 14:00:19 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 22 14:00:19 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 22 14:00:19 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 22 14:00:19 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 22 14:00:19 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: Creating Spotify config file Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio sudo[15619]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 22 14:00:19 volumio sudo[15619]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 22 14:00:19 volumio sudo[15619]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 22 14:00:19 volumio volumio[15460]: info: [1766408419571] CoreMusicLibrary::Adding element YouTube Music Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:00:19 volumio volumio[15460]: Cannot find translation for source YouTube Music Dec 22 14:00:19 volumio volumio[15460]: info: Volumio Calling Home Dec 22 14:00:19 volumio volumio[15460]: info: MPD Permissions set Dec 22 14:00:19 volumio volumio[15460]: info: MPD Permissions set Dec 22 14:00:19 volumio volumio[15460]: info: Spotify config file written Dec 22 14:00:19 volumio volumio[15460]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 22 14:00:19 volumio sudo[15636]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 22 14:00:19 volumio sudo[15636]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:19 volumio volumio[15460]: info: Volumio called home Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Dec 22 14:00:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15548]: Starting albumart workers Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:19 volumio volumio[15460]: info: No need to fix Spotify hosts Dec 22 14:00:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:19 volumio go-librespot[15644]: go-librespot daemon starting... Dec 22 14:00:19 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 22 14:00:19 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 22 14:00:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:19 volumio go-librespot[15651]: go-librespot daemon starting... Dec 22 14:00:19 volumio sudo[15636]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:19 volumio go-librespot[15652]: time="2025-12-22T14:00:19+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:19 volumio go-librespot[15652]: time="2025-12-22T14:00:19+01:00" level=debug msg="app state loaded" Dec 22 14:00:19 volumio go-librespot[15652]: time="2025-12-22T14:00:19+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:19 volumio go-librespot[15652]: time="2025-12-22T14:00:19+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:19 volumio volumio[15460]: info: Discovery: adding 11b27728-79cb-4bae-acc4-888bcd85248c Dec 22 14:00:19 volumio volumio[15460]: info: Discovery: Found device Volumio Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::volumioGetState Dec 22 14:00:19 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:19 volumio volumio[15460]: info: Starting Shairport Sync Dec 22 14:00:19 volumio volumio[15460]: info: Starting Shairport Sync Dec 22 14:00:19 volumio volumio[15460]: info: Starting Shairport Sync Dec 22 14:00:19 volumio go-librespot[15652]: time="2025-12-22T14:00:19+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-gae2.spotify.com:80]" Dec 22 14:00:19 volumio go-librespot[15652]: time="2025-12-22T14:00:19+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:19 volumio go-librespot[15652]: time="2025-12-22T14:00:19+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:19 volumio go-librespot[15652]: time="2025-12-22T14:00:19+01:00" level=info msg="zeroconf server listening on port 33367" Dec 22 14:00:19 volumio sudo[15660]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 22 14:00:19 volumio sudo[15660]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:19 volumio volumio[15551]: Starting albumart workers Dec 22 14:00:19 volumio volumio[15460]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 22 14:00:19 volumio volumio[15460]: SPOTIFY: BQAYgd4iuyJ_Md6mVLZMfTYx7HmEmBQl9xz6zXq5dc16f3WIWhiPOn5-_hA-1utS6r8hYNAWwpDmqy86W_1RLgOF-ODU5f2kTS8iCl_OD71OEdLc6ktiyNZxzNC2sl2aYnCxYu4yvcMGoi5wIVKuNZotatZkNIcBZWGe-83h5dOr6wx6cPxkD4eFqmF6jmkw9VgKz2op79lR0ixb10ia5Ox22YzqjwtxD7RL82lxTL_GuGjZJDSfMJq8Oo1zc_oZ3FTesB21pWJv-rO9RGKQOZ3_mv4v0rsCATbgIkrQT3nX5x1qX2_OGY8V Dec 22 14:00:19 volumio volumio[15460]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 22 14:00:19 volumio volumio[15460]: info: New Spotify access token = BQAYgd4iuyJ_Md6mVLZMfTYx7HmEmBQl9xz6zXq5dc16f3WIWhiPOn5-_hA-1utS6r8hYNAWwpDmqy86W_1RLgOF-ODU5f2kTS8iCl_OD71OEdLc6ktiyNZxzNC2sl2aYnCxYu4yvcMGoi5wIVKuNZotatZkNIcBZWGe-83h5dOr6wx6cPxkD4eFqmF6jmkw9VgKz2op79lR0ixb10ia5Ox22YzqjwtxD7RL82lxTL_GuGjZJDSfMJq8Oo1zc_oZ3FTesB21pWJv-rO9RGKQOZ3_mv4v0rsCATbgIkrQT3nX5x1qX2_OGY8V Dec 22 14:00:19 volumio volumio[15460]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 22 14:00:19 volumio sudo[15665]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 22 14:00:19 volumio sudo[15665]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:19 volumio sudo[15662]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 22 14:00:19 volumio sudo[15662]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:19 volumio volumio[15460]: info: Discovery: this is already registered, 11b27728-79cb-4bae-acc4-888bcd85248c Dec 22 14:00:19 volumio volumio[15460]: info: Discovery: Found device Volumio Dec 22 14:00:19 volumio volumio[15460]: info: CoreCommandRouter::volumioGetState Dec 22 14:00:19 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:19 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 22 14:00:19 volumio go-librespot[15652]: time="2025-12-22T14:00:19+01:00" level=debug msg="obtained new client token: AACIcdtFtCzzNB7ordVhuiXTRepo1kPAfUdR+CWWaQB7c8ikzUdZ4FaFj3cQs2YuObMxRFHAJ6HGQ2X90DDY3GRIyrF3hb40Qqcz9K+YjPNR+eFIvOpMikvrvYNMwM0ts8w2FzlWmrc2HgdaEGizZYspPOGT+yl5PtsfWRFY1cbE4YUJiCiKDhvj4vbbw3/iS0YorLqYufCpKHC1WZWspTUxauKgCBZXHzB0yACAs6FD9mcZAE35uNdGkA==" Dec 22 14:00:19 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 22 14:00:19 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 22 14:00:19 volumio systemd[1]: shairport-sync.service: Consumed 1.549s CPU time. Dec 22 14:00:20 volumio volumio[15554]: Starting albumart workers Dec 22 14:00:20 volumio go-librespot[15652]: time="2025-12-22T14:00:20+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:20 volumio go-librespot[15652]: time="2025-12-22T14:00:20+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:20 volumio go-librespot[15652]: time="2025-12-22T14:00:20+01:00" level=debug msg="completed challenge" Dec 22 14:00:20 volumio volumio[15460]: info: CoreCommandRouter::volumioGetState Dec 22 14:00:20 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:20 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 22 14:00:20 volumio sudo[15662]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:20 volumio sudo[15665]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:20 volumio sudo[15660]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:20 volumio go-librespot[15652]: time="2025-12-22T14:00:20+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:20 volumio volumio[15460]: info: Shairport-Sync Started Dec 22 14:00:20 volumio volumio[15460]: Error adding Membership: Error: addMembership EINVAL Dec 22 14:00:20 volumio volumio[15460]: info: Shairport-Sync Started Dec 22 14:00:20 volumio volumio[15460]: info: Shairport-Sync Started Dec 22 14:00:20 volumio volumio[15460]: SPOTIFY: User informations: {"country":"TR","display_name":"Florian","email":"florian@goezler.de","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/3136ot245q7ef5grbzukyn2yg4tq"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/3136ot245q7ef5grbzukyn2yg4tq","id":"3136ot245q7ef5grbzukyn2yg4tq","images":[],"product":"free","type":"user","uri":"spotify:user:3136ot245q7ef5grbzukyn2yg4tq"} Dec 22 14:00:20 volumio volumio[15460]: info: Spotify Successfully logged in Dec 22 14:00:20 volumio volumio[15460]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 22 14:00:20 volumio volumio[15460]: info: [1766408420144] CoreMusicLibrary::Adding element Spotify Dec 22 14:00:20 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:00:20 volumio volumio[15460]: Cannot find translation for source YouTube Music Dec 22 14:00:20 volumio volumio[15460]: Cannot find translation for source Spotify Dec 22 14:00:20 volumio mpd[15630]: 2025-12-22T14:00:20 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 22 14:00:20 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 22 14:00:20 volumio sudo[15600]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:20 volumio sudo[15589]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:20 volumio volumio[15460]: info: Completed starting Core Plugins Dec 22 14:00:20 volumio volumio[15460]: info: ------------------------------------------- Dec 22 14:00:20 volumio volumio[15460]: info: ----- MyVolumio plugins startup ---- Dec 22 14:00:20 volumio volumio[15460]: info: ------------------------------------------- Dec 22 14:00:20 volumio volumio[15460]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 22 14:00:20 volumio volumio[15460]: error: MPD error: The expression evaluated to a falsy value: Dec 22 14:00:20 volumio volumio[15460]: assert.ok(self.idling) Dec 22 14:00:20 volumio volumio[15460]: error: The expression evaluated to a falsy value: Dec 22 14:00:20 volumio volumio[15460]: assert.ok(self.idling) Dec 22 14:00:20 volumio volumio[15460]: info: MPD running with PID15630 Dec 22 14:00:20 volumio volumio[15460]: ,establishing connection Dec 22 14:00:20 volumio volumio[15460]: error: updateQueue error: null Dec 22 14:00:20 volumio volumio[15460]: error: updateQueue error: null Dec 22 14:00:20 volumio sudo[15499]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:21 volumio volumio-remote-updater[994]: [2025-12-22 14:00:21] [connect] Successful connection Dec 22 14:00:21 volumio volumio-remote-updater[994]: [2025-12-22 14:00:21] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1766408421 101 Dec 22 14:00:21 volumio volumio[15460]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 3 Dec 22 14:00:21 volumio volumio[15460]: verbose: New Socket.io Connection to 10.3.0.14:3000 from 10.3.0.11 UA: Dart/3.9 (dart:io) Engine version: 3 Transport: websocket Total Clients: 4 Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 22 14:00:21 volumio volumio[15460]: info: Discovery: Getting this device information Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::volumioGetState Dec 22 14:00:21 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 22 14:00:21 volumio volumio[15460]: verbose: New Socket.io Connection to 10.3.0.14 from 10.3.0.12 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::volumioGetVisibleSources Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::volumioGetState Dec 22 14:00:21 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::volumioGetState Dec 22 14:00:21 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 22 14:00:21 volumio volumio[15460]: info: Received Get System Info Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 22 14:00:21 volumio volumio[15460]: info: Discovery: Getting this device information Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::volumioGetState Dec 22 14:00:21 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 22 14:00:21 volumio volumio[15460]: info: CoreCommandRouter::volumioGetState Dec 22 14:00:21 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:21 volumio volumio[15460]: info: Listing playlists Dec 22 14:00:22 volumio volumio[15460]: info: go-librespot daemon successfully initialized Dec 22 14:00:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 22 14:00:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:23 volumio go-librespot[15706]: go-librespot daemon starting... Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=debug msg="app state loaded" Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=info msg="zeroconf server listening on port 42883" Dec 22 14:00:23 volumio sudo[15715]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 22 14:00:23 volumio sudo[15715]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=debug msg="obtained new client token: AAA2ynsCm0JYVajj/GRnWhlXCRJ/VyCeiISxeCHSctraNwBTnMoQkHeO1Pd2MJuBqgduzoBC+rN7zrTwJpevPv8Ttp+4H8YkLxBkvn1lWOLzous/lt0Ugt1PptjdbDIWoMFh1UHBvTg5fImXlYA1TEzlZn55QbmOuv9XiSrYoSWXMyPuQ7OlX+1LuroMtHUy+EDNgJf/geOV+7wZjJfk9qbtvT5c1+2MC1iAveqIPITsdX7q1lGSO+Gmyw==" Dec 22 14:00:23 volumio sudo[15717]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 22 14:00:23 volumio sudo[15717]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:23 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 22 14:00:23 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 22 14:00:23 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:23 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 22 14:00:23 volumio sudo[15717]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:23 volumio sudo[15715]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:23 volumio mpd_monitor.sh[15720]: MPD Monitor Service: Starting MPD Monitor Service Dec 22 14:00:23 volumio volumio[15460]: info: Successfully started MPD Monitor Dec 22 14:00:23 volumio volumio[15460]: info: Successfully started MPD Monitor Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=debug msg="completed challenge" Dec 22 14:00:23 volumio go-librespot[15707]: time="2025-12-22T14:00:23+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:25 volumio volumio[15460]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 22 14:00:25 volumio volumio[15460]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:25 volumio volumio[15460]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 22 14:00:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:26 volumio go-librespot[15724]: go-librespot daemon starting... Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=debug msg="app state loaded" Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=info msg="zeroconf server listening on port 41595" Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=debug msg="obtained new client token: AADakWUOR8cV7FIKNp2XOaPtyT+/luFXVJj5uQKwpzgxXWWnrp5KlRbmhAl8ey3vnzxHnsoCGPMsfrtJcZIYBJoHrwhGHWk/apW5s08OLowPzMwLESzMLVQoY691lXvySS7PAgDkPfjE0sJWZ3Ciw4f88itbVWQIQJOMykOmnqSFKcXjKBa1x3sVPw3m521yDquEZ2t8aMbp+w7G4NjHvOOUGI9rHsDHakbflvej2Q/WJ/8ElGGQrTdYcQ==" Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=debug msg="completed challenge" Dec 22 14:00:26 volumio go-librespot[15725]: time="2025-12-22T14:00:26+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:27 volumio sudo[15748]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 22 14:00:27 volumio sudo[15748]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:27 volumio sudo[15750]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 22 14:00:27 volumio sudo[15748]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:27 volumio sudo[15750]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:27 volumio sudo[15750]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:27 volumio sudo[15754]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 22 14:00:27 volumio sudo[15754]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:27 volumio sudo[15754]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:27 volumio volumio[15460]: info: Upmpdcli Daemon Started Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 22 14:00:28 volumio volumio[15460]: info: Adding plugin bluetooth to MyMusic Plugins Dec 22 14:00:28 volumio volumio[15460]: info: Adding plugin multiroom to MyMusic Plugins Dec 22 14:00:28 volumio volumio[15460]: info: Adding plugin metavolumio to MyMusic Plugins Dec 22 14:00:28 volumio volumio[15460]: info: Adding plugin cd_controller to MyMusic Plugins Dec 22 14:00:28 volumio volumio[15460]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 22 14:00:28 volumio volumio[15460]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 22 14:00:28 volumio volumio[15460]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 22 14:00:28 volumio volumio[15460]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 22 14:00:29 volumio volumio[15460]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 22 14:00:29 volumio volumio[15460]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 22 14:00:29 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:29 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:29 volumio volumio[15460]: info: Starting MyVolumio Remote Streaming Endpoints Dec 22 14:00:29 volumio volumio[15460]: info: MyVolumio login type: Token Dec 22 14:00:29 volumio volumio[15460]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 22 14:00:29 volumio volumio[15460]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 22 14:00:29 volumio volumio[15460]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 22 14:00:29 volumio volumio[15460]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 22 14:00:29 volumio volumio[15460]: info: Streaming services startup Dec 22 14:00:29 volumio volumio[15460]: info: Starting Streaming Daemon Dec 22 14:00:29 volumio sudo[15757]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 22 14:00:29 volumio sudo[15757]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:29 volumio volumio[15460]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 22 14:00:29 volumio sudo[15757]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:29 volumio volumio[15460]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:29 volumio volumio[15460]: error: Cannot start Volumio Streaming Daemon Dec 22 14:00:29 volumio volumio[15460]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 22 14:00:29 volumio volumio[15460]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 22 14:00:29 volumio volumio[15460]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 22 14:00:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:29 volumio volumio[15460]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 22 14:00:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:29 volumio go-librespot[15763]: go-librespot daemon starting... Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+01:00" level=debug msg="app state loaded" Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+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-gae2.spotify.com:80]" Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+01:00" level=info msg="zeroconf server listening on port 45311" Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+01:00" level=debug msg="obtained new client token: AADe9rxBe4Id8xaOeLa1ZoA8vbzZPfykfYtKTFdmHdYFMah2mfUw0tbNYDY5oQJncYx9eDkTaphiLfx6rmtHgKpWgzqZ1BiHL2386qp+AYrvSoNXth0Rj31CLTVf7CguCEbTMzaFtDxiMEB+jhFy75xGf6G/FXDaHuj2lVuMjBdsYZyX6JmW/Z3R3hTtytta7/DllNCd6VbB/mtXGh97i2Lo899++2JQcPH01PjNxbvyf96H8qx/N1Wqlg==" Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+01:00" level=debug msg="connected to ap-gew4.spotify.com:443" Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:29 volumio go-librespot[15764]: time="2025-12-22T14:00:29+01:00" level=debug msg="completed challenge" Dec 22 14:00:30 volumio go-librespot[15764]: time="2025-12-22T14:00:30+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:30 volumio volumio[15460]: info: MyVolumio token set successfully Dec 22 14:00:30 volumio volumio[15460]: info: MYVOLUMIO: Adding device Dec 22 14:00:30 volumio volumio[15460]: info: MYVOLUMIO: Evaluating Server Dec 22 14:00:30 volumio volumio[15460]: info: MyVolumio status changed Dec 22 14:00:30 volumio volumio[15460]: info: Streaming services startup Dec 22 14:00:30 volumio volumio[15460]: info: Starting Streaming Daemon Dec 22 14:00:30 volumio volumio[15460]: info: Removing browser output: myVolumio user plan is not superstar Dec 22 14:00:30 volumio volumio[15460]: info: Removing audio output: Dec 22 14:00:30 volumio volumio[15460]: info: Stoppping Tunnel 1 Dec 22 14:00:30 volumio sudo[15792]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 22 14:00:30 volumio sudo[15792]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:30 volumio sudo[15794]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 22 14:00:30 volumio sudo[15794]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:00:30 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:30 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:30 volumio sudo[15792]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:30 volumio volumio[15460]: error: Cannot start Volumio Streaming Daemon Dec 22 14:00:30 volumio volumio[15460]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 22 14:00:30 volumio volumio[15460]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 22 14:00:30 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:30 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:30 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:30 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:30 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:30 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:00:30 volumio sudo[15794]: pam_unix(sudo:session): session closed for user root Dec 22 14:00:30 volumio volumio[15460]: info: Remote SSH Stopped Dec 22 14:00:30 volumio volumio[15460]: info: Setting Geolocation for MyVolumio to eu6 Dec 22 14:00:30 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:30 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:30 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:30 volumio volumio[15460]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 22 14:00:31 volumio volumio[15460]: info: Updating MyVolumio device info Dec 22 14:00:31 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:31 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:31 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:31 volumio volumio[15460]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 22 14:00:32 volumio volumio[15460]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:32 volumio volumio[15460]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 22 14:00:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:33 volumio go-librespot[15797]: go-librespot daemon starting... Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=debug msg="app state loaded" Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=info msg="zeroconf server listening on port 34425" Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=debug msg="obtained new client token: AAD2W3bmETliux4bcXq266nEI1o9NXNyQDQ+W2y6XZPope1jSp0d8vlAyyPf08vGkLDjuuIl+pmAdugMmutei9YD7JBpA9Bq8MAHs+INpSUZ7hiI8zXfb0ESsOMPPSTH0auz6XaNgd692rTwcafxq5MUIT4yWZGD7UEusdBxPzsvRctMHKRKoQDdlpIfTE9C1GXMuQ6m9Opt/Or+geEOloDuNUXWH2GpedMa/F4qqkO3yVL7mfkY0gSUMQ==" Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=debug msg="completed challenge" Dec 22 14:00:33 volumio go-librespot[15798]: time="2025-12-22T14:00:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:34 volumio volumio[15460]: info: MYVOLUMIO: Adding device Dec 22 14:00:34 volumio volumio[15460]: info: MYVOLUMIO: Evaluating Server Dec 22 14:00:35 volumio volumio[15460]: info: Setting Geolocation for MyVolumio to eu6 Dec 22 14:00:35 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:35 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:35 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:35 volumio volumio[15460]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:35 volumio volumio[15460]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:35 volumio ntpd[1182]: PROTO: 172.104.134.72 unlink local addr 10.3.0.14 -> Dec 22 14:00:35 volumio volumio[15460]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 22 14:00:36 volumio volumio[15460]: info: Updating MyVolumio device info Dec 22 14:00:36 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:36 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:36 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 22 14:00:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:36 volumio go-librespot[15825]: go-librespot daemon starting... Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+01:00" level=debug msg="app state loaded" Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+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]" Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+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]" Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+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]" Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+01:00" level=info msg="zeroconf server listening on port 36801" Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+01:00" level=debug msg="obtained new client token: AACK2mvOF7v9hX2SssMtfCyhewTYZy898vDxlTDeeOURHGDub2konAluZBSe7o390Hk6LtZAow3AYn78lyode6+QRotgWlWqgWzVvAy79YucyuS9v9AVjlCVgD//Kmubc2PTiJAtTCg0+RughilT2og4LG7N7187vqapjwn5jefT/PgdZ28fV+DHqdHG0c6n0ZkKw8zx/nPJuD3PG7AQZIdk63LYLjUpCXhzmPOTmeue4MZ//jBrhZhxWA==" Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+01:00" level=debug msg="completed challenge" Dec 22 14:00:36 volumio go-librespot[15826]: time="2025-12-22T14:00:36+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:37 volumio volumio[15460]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 22 14:00:38 volumio volumio[15460]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:38 volumio volumio[15460]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 22 14:00:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:40 volumio go-librespot[15847]: go-librespot daemon starting... Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=debug msg="app state loaded" Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=info msg="zeroconf server listening on port 42793" Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=debug msg="obtained new client token: AADxnY4uYvEMpm1nvMceVc5UiGu8iQUHps8JFzrWG7O4PUlf7H5s618pfTmp5KAkdKSnbun+fpW3A7sBqlXXc6Ca2lGJzR9lAh0aFkckpWokmaQHH1CZpzEM36ELAp4Elk525d03MwuH140jJvE6v8/klFPtyReBByt1Q31hY8d7T+WWynAGIreAkHs+w4DEKjWGNUzzq7PHSDBtDOZ/jWt+ubQ95Q5IbGuVIKAcoZQAPckHlhK2hcE=" Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=debug msg="completed challenge" Dec 22 14:00:40 volumio go-librespot[15848]: time="2025-12-22T14:00:40+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:41 volumio volumio[15460]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:41 volumio volumio[15460]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 22 14:00:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:43 volumio go-librespot[15855]: go-librespot daemon starting... Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+01:00" level=debug msg="app state loaded" Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+01:00" level=info msg="zeroconf server listening on port 43537" Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+01:00" level=debug msg="obtained new client token: AADDqmX3d9dxLL7AxqovxZJTZgMr0UX7TCKYsyzdZac/iTgi7zAUBdzIouvrNvsSUd8h6Z9tSfa1dsjYMsn51lpRiKlHr6glBbtvIAM2/TH35jusv2aDeayD9mb6P29mxzPlyb0EOUbySLn5PJJTWKCel1BMVre5KYgw03EjWnz6pk3vSDAc2zWaSlojpwfDetD66zlXYFkjIXSuiVSQttaGJR6ILttb8N2pXzlayUxWqd6+38dNR/tqag==" Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+01:00" level=debug msg="completed challenge" Dec 22 14:00:43 volumio go-librespot[15856]: time="2025-12-22T14:00:43+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:43 volumio ntpd[1182]: PROTO: 116.203.96.227 unlink local addr 10.3.0.14 -> Dec 22 14:00:44 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 22 14:00:44 volumio volumio[15460]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Dec 22 14:00:44 volumio volumio[15460]: info: CoreCommandRouter::volumioGetState Dec 22 14:00:44 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:44 volumio volumio[15460]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:44 volumio volumio[15460]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Dec 22 14:00:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:46 volumio go-librespot[15866]: go-librespot daemon starting... Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+01:00" level=debug msg="app state loaded" Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+01:00" level=info msg="zeroconf server listening on port 32993" Dec 22 14:00:46 volumio ntpd[1182]: PROTO: 185.249.199.104 unlink local addr 10.3.0.14 -> Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+01:00" level=debug msg="obtained new client token: AABI9M1OzQZA4oI+r+xq5WtFx7PVIMpT7tWHaWl+qdhKwQLEv/+fOZzyKbeGtIpk0zBM4Dpq8y3V0EJSFF5JvIAejjB8QDx9um31IGJmcGf7HssaxfMkd3GuWG5KdDLpV0/AqN1RB8XNikpzBU83nsGJJgn2BogNSzyf6IWMSrW1DKBGc6dnDM36PnwguyL2ANmfAQOfagj/i4scyRJ22gll18DZboLWcjRUI2Zfo8gy2SHg6oFlkxcldg==" Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+01:00" level=debug msg="completed keyexchange" Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+01:00" level=debug msg="completed challenge" Dec 22 14:00:46 volumio go-librespot[15867]: time="2025-12-22T14:00:46+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:00:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:00:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:00:47 volumio volumio[15460]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:47 volumio volumio[15460]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:00:47 volumio ntpd[1182]: PROTO: 78.46.162.102 unlink local addr 10.3.0.14 -> Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::volumioGetBrowseSources Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 22 14:00:49 volumio volumio[15460]: error: MyVolumio Plugin failed to authenticate in a timely fashion Dec 22 14:00:49 volumio volumio[15460]: info: Completed starting MyVolumio Plugin Dec 22 14:00:49 volumio volumio[15460]: [Metrics] CommandRouter: 32s 47.52ms Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::volumiosetStartupVolume Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::Close All Modals sent Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::Close All Modals sent Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 22 14:00:49 volumio volumio-remote-updater[994]: Test mode disabled Dec 22 14:00:49 volumio volumio-remote-updater[994]: Alpha mode disabled Dec 22 14:00:49 volumio volumio-remote-updater[994]: Alpha legacy test mode disabled Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 22 14:00:49 volumio volumio[15460]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Dec 22 14:00:49 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 22 14:00:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Dec 22 14:00:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:00:49 volumio go-librespot[15896]: go-librespot daemon starting... Dec 22 14:00:49 volumio go-librespot[15897]: time="2025-12-22T14:00:49+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:00:49 volumio go-librespot[15897]: time="2025-12-22T14:00:49+01:00" level=debug msg="app state loaded" Dec 22 14:00:49 volumio go-librespot[15897]: time="2025-12-22T14:00:49+01:00" level=debug msg="stored credentials not found" Dec 22 14:00:49 volumio go-librespot[15897]: time="2025-12-22T14:00:49+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:00:49 volumio go-librespot[15897]: time="2025-12-22T14:00:49+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:00:49 volumio go-librespot[15897]: time="2025-12-22T14:00:49+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:00:49 volumio go-librespot[15897]: time="2025-12-22T14:00:49+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:00:49 volumio go-librespot[15897]: time="2025-12-22T14:00:49+01:00" level=info msg="zeroconf server listening on port 43703" Dec 22 14:00:49 volumio go-librespot[15897]: time="2025-12-22T14:00:49+01:00" level=debug msg="obtained new client token: AACpFcDMdjHcc6nneMxNk488DO6fDUu34Zqvn2k5JCY5RJiM5xS3ToLVF1tfjMWnp7G7w2sZCgTJWXV0PBYRrk/mqZePckgE2n9CprKJEHHYZioA67X77hPKli2WJpoX0H5b862waxisXBZVhuJll3IGmTOVTDkrQ0zsMMDSutsrrmilel3n59rdAdSLcyVh9XxHjfecjZ9QBxyM0knnTrERhNswHoOQIIhVJqTSeWeGHBZlKTMHIPYidw==" Dec 22 14:00:49 volumio go-librespot[15897]: time="2025-12-22T14:00:49+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:00:50 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 22 14:00:50 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 22 14:00:50 volumio volumio[15460]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 22 14:00:50 volumio volumio[15460]: info: Initializing connection to go-librespot Websocket Dec 22 14:00:50 volumio go-librespot[15897]: time="2025-12-22T14:00:50+01:00" level=debug msg="new websocket client" Dec 22 14:00:50 volumio volumio[15460]: info: Connection to go-librespot Websocket established Dec 22 14:00:53 volumio volumio[15460]: info: Getting Spotify volume Dec 22 14:00:53 volumio volumio[15460]: 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 22 14:00:53 volumio volumio[15460]: info: CoreCommandRouter::volumioGetState Dec 22 14:00:53 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:53 volumio volumio[15460]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Dec 22 14:00:53 volumio volumio[15460]: SPOTIFY: SPOTIFY VOLUME undefined Dec 22 14:00:53 volumio volumio[15460]: SPOTIFY: VOLUMIO VOLUME 100 Dec 22 14:00:53 volumio volumio[15460]: info: Aligning Spotify Volume to Volumio Volume Dec 22 14:00:53 volumio volumio[15460]: info: CoreCommandRouter::volumioGetState Dec 22 14:00:53 volumio volumio[15460]: info: CorePlayQueue::getTrack 0 Dec 22 14:00:53 volumio volumio[15460]: info: Setting Spotify Volume from Volumio: 100 Dec 22 14:00:54 volumio volumio[15460]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Dec 22 14:00:54 volumio volumio[15460]: info: Sending Spotify command with payload to local API: /player/volume Dec 22 14:00:54 volumio volumio[15460]: error: Failed to send command to Spotify local API: /player/volume: Error: Bad Request Dec 22 14:00:56 volumio volumio[15460]: info: BOOT COMPLETED Dec 22 14:01:00 volumio go-librespot[15897]: time="2025-12-22T14:01:00+01:00" level=debug msg="completed keyexchange" Dec 22 14:01:00 volumio go-librespot[15897]: time="2025-12-22T14:01:00+01:00" level=debug msg="completed challenge" Dec 22 14:01:00 volumio go-librespot[15897]: time="2025-12-22T14:01:00+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:01:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:01:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:01:00 volumio volumio[15460]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 22 14:01:00 volumio volumio[15460]: Error: socket hang up Dec 22 14:01:00 volumio volumio[15460]: at connResetException (node:internal/errors:720:14) Dec 22 14:01:00 volumio volumio[15460]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 22 14:01:00 volumio volumio[15460]: at Socket.emit (node:events:526:35) Dec 22 14:01:00 volumio volumio[15460]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 22 14:01:00 volumio volumio[15460]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 22 14:01:00 volumio volumio[15460]: code: 'ECONNRESET', Dec 22 14:01:00 volumio volumio[15460]: response: undefined Dec 22 14:01:00 volumio volumio[15460]: } Dec 22 14:01:00 volumio volumio[15460]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 22 14:01:01 volumio sudo[15932]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-22 14:00' Dec 22 14:01:01 volumio sudo[15932]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:01 volumio sudo[15932]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:01 volumio volumio-remote-updater[994]: [2025-12-22 14:01:01] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 22 14:01:01 volumio volumio-remote-updater[994]: [2025-12-22 14:01:01] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 22 14:01:01 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:01:01 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 22 14:01:01 volumio systemd[1]: volumio.service: Consumed 9.492s CPU time. Dec 22 14:01:01 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 22 14:01:01 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 22 14:01:01 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 26. Dec 22 14:01:01 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 22 14:01:01 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 22 14:01:01 volumio systemd[1]: volumio.service: Consumed 9.492s CPU time. Dec 22 14:01:01 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 22 14:01:01 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 22 14:01:02 volumio volumio[15947]: info: ------------------------------------------- Dec 22 14:01:02 volumio volumio[15947]: info: ----- Volumio3 ---- Dec 22 14:01:02 volumio volumio[15947]: info: ------------------------------------------- Dec 22 14:01:02 volumio volumio[15947]: info: ----- System startup ---- Dec 22 14:01:02 volumio volumio[15947]: info: ------------------------------------------- Dec 22 14:01:02 volumio volumio[15947]: info: MYVOLUMIO Environment detected Dec 22 14:01:02 volumio volumio[15947]: info: Plugin folders cleanup Dec 22 14:01:02 volumio volumio[15947]: info: Scanning into folder /volumio/app/plugins/ Dec 22 14:01:02 volumio volumio[15947]: info: Scanning category audio_interface Dec 22 14:01:02 volumio volumio[15947]: info: Scanning category miscellanea Dec 22 14:01:02 volumio volumio[15947]: info: Scanning category music_service Dec 22 14:01:02 volumio volumio[15947]: info: Scanning category plugins.json Dec 22 14:01:02 volumio volumio[15947]: info: Scanning category system_controller Dec 22 14:01:02 volumio volumio[15947]: info: Scanning category user_interface Dec 22 14:01:02 volumio volumio[15947]: info: Scanning into folder /data/plugins/ Dec 22 14:01:02 volumio volumio[15947]: info: Scanning category music_service Dec 22 14:01:02 volumio volumio[15947]: info: Plugin folders cleanup completed Dec 22 14:01:02 volumio volumio[15947]: info: ------------------------------------------- Dec 22 14:01:02 volumio volumio[15947]: info: ----- Core plugins startup ---- Dec 22 14:01:02 volumio volumio[15947]: info: ------------------------------------------- Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugins from folder /volumio/app/plugins/ Dec 22 14:01:02 volumio volumio[15947]: info: Adding plugin upnp to MyMusic Plugins Dec 22 14:01:02 volumio volumio[15947]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 22 14:01:02 volumio volumio[15947]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugins from folder /data/plugins/ Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugin "system"... Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugin "appearance"... Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugin "network"... Dec 22 14:01:02 volumio volumio[15947]: info: Refreshing Cached IP Addresses Dec 22 14:01:02 volumio sudo[15975]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 22 14:01:02 volumio sudo[15975]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:02 volumio sudo[15977]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 22 14:01:02 volumio sudo[15975]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:02 volumio sudo[15977]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:02 volumio sudo[15977]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugin "services"... Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugin "alsa_controller"... Dec 22 14:01:02 volumio sudo[15986]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 22 14:01:02 volumio sudo[15986]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:02 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugin "wizard"... Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugin "networkfs"... Dec 22 14:01:02 volumio volumio[15947]: info: Starting Udev Watcher for removable devices Dec 22 14:01:02 volumio volumio[15947]: info: Ignoring mount for partition: boot Dec 22 14:01:02 volumio volumio[15947]: info: Ignoring mount for partition: volumio Dec 22 14:01:02 volumio volumio[15947]: info: Ignoring mount for partition: volumio_data Dec 22 14:01:02 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugin "volumio_command_line_client"... Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugin "upnp"... Dec 22 14:01:02 volumio volumio[15947]: info: [1766408462667] Starting Upmpd Daemon Dec 22 14:01:02 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugin "my_music"... Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugin "mpd"... Dec 22 14:01:02 volumio volumio[15947]: info: Loading plugin "upnp_browser"... Dec 22 14:01:03 volumio volumio[15947]: info: Starting UPNP Browser Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "alarm-clock"... Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "airplay_emulation"... Dec 22 14:01:03 volumio volumio[15947]: info: Starting Shairport Sync Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "last_100"... Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "webradio"... Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "i2s_dacs"... Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "volumiodiscovery"... Dec 22 14:01:03 volumio volumio[15947]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 22 14:01:03 volumio volumio[15947]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 22 14:01:03 volumio volumio[15947]: *** WARNING *** For more information see Dec 22 14:01:03 volumio volumio[15947]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 22 14:01:03 volumio volumio[15947]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 22 14:01:03 volumio volumio[15947]: *** WARNING *** For more information see Dec 22 14:01:03 volumio node[15947]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 22 14:01:03 volumio node[15947]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 22 14:01:03 volumio node[15947]: *** WARNING *** For more information see Dec 22 14:01:03 volumio node[15947]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 22 14:01:03 volumio node[15947]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 22 14:01:03 volumio node[15947]: *** WARNING *** For more information see Dec 22 14:01:03 volumio volumio[15947]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 22 14:01:03 volumio volumio[15947]: info: Discovery: Started advertising with name: Volumio Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "spop"... Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "ytmusic"... Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "outputs"... Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "albumart"... Dec 22 14:01:03 volumio volumio[15947]: info: Plugin example_plugin is not enabled Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "inputs"... Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "updater_comm"... Dec 22 14:01:03 volumio volumio[15947]: info: Plugin mpdemulation is not enabled Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "rest_api"... Dec 22 14:01:03 volumio volumio[15947]: info: Loading plugin "websocket"... Dec 22 14:01:03 volumio volumio[15947]: info: Starting Socket.io Server version 1.7.4 Dec 22 14:01:03 volumio volumio[15947]: info: Loading i18n strings for locale de Dec 22 14:01:03 volumio volumio[15947]: Updating browse sources language Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::initPlayerControls Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 22 14:01:03 volumio volumio[15947]: Express server listening on port 3000 Dec 22 14:01:03 volumio volumio[15947]: [Metrics] WebUI: 1s 956.10ms Dec 22 14:01:03 volumio volumio[15947]: info: CoreStateMachine::resetVolumioState Dec 22 14:01:03 volumio volumio[15947]: info: CoreStateMachine::getcurrentVolume Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::volumioRetrievevolume Dec 22 14:01:03 volumio volumio[15947]: info: Volumio Network Manager: Network status updated: 1 Dec 22 14:01:03 volumio volumio[15947]: verbose: New Socket.io Connection to 10.3.0.14 from 10.3.0.12 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Dec 22 14:01:03 volumio volumio[15947]: info: CoreStateMachine::pushState Dec 22 14:01:03 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::volumioPushState Dec 22 14:01:03 volumio volumio[15947]: info: CoreStateMachine::updateTrackBlock Dec 22 14:01:03 volumio volumio[15947]: info: CorePlayQueue::getTrackBlock Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::volumioRetrievevolume Dec 22 14:01:03 volumio volumio[16011]: Forking 3 albumart workers Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:03 volumio volumio[15947]: info: Executing start script for DAC Volumio Zero ES9039 DAC Dec 22 14:01:03 volumio volumio[15947]: info: Reloading queue from file Dec 22 14:01:03 volumio volumio[15947]: info: CoreStateMachine::pushState Dec 22 14:01:03 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::volumioPushState Dec 22 14:01:03 volumio volumio[15947]: info: CoreStateMachine::setRepeat null single undefined Dec 22 14:01:03 volumio volumio[15947]: info: CoreStateMachine::pushState Dec 22 14:01:03 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::volumioPushState Dec 22 14:01:03 volumio volumio[15947]: info: CoreStateMachine::setRandom null Dec 22 14:01:03 volumio volumio[15947]: info: CoreStateMachine::pushState Dec 22 14:01:03 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:03 volumio volumio[15947]: info: CoreCommandRouter::volumioPushState Dec 22 14:01:03 volumio volumio[15947]: info: Setting Device type: Raspberry PI Dec 22 14:01:03 volumio volumio[15947]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 22 14:01:03 volumio volumio[15947]: info: USB Boot Capable - System SBC Revision found in cpuinfo: d04171 Dec 22 14:01:03 volumio volumio[15947]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 22 14:01:03 volumio sudo[16046]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cset -y 1 0x48 0x00 0x02 Dec 22 14:01:03 volumio sudo[16046]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:03 volumio sudo[16046]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:03 volumio volumio[15947]: info: DAC script executed Dec 22 14:01:03 volumio volumio[15947]: info: Completed loading Core Plugins Dec 22 14:01:03 volumio volumio[15947]: info: Preparing to generate the ALSA configuration file Dec 22 14:01:03 volumio volumio[15947]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Dec 22 14:01:03 volumio volumio[15947]: info: Reading ALSA contributions from plugins. Dec 22 14:01:03 volumio volumio[15947]: info: Asound.conf file unchanged, so no further update is needed Dec 22 14:01:03 volumio volumio[15947]: info: Output device has changed, restarting MPD Dec 22 14:01:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Dec 22 14:01:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:04 volumio volumio[15947]: info: Output device has changed, restarting Shairport Sync Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:04 volumio sudo[16082]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 22 14:01:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:04 volumio volumio[15947]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 22 14:01:04 volumio sudo[16082]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:04 volumio volumio[15947]: info: ___________ START PLUGINS ___________ Dec 22 14:01:04 volumio go-librespot[16080]: go-librespot daemon starting... Dec 22 14:01:04 volumio sudo[16081]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 22 14:01:04 volumio sudo[16081]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:04 volumio volumio[15947]: info: ControllerMpd::onStart: Initializing MPD Dec 22 14:01:04 volumio volumio[15947]: info: Creating MPD Configuration file Dec 22 14:01:04 volumio sudo[16081]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:04 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 22 14:01:04 volumio go-librespot[16088]: time="2025-12-22T14:01:04+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:01:04 volumio go-librespot[16088]: time="2025-12-22T14:01:04+01:00" level=debug msg="app state loaded" Dec 22 14:01:04 volumio go-librespot[16088]: time="2025-12-22T14:01:04+01:00" level=debug msg="stored credentials not found" Dec 22 14:01:04 volumio go-librespot[16088]: time="2025-12-22T14:01:04+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:01:04 volumio sudo[16096]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 22 14:01:04 volumio sudo[16096]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:04 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 22 14:01:04 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 22 14:01:04 volumio volumio[15947]: info: [1766408464069] CoreMusicLibrary::Adding element Medienserver Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:01:04 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 22 14:01:04 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 22 14:01:04 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 22 14:01:04 volumio sudo[16096]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:04 volumio volumio[15947]: info: UPNP Browser: Client initialized successfully Dec 22 14:01:04 volumio sudo[16099]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 22 14:01:04 volumio sudo[16099]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:04 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 22 14:01:04 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:04 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 22 14:01:04 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 22 14:01:04 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 22 14:01:04 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 22 14:01:04 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 22 14:01:04 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 22 14:01:04 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 22 14:01:04 volumio volumio[15947]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 22 14:01:04 volumio volumio[15947]: info: [1766408464181] CoreMusicLibrary::Adding element Last_100 Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 22 14:01:04 volumio volumio[15947]: info: [1766408464183] CoreMusicLibrary::Adding element Webradio Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 22 14:01:04 volumio volumio[15947]: info: Initializing BBC Radios Dec 22 14:01:04 volumio sudo[16108]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 22 14:01:04 volumio sudo[16108]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 22 14:01:04 volumio sudo[16108]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: Creating Spotify config file Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio go-librespot[16088]: time="2025-12-22T14:01:04+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:01:04 volumio go-librespot[16088]: time="2025-12-22T14:01:04+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:01:04 volumio go-librespot[16088]: time="2025-12-22T14:01:04+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:01:04 volumio go-librespot[16088]: time="2025-12-22T14:01:04+01:00" level=info msg="zeroconf server listening on port 37153" Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 22 14:01:04 volumio volumio[15947]: info: [1766408464401] CoreMusicLibrary::Adding element YouTube Music Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:01:04 volumio volumio[15947]: Cannot find translation for source YouTube Music Dec 22 14:01:04 volumio volumio[15947]: info: Volumio Calling Home Dec 22 14:01:04 volumio go-librespot[16088]: time="2025-12-22T14:01:04+01:00" level=debug msg="obtained new client token: AABud/K7liumiPLTLdGKeYzhyZqBmJwUajrXz2ulYr8HAvXpO+7nDMb/71f1BTx//Nx8dxbiU8+Ks9oox6CwfCiUzcRpgmB8B/WyNlqV8efMr5sASzKhHhWwIUxqz+ObMAoz0If7Q23SWYy/FbGqy+SfJ8+MrzSXplJP/p5WxqFcEXxAArfGC3p7bFHtgsVMzGj2uhLkqeyzV5Sw/viAv+K6ZHPgX53CUrIHjMajwuIJSssE+zFp44oBCg==" Dec 22 14:01:04 volumio go-librespot[16088]: time="2025-12-22T14:01:04+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:01:04 volumio volumio[16043]: Starting albumart workers Dec 22 14:01:04 volumio volumio[16041]: Starting albumart workers Dec 22 14:01:04 volumio volumio[15947]: info: MPD Permissions set Dec 22 14:01:04 volumio volumio[15947]: info: MPD Permissions set Dec 22 14:01:04 volumio volumio[15947]: info: Spotify config file written Dec 22 14:01:04 volumio volumio[15947]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 22 14:01:04 volumio sudo[16134]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 22 14:01:04 volumio sudo[16134]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 22 14:01:04 volumio systemd[1]: go-librespot-daemon.service: Killing process 16106 (go-librespot) with signal SIGKILL. Dec 22 14:01:04 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 22 14:01:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 22 14:01:04 volumio volumio[15947]: info: No need to fix Spotify hosts Dec 22 14:01:04 volumio volumio[15947]: info: Volumio called home Dec 22 14:01:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:04 volumio sudo[16134]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:04 volumio go-librespot[16147]: go-librespot daemon starting... Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=debug msg="app state loaded" Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=debug msg="stored credentials not found" Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:01:04 volumio volumio[15947]: info: Discovery: adding 11b27728-79cb-4bae-acc4-888bcd85248c Dec 22 14:01:04 volumio volumio[15947]: info: Discovery: Found device Volumio Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::volumioGetState Dec 22 14:01:04 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:04 volumio volumio[15947]: info: Starting Shairport Sync Dec 22 14:01:04 volumio volumio[15947]: info: Starting Shairport Sync Dec 22 14:01:04 volumio volumio[15947]: info: Starting Shairport Sync Dec 22 14:01:04 volumio volumio[15947]: info: Discovery: this is already registered, 11b27728-79cb-4bae-acc4-888bcd85248c Dec 22 14:01:04 volumio volumio[15947]: info: Discovery: Found device Volumio Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::volumioGetState Dec 22 14:01:04 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:04 volumio sudo[16159]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 22 14:01:04 volumio sudo[16157]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 22 14:01:04 volumio sudo[16157]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:04 volumio sudo[16159]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:04 volumio sudo[16155]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::volumioGetState Dec 22 14:01:04 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:04 volumio sudo[16155]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:04 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 22 14:01:04 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 22 14:01:04 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 22 14:01:04 volumio systemd[1]: shairport-sync.service: Consumed 1.493s CPU time. Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=info msg="zeroconf server listening on port 38803" Dec 22 14:01:04 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 22 14:01:04 volumio volumio[16047]: Starting albumart workers Dec 22 14:01:04 volumio volumio[15947]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 22 14:01:04 volumio volumio[15947]: SPOTIFY: BQAIl6i1ZVBLoLsdAhFzTqNNjad9oFysGtObhDN-nz9n58-4IZhGWMO_PnN6d7fwY4PvIE89io-b-N7uyHglau3Jvw0-nMP-vveQyA5lvrCTTXCOqWog4ncaTEAKPsNqNOIfoOMO7WZbTiw1PdjafYcWHvF_etBQdSfWC3qW2wBtB3tl0La0NBTzIPkHFkGL3Czcyim7YVWcMUduG7XURkKPDK9KwnpxfRDhaJw4WrMoc4Ph7aORYFBdBKQEyLd_xj1CBe448qCTq5dDe8kXoIo-Mu7GlNQsVZFvhuSnJogfUHx2ZSGSxHPu Dec 22 14:01:04 volumio volumio[15947]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 22 14:01:04 volumio volumio[15947]: info: New Spotify access token = BQAIl6i1ZVBLoLsdAhFzTqNNjad9oFysGtObhDN-nz9n58-4IZhGWMO_PnN6d7fwY4PvIE89io-b-N7uyHglau3Jvw0-nMP-vveQyA5lvrCTTXCOqWog4ncaTEAKPsNqNOIfoOMO7WZbTiw1PdjafYcWHvF_etBQdSfWC3qW2wBtB3tl0La0NBTzIPkHFkGL3Czcyim7YVWcMUduG7XURkKPDK9KwnpxfRDhaJw4WrMoc4Ph7aORYFBdBKQEyLd_xj1CBe448qCTq5dDe8kXoIo-Mu7GlNQsVZFvhuSnJogfUHx2ZSGSxHPu Dec 22 14:01:04 volumio volumio[15947]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 22 14:01:04 volumio sudo[16159]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=debug msg="obtained new client token: AABtz6TTgOrHQgI4VHggdo69DR4CnPCEKAGzQpsh2WnjuaMD3fpxQf7Ck1Qcd+EuVQF2ahAq+uIwzUVvrvHjUkuTVD0HEsdIb7I6CRBCaWhu1XnXItNmHxOwuCD3uwZ+b02Ncf0HikBWo9hwfwNcpb0tvpgWp+b5SNnl5TrYNFn/SKENXy+xjv/fZy8vsIE2ngIniVLHoKSsCO0vKKzhOynOOmKgDr7KTMNphvMw2myJIvmqGcQVZYXc1g==" Dec 22 14:01:04 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 22 14:01:04 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 22 14:01:04 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 22 14:01:04 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 22 14:01:04 volumio sudo[16157]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:01:04 volumio volumio[15947]: info: Shairport-Sync Started Dec 22 14:01:04 volumio sudo[16155]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:04 volumio volumio[15947]: Error adding Membership: Error: addMembership EINVAL Dec 22 14:01:04 volumio volumio[15947]: info: Shairport-Sync Started Dec 22 14:01:04 volumio volumio[15947]: info: Shairport-Sync Started Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=debug msg="completed keyexchange" Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=debug msg="completed challenge" Dec 22 14:01:04 volumio volumio[15947]: SPOTIFY: User informations: {"country":"TR","display_name":"Florian","email":"florian@goezler.de","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/3136ot245q7ef5grbzukyn2yg4tq"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/3136ot245q7ef5grbzukyn2yg4tq","id":"3136ot245q7ef5grbzukyn2yg4tq","images":[],"product":"free","type":"user","uri":"spotify:user:3136ot245q7ef5grbzukyn2yg4tq"} Dec 22 14:01:04 volumio volumio[15947]: info: Spotify Successfully logged in Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 22 14:01:04 volumio volumio[15947]: info: [1766408464914] CoreMusicLibrary::Adding element Spotify Dec 22 14:01:04 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:01:04 volumio volumio[15947]: Cannot find translation for source YouTube Music Dec 22 14:01:04 volumio volumio[15947]: Cannot find translation for source Spotify Dec 22 14:01:04 volumio go-librespot[16148]: time="2025-12-22T14:01:04+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:01:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:01:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:01:05 volumio mpd[16118]: 2025-12-22T14:01:05 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 22 14:01:05 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 22 14:01:05 volumio sudo[16099]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:05 volumio sudo[16082]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:05 volumio volumio[15947]: info: Completed starting Core Plugins Dec 22 14:01:05 volumio volumio[15947]: info: ------------------------------------------- Dec 22 14:01:05 volumio volumio[15947]: info: ----- MyVolumio plugins startup ---- Dec 22 14:01:05 volumio volumio[15947]: info: ------------------------------------------- Dec 22 14:01:05 volumio volumio[15947]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 22 14:01:05 volumio volumio[15947]: error: MPD error: The expression evaluated to a falsy value: Dec 22 14:01:05 volumio volumio[15947]: assert.ok(self.idling) Dec 22 14:01:05 volumio volumio[15947]: error: The expression evaluated to a falsy value: Dec 22 14:01:05 volumio volumio[15947]: assert.ok(self.idling) Dec 22 14:01:05 volumio volumio[15947]: error: updateQueue error: null Dec 22 14:01:05 volumio volumio[15947]: info: MPD running with PID16118 Dec 22 14:01:05 volumio volumio[15947]: ,establishing connection Dec 22 14:01:05 volumio volumio[15947]: error: updateQueue error: null Dec 22 14:01:05 volumio sudo[15986]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:06 volumio volumio[15947]: verbose: New Socket.io Connection to 10.3.0.14:3000 from 10.3.0.11 UA: Dart/3.9 (dart:io) Engine version: 3 Transport: websocket Total Clients: 3 Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 22 14:01:06 volumio volumio[15947]: info: Discovery: Getting this device information Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::volumioGetState Dec 22 14:01:06 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 22 14:01:06 volumio volumio-remote-updater[994]: [2025-12-22 14:01:06] [connect] Successful connection Dec 22 14:01:06 volumio volumio-remote-updater[994]: [2025-12-22 14:01:06] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1766408466 101 Dec 22 14:01:06 volumio volumio[15947]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 4 Dec 22 14:01:06 volumio volumio[15947]: verbose: New Socket.io Connection to 10.3.0.14 from 10.3.0.12 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::volumioGetVisibleSources Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::volumioGetState Dec 22 14:01:06 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::volumioGetState Dec 22 14:01:06 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 22 14:01:06 volumio volumio[15947]: info: Received Get System Info Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 22 14:01:06 volumio volumio[15947]: info: Discovery: Getting this device information Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::volumioGetState Dec 22 14:01:06 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 22 14:01:06 volumio volumio[15947]: info: CoreCommandRouter::volumioGetState Dec 22 14:01:06 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:06 volumio volumio[15947]: info: Listing playlists Dec 22 14:01:07 volumio volumio[15947]: info: go-librespot daemon successfully initialized Dec 22 14:01:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 22 14:01:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:08 volumio go-librespot[16219]: go-librespot daemon starting... Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+01:00" level=debug msg="app state loaded" Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+01:00" level=debug msg="stored credentials not found" Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+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-gae2.spotify.com:80]" Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+01:00" level=info msg="zeroconf server listening on port 45611" Dec 22 14:01:08 volumio sudo[16229]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 22 14:01:08 volumio sudo[16229]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:08 volumio sudo[16231]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 22 14:01:08 volumio sudo[16231]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+01:00" level=debug msg="obtained new client token: AACjSf1LtREfEqk8AY4ZJ3Y0jfTb8sVAFwyWPbbaYWJGYNuyFhrz6cI8tzU8rX3DdYlP/Kd6yKo0LFHdE3ryJQKynedu6JwdW2c5MLQ5Pg5VETklu6WdI92sRfv35rrgRwJKEM/CyBhS+NiwLgcXiNxqUPTAY9q+VoUjuxFMPDrzKRe0lsTf0Cd4bA5sS6H3DIVdKjzrYVo8KOBK6tYm15/uj9XlBrZoQzjD04Mm4djRxsCq1CU51fc=" Dec 22 14:01:08 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 22 14:01:08 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 22 14:01:08 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+01:00" level=debug msg="completed keyexchange" Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+01:00" level=debug msg="completed challenge" Dec 22 14:01:08 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 22 14:01:08 volumio sudo[16231]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:08 volumio sudo[16229]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:08 volumio mpd_monitor.sh[16234]: MPD Monitor Service: Starting MPD Monitor Service Dec 22 14:01:08 volumio volumio[15947]: info: Successfully started MPD Monitor Dec 22 14:01:08 volumio volumio[15947]: info: Successfully started MPD Monitor Dec 22 14:01:08 volumio go-librespot[16220]: time="2025-12-22T14:01:08+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:01:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:01:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:01:10 volumio volumio[15947]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 22 14:01:10 volumio volumio[15947]: info: Initializing connection to go-librespot Websocket Dec 22 14:01:10 volumio volumio[15947]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:01:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 22 14:01:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:11 volumio go-librespot[16238]: go-librespot daemon starting... Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=debug msg="app state loaded" Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=debug msg="stored credentials not found" Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=info msg="zeroconf server listening on port 35403" Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=debug msg="obtained new client token: AADJrvp3kI2g5uaUuIpq553X2DUoBWYxlezp0rMTDt5tVu3867FFPFn6OdcJX3MO1B61bmruA0jzo+1+sAn1WzRZP5EumP0V93hHSRdOgl53hTnkMc91a7LCWzX0UcIT8PdW+sWHzdLQggE0dkEyTPAN3tSZ+4kd0JvxN4tLwzFJrcf+j9HeSiU6XcOVvdIrX7gihCMwdunnZ3yxSFHMJyPJzy6HiOfNB2TXHqcuqBP+TiPGZJL8JS7OMQ==" Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=debug msg="completed keyexchange" Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=debug msg="completed challenge" Dec 22 14:01:11 volumio go-librespot[16239]: time="2025-12-22T14:01:11+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:01:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:01:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:01:12 volumio sudo[16261]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 22 14:01:12 volumio sudo[16261]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:12 volumio sudo[16263]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 22 14:01:12 volumio sudo[16261]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:12 volumio sudo[16263]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:12 volumio sudo[16263]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:12 volumio sudo[16267]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 22 14:01:12 volumio sudo[16267]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:12 volumio sudo[16267]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:12 volumio volumio[15947]: info: Upmpdcli Daemon Started Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 22 14:01:13 volumio volumio[15947]: info: Adding plugin bluetooth to MyMusic Plugins Dec 22 14:01:13 volumio volumio[15947]: info: Adding plugin multiroom to MyMusic Plugins Dec 22 14:01:13 volumio volumio[15947]: info: Adding plugin metavolumio to MyMusic Plugins Dec 22 14:01:13 volumio volumio[15947]: info: Adding plugin cd_controller to MyMusic Plugins Dec 22 14:01:13 volumio volumio[15947]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 22 14:01:13 volumio volumio[15947]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 22 14:01:13 volumio volumio[15947]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 22 14:01:13 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:13 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:13 volumio volumio[15947]: info: Starting MyVolumio Remote Streaming Endpoints Dec 22 14:01:13 volumio volumio[15947]: info: MyVolumio login type: Token Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 22 14:01:13 volumio volumio[15947]: info: Streaming services startup Dec 22 14:01:13 volumio volumio[15947]: info: Starting Streaming Daemon Dec 22 14:01:13 volumio sudo[16270]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 22 14:01:13 volumio sudo[16270]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:13 volumio volumio[15947]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 22 14:01:13 volumio sudo[16270]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:13 volumio volumio[15947]: info: Initializing connection to go-librespot Websocket Dec 22 14:01:13 volumio volumio[15947]: error: Cannot start Volumio Streaming Daemon Dec 22 14:01:13 volumio volumio[15947]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 22 14:01:13 volumio volumio[15947]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 22 14:01:13 volumio volumio[15947]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:01:14 volumio volumio[15947]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 22 14:01:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 22 14:01:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:14 volumio go-librespot[16276]: go-librespot daemon starting... Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=debug msg="app state loaded" Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=debug msg="stored credentials not found" Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=info msg="zeroconf server listening on port 45109" Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=debug msg="obtained new client token: AAAyhJ1AKy24IDZrhTgRqRaWsPJ9OxE2PX/3/qGsiZcyAn8WHIcfcOUA2Y3OAMXacildrKyOLmaXL7bL634sqmzuNQ1y/SLsI9cX6a39E5UA9Ou0hBhJBDTedmyTTWxXqMH/Xgj7qwINXUky6f00U87q/mim8TzVKg+vfM8TTN/sqNbUtDhxXdW9NCzEhBlCOxezWRoaea+QvQP0+2Hefx3/r5PRt4WMzwL+plVn0Ki8LGduKCVB7kIFFw==" Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=debug msg="completed keyexchange" Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=debug msg="completed challenge" Dec 22 14:01:14 volumio go-librespot[16277]: time="2025-12-22T14:01:14+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:01:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:01:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:01:15 volumio volumio[15947]: info: MyVolumio token set successfully Dec 22 14:01:15 volumio volumio[15947]: info: MYVOLUMIO: Adding device Dec 22 14:01:15 volumio volumio[15947]: info: MYVOLUMIO: Evaluating Server Dec 22 14:01:15 volumio volumio[15947]: info: MyVolumio status changed Dec 22 14:01:15 volumio volumio[15947]: info: Streaming services startup Dec 22 14:01:15 volumio volumio[15947]: info: Starting Streaming Daemon Dec 22 14:01:15 volumio volumio[15947]: info: Removing browser output: myVolumio user plan is not superstar Dec 22 14:01:15 volumio volumio[15947]: info: Removing audio output: Dec 22 14:01:15 volumio volumio[15947]: info: Stoppping Tunnel 1 Dec 22 14:01:15 volumio sudo[16305]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 22 14:01:15 volumio sudo[16305]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:15 volumio sudo[16307]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 22 14:01:15 volumio sudo[16307]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:15 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:01:15 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:01:15 volumio sudo[16305]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:15 volumio volumio[15947]: error: Cannot start Volumio Streaming Daemon Dec 22 14:01:15 volumio volumio[15947]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 22 14:01:15 volumio volumio[15947]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 22 14:01:15 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:01:15 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:01:15 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:01:15 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 22 14:01:15 volumio sudo[16307]: pam_unix(sudo:session): session closed for user root Dec 22 14:01:15 volumio volumio[15947]: info: Remote SSH Stopped Dec 22 14:01:16 volumio volumio[15947]: info: Setting Geolocation for MyVolumio to eu4 Dec 22 14:01:16 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:16 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:16 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:16 volumio volumio[15947]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 22 14:01:16 volumio volumio[15947]: info: Initializing connection to go-librespot Websocket Dec 22 14:01:16 volumio volumio[15947]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:01:17 volumio volumio[15947]: info: Updating MyVolumio device info Dec 22 14:01:17 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:17 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:17 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:17 volumio volumio[15947]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 22 14:01:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 22 14:01:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:17 volumio go-librespot[16311]: go-librespot daemon starting... Dec 22 14:01:17 volumio go-librespot[16312]: time="2025-12-22T14:01:17+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:01:17 volumio go-librespot[16312]: time="2025-12-22T14:01:17+01:00" level=debug msg="app state loaded" Dec 22 14:01:17 volumio go-librespot[16312]: time="2025-12-22T14:01:17+01:00" level=debug msg="stored credentials not found" Dec 22 14:01:17 volumio go-librespot[16312]: time="2025-12-22T14:01:17+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:01:17 volumio go-librespot[16312]: time="2025-12-22T14:01:17+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-gae2.spotify.com:80]" Dec 22 14:01:17 volumio go-librespot[16312]: time="2025-12-22T14:01:17+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:01:17 volumio go-librespot[16312]: time="2025-12-22T14:01:17+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:01:17 volumio go-librespot[16312]: time="2025-12-22T14:01:17+01:00" level=info msg="zeroconf server listening on port 42585" Dec 22 14:01:17 volumio go-librespot[16312]: time="2025-12-22T14:01:17+01:00" level=debug msg="obtained new client token: AADWInyi4VAhay+JrMtIt6M0aYAu4l2SXWI8iuyjh4yt3T+N3Tk/1QMGeObI5T3AstblPXRFJnfBektmajww96SRLxzkukSmIOb4Gk2zdULnjsEW62GeEwW+qkqbEN99CsQAgAafbeMCUtYe9kgIEcLNfNenS1xSYtwdyfh9MC3GtR/sc7DtFIkSSrnbD+/HeivwcX/1zfDvBxhCvash0rsnP0B6qjGbnBlWllnZpJU695cgmMtfp8rboA==" Dec 22 14:01:17 volumio go-librespot[16312]: time="2025-12-22T14:01:17+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:01:19 volumio go-librespot[16312]: time="2025-12-22T14:01:19+01:00" level=debug msg="completed keyexchange" Dec 22 14:01:19 volumio go-librespot[16312]: time="2025-12-22T14:01:19+01:00" level=debug msg="completed challenge" Dec 22 14:01:19 volumio go-librespot[16312]: time="2025-12-22T14:01:19+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:01:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:01:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:01:19 volumio volumio[15947]: info: Initializing connection to go-librespot Websocket Dec 22 14:01:19 volumio volumio[15947]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:01:20 volumio volumio[15947]: info: MYVOLUMIO: Adding device Dec 22 14:01:20 volumio volumio[15947]: info: MYVOLUMIO: Evaluating Server Dec 22 14:01:20 volumio volumio[15947]: info: Setting Geolocation for MyVolumio to eu4 Dec 22 14:01:20 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:20 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:20 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:21 volumio volumio[15947]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 22 14:01:21 volumio volumio[15947]: info: Updating MyVolumio device info Dec 22 14:01:21 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:21 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:21 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 22 14:01:22 volumio volumio[15947]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 22 14:01:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 22 14:01:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:22 volumio go-librespot[16338]: go-librespot daemon starting... Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+01:00" level=debug msg="app state loaded" Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+01:00" level=debug msg="stored credentials not found" Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+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-gae2.spotify.com:80]" Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+01:00" level=info msg="zeroconf server listening on port 34675" Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+01:00" level=debug msg="obtained new client token: AADMTs0fGzNS+wm/9LgqfQ1xedAo4Y10D9FwpF//6Q3q5XFvW29sy1a2nWvnRpAfByOwwefSatg1hKWaRE2BY+cEjBd7+PpXnrMWGwqphCLU3Q4FQqO1GayWOfJX/+LiYaHsngbHauxfWRoUKP+DwbDNoClMM1jNuECIU6mIMy/3lBc2FcdqURb2fcmbIqBQJYub/EKyNAsUqOXQ3QrjmeYyJ3SErZSI1W7M+yDdHIwVt6OuInQBpf/HdQ==" Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+01:00" level=debug msg="completed keyexchange" Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+01:00" level=debug msg="completed challenge" Dec 22 14:01:22 volumio go-librespot[16339]: time="2025-12-22T14:01:22+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:01:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:01:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:01:22 volumio volumio[15947]: info: Initializing connection to go-librespot Websocket Dec 22 14:01:22 volumio volumio[15947]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:01:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 22 14:01:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:25 volumio go-librespot[16360]: go-librespot daemon starting... Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=debug msg="app state loaded" Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=debug msg="stored credentials not found" Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=info msg="zeroconf server listening on port 38805" Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=debug msg="obtained new client token: AABkIjruW3I7lErYbORQ7/B2jLfZHjxJmcnz4/0TE3MABVNVaB0iTmqjMMUkA1hxZOx1z4kl2UOLKuzuigVWtlNkGCW/8xq6v37N7LdqoQafepdUYPB1WG/C6P6vQfqxuW1YVzHJNC/9IrasBk/y4ASEsZN71wN4OP+1CwTkvOwgnZ0e3Z5tqpnOuciNMKxxUgbDo0VK1lnyvTW9h93tbvVLBsxRwjquzSaKlc4tblVmhO7lZtWi/4qgfQ==" Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:01:25 volumio volumio[15947]: info: Initializing connection to go-librespot Websocket Dec 22 14:01:25 volumio volumio[15947]: info: Connection to go-librespot Websocket established Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=debug msg="new websocket client" Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=debug msg="completed keyexchange" Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=debug msg="completed challenge" Dec 22 14:01:25 volumio go-librespot[16361]: time="2025-12-22T14:01:25+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: TravelRestriction " Dec 22 14:01:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 22 14:01:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 22 14:01:25 volumio volumio[15947]: info: Connection to go-librespot Websocket closed Dec 22 14:01:28 volumio volumio[15947]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 22 14:01:28 volumio volumio[15947]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Dec 22 14:01:28 volumio volumio[15947]: info: CoreCommandRouter::volumioGetState Dec 22 14:01:28 volumio volumio[15947]: info: CorePlayQueue::getTrack 0 Dec 22 14:01:28 volumio volumio[15947]: info: Getting Spotify volume Dec 22 14:01:28 volumio volumio[15947]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 22 14:01:28 volumio volumio[15947]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 22 14:01:28 volumio volumio[15947]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 22 14:01:28 volumio volumio[15947]: errno: -111, Dec 22 14:01:28 volumio volumio[15947]: code: 'ECONNREFUSED', Dec 22 14:01:28 volumio volumio[15947]: syscall: 'connect', Dec 22 14:01:28 volumio volumio[15947]: address: '127.0.0.1', Dec 22 14:01:28 volumio volumio[15947]: port: 9879, Dec 22 14:01:28 volumio volumio[15947]: response: undefined Dec 22 14:01:28 volumio volumio[15947]: } Dec 22 14:01:28 volumio volumio[15947]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 22 14:01:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 22 14:01:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 22 14:01:29 volumio go-librespot[16384]: go-librespot daemon starting... Dec 22 14:01:29 volumio go-librespot[16385]: time="2025-12-22T14:01:29+01:00" level=info msg="running go-librespot 0.4.0" Dec 22 14:01:29 volumio go-librespot[16385]: time="2025-12-22T14:01:29+01:00" level=debug msg="app state loaded" Dec 22 14:01:29 volumio go-librespot[16385]: time="2025-12-22T14:01:29+01:00" level=debug msg="stored credentials not found" Dec 22 14:01:29 volumio go-librespot[16385]: time="2025-12-22T14:01:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 22 14:01:29 volumio go-librespot[16385]: time="2025-12-22T14:01:29+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 22 14:01:29 volumio go-librespot[16385]: time="2025-12-22T14:01:29+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 22 14:01:29 volumio go-librespot[16385]: time="2025-12-22T14:01:29+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 22 14:01:29 volumio go-librespot[16385]: time="2025-12-22T14:01:29+01:00" level=info msg="zeroconf server listening on port 42825" Dec 22 14:01:29 volumio go-librespot[16385]: time="2025-12-22T14:01:29+01:00" level=debug msg="obtained new client token: AADLSmTDAhgiInF1Ymq3cY2iKNZzzZWKVK3nd5jyMt50RI6t7xMMU9vJeg0ioFAh0QHEeWW5MDYbmA+61GelBFsDSSCN0o/oyIGNOAR4CT1Csygo/vTrTewo87YRFlNNGw946A+tA5wL8RZGvernKSKBLYKoBIP1rFaUC2E6HOOFYRxQbwBCLx4rNc61nkHlBakRyU8XDiwZeq2U0yXVkqs4xdnZ86oyic5wGsBEsSOQPLfzQsihr84=" Dec 22 14:01:29 volumio sudo[16394]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-22 14:00' Dec 22 14:01:29 volumio sudo[16394]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 22 14:01:29 volumio go-librespot[16385]: time="2025-12-22T14:01:29+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 22 14:01:29 volumio go-librespot[16385]: time="2025-12-22T14:01:29+01:00" level=debug msg="completed keyexchange" Dec 22 14:01:29 volumio go-librespot[16385]: time="2025-12-22T14:01:29+01:00" level=debug msg="completed challenge" 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"