Oct 26 08:23:00 volumio volumio[3541]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 26 08:23:00 volumio volumio[3541]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 26 08:23:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 531. Oct 26 08:23:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:00 volumio go-librespot[3907]: go-librespot daemon starting... Oct 26 08:23:00 volumio go-librespot[3908]: time="2025-10-26T08:23:00Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:00 volumio go-librespot[3908]: time="2025-10-26T08:23:00Z" level=debug msg="app state loaded" Oct 26 08:23:00 volumio go-librespot[3908]: time="2025-10-26T08:23:00Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:00 volumio go-librespot[3908]: time="2025-10-26T08:23:00Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:00 volumio go-librespot[3908]: time="2025-10-26T08:23:00Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:00 volumio go-librespot[3908]: time="2025-10-26T08:23:00Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:00 volumio go-librespot[3908]: time="2025-10-26T08:23:00Z" level=info msg="zeroconf server listening on port 41279" Oct 26 08:23:00 volumio go-librespot[3908]: time="2025-10-26T08:23:00Z" level=debug msg="obtained new client token: AABK1KuXVu2YJH9oEei5ekJy8eOHTXq0IjlcKKLq1vgWv1OsmO+RWH9gb8oD3ATtOVKzbmROE+o0dAhng1EVQ+j1/afNJrxk3rmVe6ekyBzpuB1fsvRybfRFdsOX1oF0+ryp+bsanjMmpLPJeNlmhMu4+RDn7yzYYQ/znOJ/r+Zzt5B2M8ZJUgAjiTua8fp6CXbm1iUNfaOs6u59zQmBcutmsmu5YZhKGcQ4vgtdTVGFG3n24or1Tck=" Oct 26 08:23:00 volumio go-librespot[3908]: time="2025-10-26T08:23:00Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:00 volumio go-librespot[3908]: time="2025-10-26T08:23:00Z" level=debug msg="completed keyexchange" Oct 26 08:23:00 volumio go-librespot[3908]: time="2025-10-26T08:23:00Z" level=debug msg="completed challenge" Oct 26 08:23:00 volumio go-librespot[3908]: time="2025-10-26T08:23:00Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:01 volumio volumio[3541]: info: Initializing connection to go-librespot Websocket Oct 26 08:23:01 volumio volumio[3541]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:23:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 532. Oct 26 08:23:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:04 volumio go-librespot[3916]: go-librespot daemon starting... Oct 26 08:23:04 volumio go-librespot[3917]: time="2025-10-26T08:23:04Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:04 volumio go-librespot[3917]: time="2025-10-26T08:23:04Z" level=debug msg="app state loaded" Oct 26 08:23:04 volumio go-librespot[3917]: time="2025-10-26T08:23:04Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:04 volumio go-librespot[3917]: time="2025-10-26T08:23:04Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 26 08:23:04 volumio go-librespot[3917]: time="2025-10-26T08:23:04Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 26 08:23:04 volumio go-librespot[3917]: time="2025-10-26T08:23:04Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 26 08:23:04 volumio go-librespot[3917]: time="2025-10-26T08:23:04Z" level=info msg="zeroconf server listening on port 33507" Oct 26 08:23:04 volumio go-librespot[3917]: time="2025-10-26T08:23:04Z" level=debug msg="obtained new client token: AACRRyFSJbtsDre3tseKXvd7d3L0RgV6VNlJr4himJPbxBSX3Z2ytejIYFB0xNoqiwYKu074Hyfdez9z8P4nTpX40gQwwSFPmOlW6I+3pWnrPD2b/WxYAHyzw65olOzbsSRnu2OE/r8oJO+PIZ8jTj8f6s/8IMeCNeOpQrMEunjheAYZiC5AvsJMrUbew76ZdiRizxPvbv/SqobBBnP1zZBwlHzsz5beMJhdUDoqM2qPwO1nSSXd8CU=" Oct 26 08:23:04 volumio go-librespot[3917]: time="2025-10-26T08:23:04Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:04 volumio go-librespot[3917]: time="2025-10-26T08:23:04Z" level=debug msg="completed keyexchange" Oct 26 08:23:04 volumio go-librespot[3917]: time="2025-10-26T08:23:04Z" level=debug msg="completed challenge" Oct 26 08:23:04 volumio go-librespot[3917]: time="2025-10-26T08:23:04Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:04 volumio volumio[3541]: info: Initializing connection to go-librespot Websocket Oct 26 08:23:04 volumio volumio[3541]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:23:07 volumio volumio[3541]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 26 08:23:07 volumio volumio[3541]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 26 08:23:07 volumio volumio[3541]: info: CoreCommandRouter::volumioGetState Oct 26 08:23:07 volumio volumio[3541]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 533. Oct 26 08:23:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:07 volumio go-librespot[3927]: go-librespot daemon starting... Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=debug msg="app state loaded" Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=info msg="zeroconf server listening on port 45721" Oct 26 08:23:07 volumio volumio[3541]: info: Initializing connection to go-librespot Websocket Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=debug msg="new websocket client" Oct 26 08:23:07 volumio volumio[3541]: info: Connection to go-librespot Websocket established Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=debug msg="obtained new client token: AAA+w038XAXyBj92alOXbKnV8NnMZLbf1jaWrF9zBsug+VKrnENQZ/lWtLf932cOwRW2UX2v2aSLBHLqW3L5t3NvXSwMWoh3yz18ZMnB95a4jywcIR2qyCSBoWlXxPb9vqmVfNlBtYt4C4HQyFRRxz/Hd6fLLmdBZrsdl6Ie3Nxd55i3xQhWfTeeRMQzO0vymnHTbIYn/QhFRNwGuyik5+X/OGIWkDCig/QGAGsB9AvbYu0tdw2rzUo=" Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=debug msg="completed keyexchange" Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=debug msg="completed challenge" Oct 26 08:23:07 volumio go-librespot[3928]: time="2025-10-26T08:23:07Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:07 volumio volumio[3541]: info: Connection to go-librespot Websocket closed Oct 26 08:23:10 volumio volumio[3541]: info: Getting Spotify volume Oct 26 08:23:10 volumio volumio[3541]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 08:23:10 volumio volumio[3541]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:23:10 volumio volumio[3541]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 26 08:23:10 volumio volumio[3541]: errno: -111, Oct 26 08:23:10 volumio volumio[3541]: code: 'ECONNREFUSED', Oct 26 08:23:10 volumio volumio[3541]: syscall: 'connect', Oct 26 08:23:10 volumio volumio[3541]: address: '127.0.0.1', Oct 26 08:23:10 volumio volumio[3541]: port: 9879, Oct 26 08:23:10 volumio volumio[3541]: response: undefined Oct 26 08:23:10 volumio volumio[3541]: } Oct 26 08:23:10 volumio volumio[3541]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 08:23:11 volumio sudo[3963]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-26 08:22' Oct 26 08:23:11 volumio sudo[3963]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:11 volumio sudo[3963]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:11 volumio volumio-remote-updater[896]: [2025-10-26 08:23:11] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 26 08:23:11 volumio volumio-remote-updater[896]: [2025-10-26 08:23:11] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 26 08:23:11 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 534. Oct 26 08:23:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:11 volumio go-librespot[3968]: go-librespot daemon starting... Oct 26 08:23:11 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 26 08:23:11 volumio systemd[1]: volumio.service: Consumed 11.401s CPU time. Oct 26 08:23:11 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 26 08:23:11 volumio go-librespot[3969]: time="2025-10-26T08:23:11Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:11 volumio go-librespot[3969]: time="2025-10-26T08:23:11Z" level=debug msg="app state loaded" Oct 26 08:23:11 volumio go-librespot[3969]: time="2025-10-26T08:23:11Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:11 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 26 08:23:11 volumio go-librespot[3969]: time="2025-10-26T08:23:11Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:11 volumio go-librespot[3969]: time="2025-10-26T08:23:11Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:11 volumio go-librespot[3969]: time="2025-10-26T08:23:11Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:11 volumio go-librespot[3969]: time="2025-10-26T08:23:11Z" level=info msg="zeroconf server listening on port 34691" Oct 26 08:23:11 volumio go-librespot[3969]: time="2025-10-26T08:23:11Z" level=debug msg="obtained new client token: AABrZZgLfsxUgTh/J0YQrX9gKP/oJPB/MBjbYwvULmJzs/eDobxLH4ZAgoJCNYK2Ke0d/mSD785scmM2EiE2FfMyajQ9NiH/WRjRoPccWTJ6M2ewLpi/TKn+CsuxnmQ5HnQgbdWWHgBul3fzg13t5aukOr4hYsKUQ+X1d3On8p6juEYyCQwzAOACLV/HjV3XqkybYeOWvIaLnmLg/x+PNzSKbonae9Nq/vpXpxT9qojTWDnvxQq8rqY=" Oct 26 08:23:11 volumio go-librespot[3969]: time="2025-10-26T08:23:11Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:11 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 6749. Oct 26 08:23:11 volumio go-librespot[3969]: time="2025-10-26T08:23:11Z" level=debug msg="completed keyexchange" Oct 26 08:23:11 volumio go-librespot[3969]: time="2025-10-26T08:23:11Z" level=debug msg="completed challenge" Oct 26 08:23:11 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 26 08:23:11 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 26 08:23:11 volumio systemd[1]: volumio.service: Consumed 11.401s CPU time. Oct 26 08:23:11 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 26 08:23:11 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 26 08:23:11 volumio go-librespot[3969]: time="2025-10-26T08:23:11Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:11 volumio volumio[3984]: info: ------------------------------------------- Oct 26 08:23:11 volumio volumio[3984]: info: ----- Volumio3 ---- Oct 26 08:23:11 volumio volumio[3984]: info: ------------------------------------------- Oct 26 08:23:11 volumio volumio[3984]: info: ----- System startup ---- Oct 26 08:23:11 volumio volumio[3984]: info: ------------------------------------------- Oct 26 08:23:12 volumio volumio[3984]: info: MYVOLUMIO Environment detected Oct 26 08:23:12 volumio volumio[3984]: info: Plugin folders cleanup Oct 26 08:23:12 volumio volumio[3984]: info: Scanning into folder /volumio/app/plugins/ Oct 26 08:23:12 volumio volumio[3984]: info: Scanning category audio_interface Oct 26 08:23:12 volumio volumio[3984]: info: Scanning category miscellanea Oct 26 08:23:12 volumio volumio[3984]: info: Scanning category music_service Oct 26 08:23:12 volumio volumio[3984]: info: Scanning category plugins.json Oct 26 08:23:12 volumio volumio[3984]: info: Scanning category system_controller Oct 26 08:23:12 volumio volumio[3984]: info: Scanning category user_interface Oct 26 08:23:12 volumio volumio[3984]: info: Scanning into folder /data/plugins/ Oct 26 08:23:12 volumio volumio[3984]: info: Scanning category music_service Oct 26 08:23:12 volumio volumio[3984]: info: Scanning category user_interface Oct 26 08:23:12 volumio volumio[3984]: info: Plugin folders cleanup completed Oct 26 08:23:12 volumio volumio[3984]: info: ------------------------------------------- Oct 26 08:23:12 volumio volumio[3984]: info: ----- Core plugins startup ---- Oct 26 08:23:12 volumio volumio[3984]: info: ------------------------------------------- Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugins from folder /volumio/app/plugins/ Oct 26 08:23:12 volumio volumio[3984]: info: Adding plugin upnp to MyMusic Plugins Oct 26 08:23:12 volumio volumio[3984]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 26 08:23:12 volumio volumio[3984]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugins from folder /data/plugins/ Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugin "system"... Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugin "appearance"... Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugin "network"... Oct 26 08:23:12 volumio volumio[3984]: info: Refreshing Cached IP Addresses Oct 26 08:23:12 volumio sudo[4012]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 08:23:12 volumio sudo[4012]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:12 volumio sudo[4014]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 08:23:12 volumio sudo[4014]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugin "services"... Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugin "alsa_controller"... Oct 26 08:23:12 volumio sudo[4014]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:12 volumio sudo[4012]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:12 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugin "wizard"... Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugin "networkfs"... Oct 26 08:23:12 volumio volumio[3984]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 26 08:23:12 volumio volumio[3984]: info: Starting Udev Watcher for removable devices Oct 26 08:23:12 volumio volumio[3984]: info: Ignoring mount for partition: boot Oct 26 08:23:12 volumio volumio[3984]: info: Ignoring mount for partition: volumio Oct 26 08:23:12 volumio volumio[3984]: info: Ignoring mount for partition: volumio_data Oct 26 08:23:12 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugin "volumio_command_line_client"... Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugin "upnp"... Oct 26 08:23:12 volumio volumio[3984]: info: [1761466992588] Starting Upmpd Daemon Oct 26 08:23:12 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugin "my_music"... Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugin "mpd"... Oct 26 08:23:12 volumio volumio[3984]: info: Loading plugin "upnp_browser"... Oct 26 08:23:13 volumio volumio[3984]: info: Loading plugin "alarm-clock"... Oct 26 08:23:13 volumio volumio[3984]: info: Loading plugin "airplay_emulation"... Oct 26 08:23:13 volumio volumio[3984]: info: Starting Shairport Sync Oct 26 08:23:13 volumio volumio[3984]: info: Loading plugin "last_100"... Oct 26 08:23:13 volumio volumio[3984]: info: Loading plugin "webradio"... Oct 26 08:23:13 volumio volumio[3984]: info: Loading plugin "i2s_dacs"... Oct 26 08:23:13 volumio volumio[3984]: info: I2S DAC not set, start Auto-detection Oct 26 08:23:13 volumio volumio[3984]: info: Loading plugin "volumiodiscovery"... Oct 26 08:23:13 volumio volumio[3984]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 08:23:13 volumio volumio[3984]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 08:23:13 volumio volumio[3984]: *** WARNING *** For more information see Oct 26 08:23:13 volumio volumio[3984]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 08:23:13 volumio volumio[3984]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 08:23:13 volumio volumio[3984]: *** WARNING *** For more information see Oct 26 08:23:13 volumio node[3984]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 08:23:13 volumio node[3984]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 08:23:13 volumio node[3984]: *** WARNING *** For more information see Oct 26 08:23:13 volumio node[3984]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 08:23:13 volumio node[3984]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 08:23:13 volumio node[3984]: *** WARNING *** For more information see Oct 26 08:23:13 volumio volumio[3984]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 26 08:23:13 volumio volumio[3984]: info: Discovery: Started advertising with name: Volumio Oct 26 08:23:13 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 08:23:13 volumio volumio[3984]: info: Loading plugin "spop"... Oct 26 08:23:13 volumio volumio[3984]: info: Loading plugin "ytcr"... Oct 26 08:23:14 volumio volumio[3984]: info: Loading plugin "outputs"... Oct 26 08:23:14 volumio volumio[3984]: info: Loading plugin "albumart"... Oct 26 08:23:14 volumio volumio[3984]: info: Plugin example_plugin is not enabled Oct 26 08:23:14 volumio volumio[3984]: info: Loading plugin "inputs"... Oct 26 08:23:14 volumio volumio[3984]: info: Loading plugin "updater_comm"... Oct 26 08:23:14 volumio volumio[3984]: info: Plugin mpdemulation is not enabled Oct 26 08:23:14 volumio volumio[3984]: info: Loading plugin "rest_api"... Oct 26 08:23:14 volumio volumio[3984]: info: Loading plugin "websocket"... Oct 26 08:23:14 volumio volumio[3984]: info: Starting Socket.io Server version 1.7.4 Oct 26 08:23:14 volumio volumio[3984]: info: Loading plugin "Systeminfo"... Oct 26 08:23:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 535. Oct 26 08:23:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:14 volumio go-librespot[4054]: go-librespot daemon starting... Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=debug msg="app state loaded" Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:14 volumio volumio[3984]: info: Loading i18n strings for locale en Oct 26 08:23:14 volumio volumio[3984]: Updating browse sources language Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:23:14 volumio volumio[4044]: Forking 3 albumart workers Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::initPlayerControls Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 08:23:14 volumio volumio[3984]: Express server listening on port 3000 Oct 26 08:23:14 volumio volumio[3984]: [Metrics] WebUI: 2s 960.21ms Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=info msg="zeroconf server listening on port 34667" Oct 26 08:23:14 volumio volumio[3984]: info: CoreStateMachine::resetVolumioState Oct 26 08:23:14 volumio volumio[3984]: info: CoreStateMachine::getcurrentVolume Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:14 volumio volumio[3984]: info: Cannot read play queue from file Oct 26 08:23:14 volumio volumio[3984]: info: Volumio Network Manager: Network status updated: 1 Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=debug msg="obtained new client token: AABMnJhCEPK/Mycm7Cit5oX32mZhlxuCABDZ79U7gFP1svZWfIVVwleZLV1FYjsUJPHvoAivqCOD3ilzMZ+UIfsscQ92lMEGEsMWakvPDd0IZoABELZR7TR8An+d22EgqK2/Hbok+pDLTSIW5nfZ6+nuqAO99KsePxUxH8iTjUrT+2/0cAaAZ4Vrdkahewy6r9Gb5oX6rVZHFSAye8CKndxXDumbbSrie4WJBnD1YFZxLkBrUa6uwhs=" Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Oct 26 08:23:14 volumio volumio[3984]: info: VolumeController:: Volume=33 Mute =false Oct 26 08:23:14 volumio volumio[3984]: info: CoreStateMachine::pushState Oct 26 08:23:14 volumio volumio[3984]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::volumioPushState Oct 26 08:23:14 volumio volumio[3984]: info: CoreStateMachine::updateTrackBlock Oct 26 08:23:14 volumio volumio[3984]: info: CorePlayQueue::getTrackBlock Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.65.9:443: connect: connection refused" Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=debug msg="connected to ap-gew1.spotify.com:80" Oct 26 08:23:14 volumio volumio[3984]: info: CoreStateMachine::setRepeat null single undefined Oct 26 08:23:14 volumio volumio[3984]: info: CoreStateMachine::pushState Oct 26 08:23:14 volumio volumio[3984]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::volumioPushState Oct 26 08:23:14 volumio volumio[3984]: info: CoreStateMachine::setRandom null Oct 26 08:23:14 volumio volumio[3984]: info: CoreStateMachine::pushState Oct 26 08:23:14 volumio volumio[3984]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:14 volumio volumio[3984]: info: CoreCommandRouter::volumioPushState Oct 26 08:23:14 volumio volumio[3984]: info: Setting Device type: Raspberry PI Oct 26 08:23:14 volumio volumio[3984]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 26 08:23:14 volumio volumio[3984]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 26 08:23:14 volumio volumio[3984]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=debug msg="completed keyexchange" Oct 26 08:23:14 volumio go-librespot[4055]: time="2025-10-26T08:23:14Z" level=debug msg="completed challenge" Oct 26 08:23:15 volumio volumio[3984]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 26 08:23:15 volumio volumio[3984]: info: Discovery: Found device Volumio Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::volumioGetState Oct 26 08:23:15 volumio volumio[3984]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:15 volumio volumio[3984]: info: VolumeController:: Volume=33 Mute =false Oct 26 08:23:15 volumio volumio[3984]: info: CoreStateMachine::pushState Oct 26 08:23:15 volumio volumio[3984]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::volumioPushState Oct 26 08:23:15 volumio volumio[3984]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 26 08:23:15 volumio volumio[3984]: info: Discovery: Found device Volumio Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::volumioGetState Oct 26 08:23:15 volumio volumio[3984]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:15 volumio volumio[3984]: info: Completed loading Core Plugins Oct 26 08:23:15 volumio go-librespot[4055]: time="2025-10-26T08:23:15Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:15 volumio volumio[3984]: info: Preparing to generate the ALSA configuration file Oct 26 08:23:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:15 volumio volumio[3984]: info: Asound.conf file unchanged, so no further update is needed Oct 26 08:23:15 volumio volumio[3984]: info: Output device has changed, restarting MPD Oct 26 08:23:15 volumio volumio[3984]: info: Output device has changed, restarting Shairport Sync Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:15 volumio sudo[4108]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 08:23:15 volumio sudo[4108]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:15 volumio volumio[3984]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 08:23:15 volumio sudo[4110]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 08:23:15 volumio volumio[3984]: info: ___________ START PLUGINS ___________ Oct 26 08:23:15 volumio sudo[4110]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:15 volumio volumio[3984]: info: ControllerMpd::onStart: Initializing MPD Oct 26 08:23:15 volumio volumio[3984]: info: Creating MPD Configuration file Oct 26 08:23:15 volumio sudo[4108]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:15 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 08:23:15 volumio volumio[3984]: info: [1761466995121] CoreMusicLibrary::Adding element Media Servers Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:23:15 volumio sudo[4118]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 08:23:15 volumio sudo[4118]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:15 volumio sudo[4118]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:15 volumio sudo[4120]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 08:23:15 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 26 08:23:15 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 26 08:23:15 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 26 08:23:15 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 26 08:23:15 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 26 08:23:15 volumio sudo[4120]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:15 volumio volumio[3984]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 08:23:15 volumio volumio[3984]: info: [1761466995176] CoreMusicLibrary::Adding element Last_100 Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 08:23:15 volumio volumio[3984]: info: [1761466995178] CoreMusicLibrary::Adding element Webradio Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:23:15 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 26 08:23:15 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 08:23:15 volumio volumio[3984]: info: Initializing BBC Radios Oct 26 08:23:15 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 26 08:23:15 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 26 08:23:15 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 26 08:23:15 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 26 08:23:15 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 26 08:23:15 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 26 08:23:15 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: Creating Spotify config file Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio sudo[4138]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 26 08:23:15 volumio sudo[4138]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 26 08:23:15 volumio sudo[4138]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:15 volumio volumio[4063]: Starting albumart workers Oct 26 08:23:15 volumio volumio[4064]: Starting albumart workers Oct 26 08:23:15 volumio volumio[4062]: Starting albumart workers Oct 26 08:23:15 volumio volumio[3984]: info: Volumio Calling Home Oct 26 08:23:15 volumio volumio[3984]: info: MPD Permissions set Oct 26 08:23:15 volumio volumio[3984]: info: MPD Permissions set Oct 26 08:23:15 volumio volumio[3984]: info: Volumio called home Oct 26 08:23:15 volumio volumio[3984]: info: Spotify config file written Oct 26 08:23:15 volumio sudo[4174]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 26 08:23:15 volumio sudo[4174]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:15 volumio volumio[3984]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:15 volumio volumio[3984]: info: No need to fix Spotify hosts Oct 26 08:23:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:15 volumio go-librespot[4181]: go-librespot daemon starting... Oct 26 08:23:15 volumio sudo[4174]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:15 volumio go-librespot[4187]: time="2025-10-26T08:23:15Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:15 volumio go-librespot[4187]: time="2025-10-26T08:23:15Z" level=debug msg="app state loaded" Oct 26 08:23:15 volumio go-librespot[4187]: time="2025-10-26T08:23:15Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:15 volumio volumio[3984]: info: Starting Shairport Sync Oct 26 08:23:15 volumio volumio[3984]: info: Starting Shairport Sync Oct 26 08:23:15 volumio volumio[3984]: info: Starting Shairport Sync Oct 26 08:23:15 volumio sudo[4194]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 08:23:15 volumio sudo[4194]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:15 volumio sudo[4196]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 08:23:15 volumio sudo[4196]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:15 volumio sudo[4199]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 08:23:15 volumio sudo[4199]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:15 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 26 08:23:15 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 26 08:23:15 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 26 08:23:15 volumio systemd[1]: shairport-sync.service: Consumed 1.565s CPU time. Oct 26 08:23:15 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 26 08:23:15 volumio sudo[4194]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:15 volumio sudo[4199]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:15 volumio sudo[4196]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:15 volumio go-librespot[4187]: time="2025-10-26T08:23:15Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:15 volumio go-librespot[4187]: time="2025-10-26T08:23:15Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:15 volumio go-librespot[4187]: time="2025-10-26T08:23:15Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:15 volumio volumio[3984]: info: Shairport-Sync Started Oct 26 08:23:15 volumio volumio[3984]: Error adding Membership: Error: addMembership EINVAL Oct 26 08:23:15 volumio go-librespot[4187]: time="2025-10-26T08:23:15Z" level=info msg="zeroconf server listening on port 36565" Oct 26 08:23:15 volumio volumio[3984]: info: Shairport-Sync Started Oct 26 08:23:15 volumio volumio[3984]: info: Shairport-Sync Started Oct 26 08:23:15 volumio volumio[3984]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 08:23:15 volumio volumio[3984]: SPOTIFY: BQC81R59tQByW_wbvrwd51miO4NfCUZcZ03olP84RKz56S8CnHrbbBEhrRO00QuA6pd2S6SwuvxLMFkAhYEMK43xdrzr8xn0E-1RmeM0cFEn27jJnWGM3T52UDZdvr9B4ELjG2ZfpX9O_RXSZVhE7cwm29JLf4oSku60R5DD30-CnBhXOcqOvQqrP6aSzBRN8409whoAg_xjDDwLIe2ARBQurlntVGjAAUTrosYx5atbLQmMCJDgnsW1jt_jnKf2ZeN682gPb1dR6zOLPXnxk2a7DDJqvLRRB0JT86Dli64jQH_0dBM Oct 26 08:23:15 volumio volumio[3984]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 08:23:15 volumio volumio[3984]: info: New Spotify access token = BQC81R59tQByW_wbvrwd51miO4NfCUZcZ03olP84RKz56S8CnHrbbBEhrRO00QuA6pd2S6SwuvxLMFkAhYEMK43xdrzr8xn0E-1RmeM0cFEn27jJnWGM3T52UDZdvr9B4ELjG2ZfpX9O_RXSZVhE7cwm29JLf4oSku60R5DD30-CnBhXOcqOvQqrP6aSzBRN8409whoAg_xjDDwLIe2ARBQurlntVGjAAUTrosYx5atbLQmMCJDgnsW1jt_jnKf2ZeN682gPb1dR6zOLPXnxk2a7DDJqvLRRB0JT86Dli64jQH_0dBM Oct 26 08:23:15 volumio volumio[3984]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 26 08:23:15 volumio volumio[3984]: info: CoreCommandRouter::volumioGetState Oct 26 08:23:15 volumio volumio[3984]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:16 volumio go-librespot[4187]: time="2025-10-26T08:23:16Z" level=debug msg="obtained new client token: AACqsL4Mqaq+NhO/LECsjCk5FfBM+Z+CxAJqNDb8CDLaFe3LjGS+daDhVx1XMANeYVZpXkmcOF15TSJTeR8EPfjMCenC/Y5Jt07kdA2q1+2KKq1SvLl8a/L6ZMPmEAiBRafPyVrWlaH5TsU8hvfgl7QYGUDv06OnoGynfXW8/pa9uOA8KYXSKmOXDAD+pHLSn1TJwZNg0NVThELxHOtHo2dUASyIuLA0LTQhZTzNZmOUerjngJeS" Oct 26 08:23:16 volumio go-librespot[4187]: time="2025-10-26T08:23:16Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Oct 26 08:23:16 volumio volumio[3984]: SPOTIFY: User informations: {"country":"DE","display_name":"lapman","email":"ylm19961214@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31hyzsop5elyyfayaiyk5tmkxmky"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31hyzsop5elyyfayaiyk5tmkxmky","id":"31hyzsop5elyyfayaiyk5tmkxmky","images":[],"product":"free","type":"user","uri":"spotify:user:31hyzsop5elyyfayaiyk5tmkxmky"} Oct 26 08:23:16 volumio go-librespot[4187]: time="2025-10-26T08:23:16Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 26 08:23:16 volumio volumio[3984]: info: Spotify Successfully logged in Oct 26 08:23:16 volumio volumio[3984]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 08:23:16 volumio volumio[3984]: info: [1761466996082] CoreMusicLibrary::Adding element Spotify Oct 26 08:23:16 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:23:16 volumio volumio[3984]: Cannot find translation for source Spotify Oct 26 08:23:16 volumio mpd[4150]: 2025-10-26T08:23:16 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 26 08:23:16 volumio go-librespot[4187]: time="2025-10-26T08:23:16Z" level=debug msg="completed keyexchange" Oct 26 08:23:16 volumio go-librespot[4187]: time="2025-10-26T08:23:16Z" level=debug msg="completed challenge" Oct 26 08:23:16 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 26 08:23:16 volumio sudo[4120]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:16 volumio sudo[4110]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:16 volumio go-librespot[4187]: time="2025-10-26T08:23:16Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:16 volumio volumio-remote-updater[896]: [2025-10-26 08:23:16] [connect] Successful connection Oct 26 08:23:16 volumio volumio[3984]: error: MPD error: The expression evaluated to a falsy value: Oct 26 08:23:16 volumio volumio[3984]: assert.ok(self.idling) Oct 26 08:23:16 volumio volumio[3984]: error: The expression evaluated to a falsy value: Oct 26 08:23:16 volumio volumio[3984]: assert.ok(self.idling) Oct 26 08:23:16 volumio volumio[3984]: info: MPD running with PID4150 Oct 26 08:23:16 volumio volumio[3984]: ,establishing connection Oct 26 08:23:16 volumio volumio[3984]: error: updateQueue error: null Oct 26 08:23:16 volumio volumio-remote-updater[896]: [2025-10-26 08:23:16] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761466996 101 Oct 26 08:23:16 volumio volumio[3984]: 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: 2 Oct 26 08:23:16 volumio volumio[3984]: error: updateQueue error: null Oct 26 08:23:16 volumio volumio[3984]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 26 08:23:16 volumio volumio[3984]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 08:23:16 volumio volumio[3984]: info: VolumeController:: Volume=33 Mute =false Oct 26 08:23:16 volumio volumio[3984]: info: CoreCommandRouter::volumioGetState Oct 26 08:23:16 volumio volumio[3984]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:16 volumio volumio[3984]: info: CoreStateMachine::pushState Oct 26 08:23:16 volumio volumio[3984]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:16 volumio volumio[3984]: info: CoreCommandRouter::volumioPushState Oct 26 08:23:16 volumio volumio[3984]: info: Completed starting Core Plugins Oct 26 08:23:16 volumio volumio[3984]: info: ------------------------------------------- Oct 26 08:23:16 volumio volumio[3984]: info: ----- MyVolumio plugins startup ---- Oct 26 08:23:16 volumio volumio[3984]: info: ------------------------------------------- Oct 26 08:23:16 volumio volumio[3984]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 26 08:23:17 volumio volumio[3984]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 26 08:23:18 volumio volumio[3984]: info: go-librespot daemon successfully initialized Oct 26 08:23:19 volumio sudo[4226]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 26 08:23:19 volumio sudo[4226]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:19 volumio sudo[4228]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 26 08:23:19 volumio sudo[4228]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:19 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 26 08:23:19 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 26 08:23:19 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 26 08:23:19 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 26 08:23:19 volumio sudo[4228]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 536. Oct 26 08:23:19 volumio sudo[4226]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:19 volumio mpd_monitor.sh[4231]: MPD Monitor Service: Starting MPD Monitor Service Oct 26 08:23:19 volumio volumio[3984]: info: Successfully started MPD Monitor Oct 26 08:23:19 volumio volumio[3984]: info: Successfully started MPD Monitor Oct 26 08:23:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:19 volumio go-librespot[4234]: go-librespot daemon starting... Oct 26 08:23:19 volumio go-librespot[4235]: time="2025-10-26T08:23:19Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:19 volumio go-librespot[4235]: time="2025-10-26T08:23:19Z" level=debug msg="app state loaded" Oct 26 08:23:19 volumio go-librespot[4235]: time="2025-10-26T08:23:19Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:19 volumio go-librespot[4235]: time="2025-10-26T08:23:19Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:19 volumio go-librespot[4235]: time="2025-10-26T08:23:19Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:19 volumio go-librespot[4235]: time="2025-10-26T08:23:19Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:19 volumio go-librespot[4235]: time="2025-10-26T08:23:19Z" level=info msg="zeroconf server listening on port 36623" Oct 26 08:23:19 volumio go-librespot[4235]: time="2025-10-26T08:23:19Z" level=debug msg="obtained new client token: AACQe9EzNAbYUOPLqioGVc70/b8YStgCNCiVupDw172HJkUtKMQAr2GDgMCZRyqAvqaMXQWmobgYYFJlc7kVLdwUwCHMLMrBPhVTvij15VmZaTsOPHyUpHFE6XF3BsY1whU2sMtEg5uFxJIkO63T8RHrsJ1/bXSLGT/VsTulPIqMBYlpySrgBVG2b5fdJR+izyoJ969oPDOUa5llZ/U0Moz2Rm5a14XMm/tU9dj0Ew5CPXBTLtvmSTU=" Oct 26 08:23:19 volumio go-librespot[4235]: time="2025-10-26T08:23:19Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:19 volumio go-librespot[4235]: time="2025-10-26T08:23:19Z" level=debug msg="completed keyexchange" Oct 26 08:23:19 volumio go-librespot[4235]: time="2025-10-26T08:23:19Z" level=debug msg="completed challenge" Oct 26 08:23:19 volumio go-librespot[4235]: time="2025-10-26T08:23:19Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:21 volumio volumio[3984]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 26 08:23:21 volumio volumio[3984]: info: Initializing connection to go-librespot Websocket Oct 26 08:23:21 volumio volumio[3984]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:23:22 volumio volumio[3984]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 26 08:23:22 volumio sudo[4258]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 08:23:22 volumio sudo[4258]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:22 volumio sudo[4260]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 08:23:22 volumio sudo[4258]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:22 volumio sudo[4260]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:22 volumio sudo[4260]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:22 volumio sudo[4263]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 26 08:23:22 volumio sudo[4263]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 537. Oct 26 08:23:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:22 volumio go-librespot[4266]: go-librespot daemon starting... Oct 26 08:23:22 volumio sudo[4263]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:22 volumio volumio[3984]: info: Upmpdcli Daemon Started Oct 26 08:23:22 volumio go-librespot[4267]: time="2025-10-26T08:23:22Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:22 volumio go-librespot[4267]: time="2025-10-26T08:23:22Z" level=debug msg="app state loaded" Oct 26 08:23:22 volumio go-librespot[4267]: time="2025-10-26T08:23:22Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:22 volumio go-librespot[4267]: time="2025-10-26T08:23:22Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 26 08:23:22 volumio go-librespot[4267]: time="2025-10-26T08:23:22Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 26 08:23:22 volumio go-librespot[4267]: time="2025-10-26T08:23:22Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 26 08:23:22 volumio go-librespot[4267]: time="2025-10-26T08:23:22Z" level=info msg="zeroconf server listening on port 44549" Oct 26 08:23:22 volumio go-librespot[4267]: time="2025-10-26T08:23:22Z" level=debug msg="obtained new client token: AAB4Kllyk/V4WoVOBdcKs5XmwChcsRW8yr7qkKHMTd2xTb0RoU3KliZQNMoG3FIJgTBK08whcslSYanf33KJZ3XSCzNhSgM1BOw3Q+2XgBLWLEjZXnGa/Dh7JApqoc1E2gHj+w7NzwHfsz1uNqpZ/T3PjLiLSpW7zJ165U3Kebk4U41IgEEIoyc5qN7Ox87P4AMAypCLQ6y1MbtE0RQ7nG18Fss8Hn0DV8SjR4FRrjguufDdMN7DQ2M=" Oct 26 08:23:22 volumio go-librespot[4267]: time="2025-10-26T08:23:22Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:22 volumio go-librespot[4267]: time="2025-10-26T08:23:22Z" level=debug msg="completed keyexchange" Oct 26 08:23:22 volumio go-librespot[4267]: time="2025-10-26T08:23:22Z" level=debug msg="completed challenge" Oct 26 08:23:22 volumio go-librespot[4267]: time="2025-10-26T08:23:22Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 26 08:23:24 volumio volumio[3984]: info: Adding plugin bluetooth to MyMusic Plugins Oct 26 08:23:24 volumio volumio[3984]: info: Adding plugin multiroom to MyMusic Plugins Oct 26 08:23:24 volumio volumio[3984]: info: Adding plugin metavolumio to MyMusic Plugins Oct 26 08:23:24 volumio volumio[3984]: info: Adding plugin cd_controller to MyMusic Plugins Oct 26 08:23:24 volumio volumio[3984]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 26 08:23:24 volumio volumio[3984]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 26 08:23:24 volumio volumio[3984]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 26 08:23:24 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:24 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:24 volumio volumio[3984]: info: Starting MyVolumio Remote Streaming Endpoints Oct 26 08:23:24 volumio volumio[3984]: info: MyVolumio login type: Token Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 26 08:23:24 volumio volumio[3984]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 26 08:23:25 volumio volumio[3984]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 26 08:23:25 volumio volumio[3984]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 26 08:23:25 volumio volumio[3984]: info: Streaming services startup Oct 26 08:23:25 volumio volumio[3984]: info: Starting Streaming Daemon Oct 26 08:23:25 volumio sudo[4276]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 26 08:23:25 volumio sudo[4276]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:25 volumio volumio[3984]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 26 08:23:25 volumio sudo[4276]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:25 volumio volumio[3984]: info: Initializing connection to go-librespot Websocket Oct 26 08:23:25 volumio volumio[3984]: error: Cannot start Volumio Streaming Daemon Oct 26 08:23:25 volumio volumio[3984]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 26 08:23:25 volumio volumio[3984]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 26 08:23:25 volumio volumio[3984]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:23:25 volumio volumio[3984]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 26 08:23:25 volumio volumio[3984]: info: MyVolumio token set successfully Oct 26 08:23:25 volumio volumio[3984]: info: MYVOLUMIO: Adding device Oct 26 08:23:25 volumio volumio[3984]: info: MYVOLUMIO: Evaluating Server Oct 26 08:23:26 volumio volumio[3984]: info: MyVolumio status changed Oct 26 08:23:26 volumio volumio[3984]: info: Streaming services startup Oct 26 08:23:26 volumio volumio[3984]: info: Starting Streaming Daemon Oct 26 08:23:26 volumio volumio[3984]: info: Removing browser output: myVolumio user plan is not superstar Oct 26 08:23:26 volumio volumio[3984]: info: Removing audio output: Oct 26 08:23:26 volumio volumio[3984]: info: Stoppping Tunnel 1 Oct 26 08:23:26 volumio sudo[4301]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 26 08:23:26 volumio sudo[4301]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:26 volumio sudo[4303]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 26 08:23:26 volumio sudo[4303]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 538. Oct 26 08:23:26 volumio sudo[4301]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:26 volumio volumio[3984]: error: Cannot start Volumio Streaming Daemon Oct 26 08:23:26 volumio volumio[3984]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 26 08:23:26 volumio volumio[3984]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 26 08:23:26 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. Oct 26 08:23:26 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. Oct 26 08:23:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:26 volumio go-librespot[4306]: go-librespot daemon starting... Oct 26 08:23:26 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. Oct 26 08:23:26 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. Oct 26 08:23:26 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. Oct 26 08:23:26 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. Oct 26 08:23:26 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. Oct 26 08:23:26 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. Oct 26 08:23:26 volumio go-librespot[4307]: time="2025-10-26T08:23:26Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:26 volumio go-librespot[4307]: time="2025-10-26T08:23:26Z" level=debug msg="app state loaded" Oct 26 08:23:26 volumio go-librespot[4307]: time="2025-10-26T08:23:26Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:26 volumio sudo[4303]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:26 volumio volumio[3984]: info: Remote SSH Stopped Oct 26 08:23:26 volumio go-librespot[4307]: time="2025-10-26T08:23:26Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:26 volumio go-librespot[4307]: time="2025-10-26T08:23:26Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:26 volumio go-librespot[4307]: time="2025-10-26T08:23:26Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:26 volumio go-librespot[4307]: time="2025-10-26T08:23:26Z" level=info msg="zeroconf server listening on port 39379" Oct 26 08:23:26 volumio go-librespot[4307]: time="2025-10-26T08:23:26Z" level=debug msg="obtained new client token: AABkNoUax9cmD1Yl6kVtHmzbKVpSZSzJ0tAT0pfQynCUMcg1KW0dr3mq1WeQQliAvUz/MLgHj3av7OkTRNWxZjZwLFet7XBJowXzQunh8k2zBZCtOQq8pzZYRFOUVM/fTgNCIYASMJ9UEEF03waYVSabsuNBbON8G2ROcMxhrZuwzpgHAiZXxUVf2aZUPHm37DUCqTJZXs+/6ppSBe6mGcCeB/6wbcsIkNjbQwpFEDz3/nQp92UjPJo=" Oct 26 08:23:26 volumio volumio[3984]: info: Setting Geolocation for MyVolumio to eu3 Oct 26 08:23:26 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:26 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:26 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:26 volumio go-librespot[4307]: time="2025-10-26T08:23:26Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:26 volumio go-librespot[4307]: time="2025-10-26T08:23:26Z" level=debug msg="completed keyexchange" Oct 26 08:23:26 volumio go-librespot[4307]: time="2025-10-26T08:23:26Z" level=debug msg="completed challenge" Oct 26 08:23:26 volumio go-librespot[4307]: time="2025-10-26T08:23:26Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:27 volumio volumio[3984]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 26 08:23:27 volumio volumio[3984]: info: Updating MyVolumio device info Oct 26 08:23:27 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:27 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:27 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:27 volumio volumio[3984]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 26 08:23:27 volumio volumio[3984]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 26 08:23:28 volumio volumio[3984]: info: Initializing connection to go-librespot Websocket Oct 26 08:23:28 volumio volumio[3984]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:23:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 539. Oct 26 08:23:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:29 volumio go-librespot[4314]: go-librespot daemon starting... Oct 26 08:23:29 volumio go-librespot[4315]: time="2025-10-26T08:23:29Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:29 volumio go-librespot[4315]: time="2025-10-26T08:23:29Z" level=debug msg="app state loaded" Oct 26 08:23:29 volumio go-librespot[4315]: time="2025-10-26T08:23:29Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:29 volumio go-librespot[4315]: time="2025-10-26T08:23:29Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:29 volumio go-librespot[4315]: time="2025-10-26T08:23:29Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:29 volumio go-librespot[4315]: time="2025-10-26T08:23:29Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:29 volumio go-librespot[4315]: time="2025-10-26T08:23:29Z" level=info msg="zeroconf server listening on port 44027" Oct 26 08:23:29 volumio go-librespot[4315]: time="2025-10-26T08:23:29Z" level=debug msg="obtained new client token: AADaAMjqbna0g1E/zD91MavLovh6kBdhngCxDI+kYenMBcRQGDUOJXX/5p7jc39J26LjQD8ydIIKEVMT1z98O8Tt6SoR6pM4M97WdRs74G6kYaFkOiHsEE3MIg/145EdAhTgvuUQPwzBvVQYyf3qc31iChpRYhImGE0zTnCtlGMUax2hWL9mP1DdggP3TUr6+NgY7L6NU6qtCZ+KwrhJAuzFbNXxqZSRCsAHjXeRS4Q4vfEGbEtaaZE=" Oct 26 08:23:29 volumio go-librespot[4315]: time="2025-10-26T08:23:29Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:29 volumio go-librespot[4315]: time="2025-10-26T08:23:29Z" level=debug msg="completed keyexchange" Oct 26 08:23:29 volumio go-librespot[4315]: time="2025-10-26T08:23:29Z" level=debug msg="completed challenge" Oct 26 08:23:29 volumio go-librespot[4315]: time="2025-10-26T08:23:29Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:31 volumio volumio[3984]: info: MYVOLUMIO: Adding device Oct 26 08:23:31 volumio volumio[3984]: info: MYVOLUMIO: Evaluating Server Oct 26 08:23:31 volumio volumio[3984]: info: Initializing connection to go-librespot Websocket Oct 26 08:23:31 volumio volumio[3984]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:23:31 volumio volumio[3984]: info: Setting Geolocation for MyVolumio to eu3 Oct 26 08:23:31 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:31 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:31 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:31 volumio volumio[3984]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 26 08:23:32 volumio volumio[3984]: info: Updating MyVolumio device info Oct 26 08:23:32 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:32 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:32 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:32 volumio volumio[3984]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 26 08:23:32 volumio volumio[3984]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 26 08:23:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 540. Oct 26 08:23:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:33 volumio go-librespot[4351]: go-librespot daemon starting... Oct 26 08:23:33 volumio go-librespot[4352]: time="2025-10-26T08:23:33Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:33 volumio go-librespot[4352]: time="2025-10-26T08:23:33Z" level=debug msg="app state loaded" Oct 26 08:23:33 volumio go-librespot[4352]: time="2025-10-26T08:23:33Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:33 volumio go-librespot[4352]: time="2025-10-26T08:23:33Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:33 volumio go-librespot[4352]: time="2025-10-26T08:23:33Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:33 volumio go-librespot[4352]: time="2025-10-26T08:23:33Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:33 volumio go-librespot[4352]: time="2025-10-26T08:23:33Z" level=info msg="zeroconf server listening on port 37713" Oct 26 08:23:33 volumio go-librespot[4352]: time="2025-10-26T08:23:33Z" level=debug msg="obtained new client token: AADIuTZve+f5NfocLCLF04NEjUH7HSxevwtnnFw/CdmntfHrqg6QN7aR77W2JEklxsMFEFbR4nDQzfKb1zatUmYTX0IL4dlucV1ODiZMiqBjcen00RKXuHi8WrAlv/BIsDfefJLU5rnGcvE88RWW7SqupTzhNqT6XuVM0WPbbC8LR15ww6Bs0dWxEwbZfZDZaPPuvrJc4IXkl+Qer3Or1lwtQPQ1QdUqnhThPDOxTz+9iC3W0QVX+G0=" Oct 26 08:23:33 volumio go-librespot[4352]: time="2025-10-26T08:23:33Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:33 volumio go-librespot[4352]: time="2025-10-26T08:23:33Z" level=debug msg="completed keyexchange" Oct 26 08:23:33 volumio go-librespot[4352]: time="2025-10-26T08:23:33Z" level=debug msg="completed challenge" Oct 26 08:23:33 volumio go-librespot[4352]: time="2025-10-26T08:23:33Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:34 volumio volumio[3984]: info: Initializing connection to go-librespot Websocket Oct 26 08:23:34 volumio volumio[3984]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:23:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 541. Oct 26 08:23:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:36 volumio go-librespot[4360]: go-librespot daemon starting... Oct 26 08:23:36 volumio go-librespot[4361]: time="2025-10-26T08:23:36Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:36 volumio go-librespot[4361]: time="2025-10-26T08:23:36Z" level=debug msg="app state loaded" Oct 26 08:23:36 volumio go-librespot[4361]: time="2025-10-26T08:23:36Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:36 volumio go-librespot[4361]: time="2025-10-26T08:23:36Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 26 08:23:36 volumio go-librespot[4361]: time="2025-10-26T08:23:36Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 26 08:23:36 volumio go-librespot[4361]: time="2025-10-26T08:23:36Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 26 08:23:36 volumio go-librespot[4361]: time="2025-10-26T08:23:36Z" level=info msg="zeroconf server listening on port 36097" Oct 26 08:23:36 volumio go-librespot[4361]: time="2025-10-26T08:23:36Z" level=debug msg="obtained new client token: AAC2Z9syq3lK/d0XboRyhSswxbN6VkCUTQx7x3ztZB7VpAlcawVyrA93Iq69uDa16+MHfC9/pgSHyb8813e5QoQikwMFq/a1rCntlgDF86WOXWV6T+DWleMw4Pt1/wHfvGV0OMWRM17/IbDOPjNLZJyr6cF5A6S1hcANT8Si4yTUvROXoXaa9Ot+3rdXzKQ38eN9m+AbqCFM7Ro7u3/A8FhD9u4RIuoro55qdrP4lnBzk9wCZjuG0ME=" Oct 26 08:23:36 volumio go-librespot[4361]: time="2025-10-26T08:23:36Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:36 volumio go-librespot[4361]: time="2025-10-26T08:23:36Z" level=debug msg="completed keyexchange" Oct 26 08:23:36 volumio go-librespot[4361]: time="2025-10-26T08:23:36Z" level=debug msg="completed challenge" Oct 26 08:23:36 volumio go-librespot[4361]: time="2025-10-26T08:23:36Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:37 volumio volumio[3984]: info: Initializing connection to go-librespot Websocket Oct 26 08:23:37 volumio volumio[3984]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:23:39 volumio volumio[3984]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 26 08:23:39 volumio volumio[3984]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 26 08:23:39 volumio volumio[3984]: info: CoreCommandRouter::volumioGetState Oct 26 08:23:39 volumio volumio[3984]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 542. Oct 26 08:23:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:40 volumio go-librespot[4371]: go-librespot daemon starting... Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=debug msg="app state loaded" Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:40 volumio volumio[3984]: info: Initializing connection to go-librespot Websocket Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=debug msg="new websocket client" Oct 26 08:23:40 volumio volumio[3984]: info: Connection to go-librespot Websocket established Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=info msg="zeroconf server listening on port 38227" Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=debug msg="obtained new client token: AAD7ur4f8qey2VDJeCeUYTFtbTBf8qO75rnN6fTz/RCoxsKawyI8sTLBq8m6pRXrqh91UmY4br31vcYccxXLcsdFP9KR5PQ6VBiiFrbll6isCsPBowe3MN6ci6O9r4lo/9knd4cdNeDWf640z5J4/jC5435z8ehZylPqiICz0g9dR5cSxytusSllq6hpnYFzGQRlhx+wAcu2AxSNmtF7jNAX7DcBjIOQ7X0iEyBtqzIX6cZnm2VJYqw=" Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=debug msg="completed keyexchange" Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=debug msg="completed challenge" Oct 26 08:23:40 volumio go-librespot[4372]: time="2025-10-26T08:23:40Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:40 volumio volumio[3984]: info: Connection to go-librespot Websocket closed Oct 26 08:23:43 volumio volumio[3984]: info: Getting Spotify volume Oct 26 08:23:43 volumio volumio[3984]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 08:23:43 volumio volumio[3984]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:23:43 volumio volumio[3984]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 26 08:23:43 volumio volumio[3984]: errno: -111, Oct 26 08:23:43 volumio volumio[3984]: code: 'ECONNREFUSED', Oct 26 08:23:43 volumio volumio[3984]: syscall: 'connect', Oct 26 08:23:43 volumio volumio[3984]: address: '127.0.0.1', Oct 26 08:23:43 volumio volumio[3984]: port: 9879, Oct 26 08:23:43 volumio volumio[3984]: response: undefined Oct 26 08:23:43 volumio volumio[3984]: } Oct 26 08:23:43 volumio volumio[3984]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 08:23:43 volumio sudo[4407]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-26 08:22' Oct 26 08:23:43 volumio sudo[4407]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:43 volumio sudo[4407]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:43 volumio volumio-remote-updater[896]: [2025-10-26 08:23:43] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 26 08:23:43 volumio volumio-remote-updater[896]: [2025-10-26 08:23:43] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 26 08:23:43 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 543. Oct 26 08:23:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:43 volumio go-librespot[4412]: go-librespot daemon starting... Oct 26 08:23:43 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 26 08:23:43 volumio systemd[1]: volumio.service: Consumed 11.727s CPU time. Oct 26 08:23:43 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 26 08:23:43 volumio go-librespot[4413]: time="2025-10-26T08:23:43Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:43 volumio go-librespot[4413]: time="2025-10-26T08:23:43Z" level=debug msg="app state loaded" Oct 26 08:23:43 volumio go-librespot[4413]: time="2025-10-26T08:23:43Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:43 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 26 08:23:43 volumio go-librespot[4413]: time="2025-10-26T08:23:43Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:43 volumio go-librespot[4413]: time="2025-10-26T08:23:43Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:43 volumio go-librespot[4413]: time="2025-10-26T08:23:43Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:43 volumio go-librespot[4413]: time="2025-10-26T08:23:43Z" level=info msg="zeroconf server listening on port 46049" Oct 26 08:23:43 volumio go-librespot[4413]: time="2025-10-26T08:23:43Z" level=debug msg="obtained new client token: AAA9uIJN7NRm4D4hKUyJ2LY4tBnxLyQWlY+57LEVWVBzOtLCtg/VJ5gPGyhTak1wHEWnjTRsV4SANBSbAUWJh71b8it1uqEBN+Md8u2jzCOzPSUGY/n4UTVMVxZ/5AF/d5BQ9shmWK6ypQ2+ZEcAXMsL4XuRCAGRDPXvPelo/QE+epvOvbp4BO1DD3Fj92AKxNEWHM5KXFGDoKLCF8Rl8kQLVYUybiy+2rT0PYy7nmHU5CW8ZOZEhw4=" Oct 26 08:23:43 volumio go-librespot[4413]: time="2025-10-26T08:23:43Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:43 volumio go-librespot[4413]: time="2025-10-26T08:23:43Z" level=debug msg="completed keyexchange" Oct 26 08:23:43 volumio go-librespot[4413]: time="2025-10-26T08:23:43Z" level=debug msg="completed challenge" Oct 26 08:23:43 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 6750. Oct 26 08:23:43 volumio go-librespot[4413]: time="2025-10-26T08:23:43Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:43 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 26 08:23:43 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 26 08:23:43 volumio systemd[1]: volumio.service: Consumed 11.727s CPU time. Oct 26 08:23:43 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 26 08:23:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:43 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 26 08:23:44 volumio volumio[4427]: info: ------------------------------------------- Oct 26 08:23:44 volumio volumio[4427]: info: ----- Volumio3 ---- Oct 26 08:23:44 volumio volumio[4427]: info: ------------------------------------------- Oct 26 08:23:44 volumio volumio[4427]: info: ----- System startup ---- Oct 26 08:23:44 volumio volumio[4427]: info: ------------------------------------------- Oct 26 08:23:44 volumio volumio[4427]: info: MYVOLUMIO Environment detected Oct 26 08:23:44 volumio volumio[4427]: info: Plugin folders cleanup Oct 26 08:23:44 volumio volumio[4427]: info: Scanning into folder /volumio/app/plugins/ Oct 26 08:23:44 volumio volumio[4427]: info: Scanning category audio_interface Oct 26 08:23:44 volumio volumio[4427]: info: Scanning category miscellanea Oct 26 08:23:44 volumio volumio[4427]: info: Scanning category music_service Oct 26 08:23:44 volumio volumio[4427]: info: Scanning category plugins.json Oct 26 08:23:44 volumio volumio[4427]: info: Scanning category system_controller Oct 26 08:23:44 volumio volumio[4427]: info: Scanning category user_interface Oct 26 08:23:44 volumio volumio[4427]: info: Scanning into folder /data/plugins/ Oct 26 08:23:44 volumio volumio[4427]: info: Scanning category music_service Oct 26 08:23:44 volumio volumio[4427]: info: Scanning category user_interface Oct 26 08:23:44 volumio volumio[4427]: info: Plugin folders cleanup completed Oct 26 08:23:44 volumio volumio[4427]: info: ------------------------------------------- Oct 26 08:23:44 volumio volumio[4427]: info: ----- Core plugins startup ---- Oct 26 08:23:44 volumio volumio[4427]: info: ------------------------------------------- Oct 26 08:23:44 volumio volumio[4427]: info: Loading plugins from folder /volumio/app/plugins/ Oct 26 08:23:44 volumio volumio[4427]: info: Adding plugin upnp to MyMusic Plugins Oct 26 08:23:44 volumio volumio[4427]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 26 08:23:44 volumio volumio[4427]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 26 08:23:44 volumio volumio[4427]: info: Loading plugins from folder /data/plugins/ Oct 26 08:23:44 volumio volumio[4427]: info: Loading plugin "system"... Oct 26 08:23:44 volumio volumio[4427]: info: Loading plugin "appearance"... Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "network"... Oct 26 08:23:45 volumio volumio[4427]: info: Refreshing Cached IP Addresses Oct 26 08:23:45 volumio sudo[4455]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 08:23:45 volumio sudo[4455]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:45 volumio sudo[4457]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 08:23:45 volumio sudo[4457]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:45 volumio sudo[4455]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:45 volumio sudo[4457]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "services"... Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "alsa_controller"... Oct 26 08:23:45 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "wizard"... Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "networkfs"... Oct 26 08:23:45 volumio volumio[4427]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 26 08:23:45 volumio volumio[4427]: info: Starting Udev Watcher for removable devices Oct 26 08:23:45 volumio volumio[4427]: info: Ignoring mount for partition: boot Oct 26 08:23:45 volumio volumio[4427]: info: Ignoring mount for partition: volumio Oct 26 08:23:45 volumio volumio[4427]: info: Ignoring mount for partition: volumio_data Oct 26 08:23:45 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "volumio_command_line_client"... Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "upnp"... Oct 26 08:23:45 volumio volumio[4427]: info: [1761467025109] Starting Upmpd Daemon Oct 26 08:23:45 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "my_music"... Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "mpd"... Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "upnp_browser"... Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "alarm-clock"... Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "airplay_emulation"... Oct 26 08:23:45 volumio volumio[4427]: info: Starting Shairport Sync Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "last_100"... Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "webradio"... Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "i2s_dacs"... Oct 26 08:23:45 volumio volumio[4427]: info: I2S DAC not set, start Auto-detection Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "volumiodiscovery"... Oct 26 08:23:45 volumio volumio[4427]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 08:23:45 volumio volumio[4427]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 08:23:45 volumio volumio[4427]: *** WARNING *** For more information see Oct 26 08:23:45 volumio volumio[4427]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 08:23:45 volumio node[4427]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 08:23:45 volumio volumio[4427]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 08:23:45 volumio volumio[4427]: *** WARNING *** For more information see Oct 26 08:23:45 volumio node[4427]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 08:23:45 volumio node[4427]: *** WARNING *** For more information see Oct 26 08:23:45 volumio node[4427]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 08:23:45 volumio node[4427]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 08:23:45 volumio node[4427]: *** WARNING *** For more information see Oct 26 08:23:45 volumio volumio[4427]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 26 08:23:45 volumio volumio[4427]: info: Discovery: Started advertising with name: Volumio Oct 26 08:23:45 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 08:23:45 volumio volumio[4427]: info: Loading plugin "spop"... Oct 26 08:23:46 volumio volumio[4427]: info: Loading plugin "ytcr"... Oct 26 08:23:47 volumio volumio[4427]: info: Loading plugin "outputs"... Oct 26 08:23:47 volumio volumio[4427]: info: Loading plugin "albumart"... Oct 26 08:23:47 volumio volumio[4427]: info: Plugin example_plugin is not enabled Oct 26 08:23:47 volumio volumio[4427]: info: Loading plugin "inputs"... Oct 26 08:23:47 volumio volumio[4427]: info: Loading plugin "updater_comm"... Oct 26 08:23:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 544. Oct 26 08:23:47 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:47 volumio volumio[4427]: info: Plugin mpdemulation is not enabled Oct 26 08:23:47 volumio volumio[4427]: info: Loading plugin "rest_api"... Oct 26 08:23:47 volumio volumio[4427]: info: Loading plugin "websocket"... Oct 26 08:23:47 volumio volumio[4427]: info: Starting Socket.io Server version 1.7.4 Oct 26 08:23:47 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:47 volumio volumio[4427]: info: Loading plugin "Systeminfo"... Oct 26 08:23:47 volumio go-librespot[4496]: go-librespot daemon starting... Oct 26 08:23:47 volumio go-librespot[4498]: time="2025-10-26T08:23:47Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:47 volumio go-librespot[4498]: time="2025-10-26T08:23:47Z" level=debug msg="app state loaded" Oct 26 08:23:47 volumio go-librespot[4498]: time="2025-10-26T08:23:47Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:47 volumio volumio[4427]: info: Loading i18n strings for locale en Oct 26 08:23:47 volumio volumio[4427]: Updating browse sources language Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:23:47 volumio volumio[4487]: Forking 3 albumart workers Oct 26 08:23:47 volumio go-librespot[4498]: time="2025-10-26T08:23:47Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:47 volumio go-librespot[4498]: time="2025-10-26T08:23:47Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:47 volumio go-librespot[4498]: time="2025-10-26T08:23:47Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:47 volumio go-librespot[4498]: time="2025-10-26T08:23:47Z" level=info msg="zeroconf server listening on port 38549" Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::initPlayerControls Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: Express server listening on port 3000 Oct 26 08:23:47 volumio volumio[4427]: [Metrics] WebUI: 2s 996.47ms Oct 26 08:23:47 volumio volumio[4427]: info: CoreStateMachine::resetVolumioState Oct 26 08:23:47 volumio volumio[4427]: info: CoreStateMachine::getcurrentVolume Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: Cannot read play queue from file Oct 26 08:23:47 volumio volumio[4427]: info: Volumio Network Manager: Network status updated: 1 Oct 26 08:23:47 volumio go-librespot[4498]: time="2025-10-26T08:23:47Z" level=debug msg="obtained new client token: AAD+jpTrTAqWfo5Q5pba59+lS/AuH2dmS3svozPM4cOo4gN/xh/62iZGVy5fvjxsdVS4sLi0K1c6TpuNIevGFznvSoCmpre+ZvLNVqG5sotZ2Zjvlf7PeeH0vppX2+JgWGN52CsV88QaWS32F5GFkzB2isYEThbaekzB/DwZ9eAr7cgS124WRb/ZMAP76AyNrUXI95Qp4PtVw3gkFjI4ROOVpvxFKMwVXwoPXv15E2O2xlIHlMQDOU0=" Oct 26 08:23:47 volumio go-librespot[4498]: time="2025-10-26T08:23:47Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:47 volumio go-librespot[4498]: time="2025-10-26T08:23:47Z" level=debug msg="completed keyexchange" Oct 26 08:23:47 volumio go-librespot[4498]: time="2025-10-26T08:23:47Z" level=debug msg="completed challenge" Oct 26 08:23:47 volumio volumio[4427]: info: VolumeController:: Volume=33 Mute =false Oct 26 08:23:47 volumio volumio[4427]: info: CoreStateMachine::pushState Oct 26 08:23:47 volumio volumio[4427]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::volumioPushState Oct 26 08:23:47 volumio volumio[4427]: info: CoreStateMachine::updateTrackBlock Oct 26 08:23:47 volumio volumio[4427]: info: CorePlayQueue::getTrackBlock Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 08:23:47 volumio go-librespot[4498]: time="2025-10-26T08:23:47Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:47 volumio volumio[4427]: info: CoreStateMachine::setRepeat null single undefined Oct 26 08:23:47 volumio volumio[4427]: info: CoreStateMachine::pushState Oct 26 08:23:47 volumio volumio[4427]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::volumioPushState Oct 26 08:23:47 volumio volumio[4427]: info: CoreStateMachine::setRandom null Oct 26 08:23:47 volumio volumio[4427]: info: CoreStateMachine::pushState Oct 26 08:23:47 volumio volumio[4427]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::volumioPushState Oct 26 08:23:47 volumio volumio[4427]: info: Setting Device type: Raspberry PI Oct 26 08:23:47 volumio volumio[4427]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 26 08:23:47 volumio volumio[4427]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 26 08:23:47 volumio volumio[4427]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 26 08:23:47 volumio volumio[4427]: info: VolumeController:: Volume=33 Mute =false Oct 26 08:23:47 volumio volumio[4427]: info: CoreStateMachine::pushState Oct 26 08:23:47 volumio volumio[4427]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::volumioPushState Oct 26 08:23:47 volumio volumio[4427]: info: Completed loading Core Plugins Oct 26 08:23:47 volumio volumio[4427]: info: Preparing to generate the ALSA configuration file Oct 26 08:23:47 volumio volumio[4427]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 26 08:23:47 volumio volumio[4427]: info: Discovery: Found device Volumio Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::volumioGetState Oct 26 08:23:47 volumio volumio[4427]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:47 volumio volumio[4427]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 26 08:23:47 volumio volumio[4427]: info: Discovery: Found device Volumio Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::volumioGetState Oct 26 08:23:47 volumio volumio[4427]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:47 volumio volumio[4427]: info: Asound.conf file unchanged, so no further update is needed Oct 26 08:23:47 volumio volumio[4427]: info: Output device has changed, restarting MPD Oct 26 08:23:47 volumio volumio[4427]: info: Output device has changed, restarting Shairport Sync Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:47 volumio sudo[4551]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 08:23:47 volumio sudo[4551]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:47 volumio sudo[4551]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:47 volumio sudo[4553]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 08:23:47 volumio sudo[4553]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:47 volumio volumio[4427]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 08:23:47 volumio volumio[4427]: info: ___________ START PLUGINS ___________ Oct 26 08:23:47 volumio volumio[4427]: info: ControllerMpd::onStart: Initializing MPD Oct 26 08:23:47 volumio volumio[4427]: info: Creating MPD Configuration file Oct 26 08:23:47 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 08:23:47 volumio volumio[4427]: info: [1761467027666] CoreMusicLibrary::Adding element Media Servers Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:47 volumio sudo[4563]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 08:23:47 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 26 08:23:47 volumio sudo[4563]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:47 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 26 08:23:47 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 26 08:23:47 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 26 08:23:47 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 26 08:23:47 volumio sudo[4561]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 08:23:47 volumio sudo[4561]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:47 volumio volumio[4427]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 08:23:47 volumio sudo[4561]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:47 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 26 08:23:47 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 26 08:23:47 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 26 08:23:47 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 26 08:23:47 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 26 08:23:47 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 26 08:23:47 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 26 08:23:47 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 26 08:23:47 volumio volumio[4427]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 08:23:47 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 08:23:47 volumio volumio[4427]: info: [1761467027742] CoreMusicLibrary::Adding element Last_100 Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 08:23:47 volumio volumio[4427]: info: [1761467027746] CoreMusicLibrary::Adding element Webradio Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 08:23:47 volumio volumio[4427]: info: Initializing BBC Radios Oct 26 08:23:47 volumio volumio[4505]: Starting albumart workers Oct 26 08:23:47 volumio sudo[4577]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 26 08:23:47 volumio sudo[4577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:47 volumio sudo[4577]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:47 volumio volumio[4427]: info: Creating Spotify config file Oct 26 08:23:47 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:47 volumio volumio[4506]: Starting albumart workers Oct 26 08:23:47 volumio volumio[4507]: Starting albumart workers Oct 26 08:23:48 volumio volumio[4427]: info: Volumio Calling Home Oct 26 08:23:48 volumio volumio[4427]: info: MPD Permissions set Oct 26 08:23:48 volumio volumio[4427]: info: MPD Permissions set Oct 26 08:23:48 volumio volumio[4427]: info: Volumio called home Oct 26 08:23:48 volumio volumio[4427]: info: Spotify config file written Oct 26 08:23:48 volumio sudo[4615]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 26 08:23:48 volumio sudo[4615]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:48 volumio volumio[4427]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:48 volumio go-librespot[4622]: go-librespot daemon starting... Oct 26 08:23:48 volumio sudo[4615]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:23:48 volumio volumio[4427]: info: No need to fix Spotify hosts Oct 26 08:23:48 volumio go-librespot[4628]: time="2025-10-26T08:23:48Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:48 volumio go-librespot[4628]: time="2025-10-26T08:23:48Z" level=debug msg="app state loaded" Oct 26 08:23:48 volumio go-librespot[4628]: time="2025-10-26T08:23:48Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:48 volumio volumio[4427]: info: Starting Shairport Sync Oct 26 08:23:48 volumio go-librespot[4628]: time="2025-10-26T08:23:48Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:48 volumio go-librespot[4628]: time="2025-10-26T08:23:48Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:48 volumio go-librespot[4628]: time="2025-10-26T08:23:48Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:48 volumio volumio[4427]: info: Starting Shairport Sync Oct 26 08:23:48 volumio go-librespot[4628]: time="2025-10-26T08:23:48Z" level=info msg="zeroconf server listening on port 36287" Oct 26 08:23:48 volumio volumio[4427]: info: Starting Shairport Sync Oct 26 08:23:48 volumio sudo[4636]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 08:23:48 volumio sudo[4640]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 08:23:48 volumio sudo[4640]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:48 volumio sudo[4638]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 08:23:48 volumio sudo[4638]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:48 volumio sudo[4636]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:48 volumio volumio[4427]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 08:23:48 volumio volumio[4427]: SPOTIFY: BQC7uWGupTmI-qDl-KXS3w1yHZndAZM9PzGdijq7rjOchZslUS05S4EaMPeWm3MZI2fJXIwtfml6lxTM4m9CsR6DBOS0HaT9Vag_TkFu24dA3bOSCow-tZik4PRpXkny5K2KLWvJZwGtLhUJo88iw7fnd8SkPE90bgL7J5OHn3M5JwDVUcfFEbpOJy-q9CzbdLQaOCOm-aBhtwlUUwr5kPSTq828fAhO3FJ-7uCpxnMeS7dDi24crp6hSjAvGHDYZt6HjBertC63O5uT2QiTk-W3sFrO1T2sD-C4HGqA_UuFTI8tH-4 Oct 26 08:23:48 volumio volumio[4427]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 08:23:48 volumio volumio[4427]: info: New Spotify access token = BQC7uWGupTmI-qDl-KXS3w1yHZndAZM9PzGdijq7rjOchZslUS05S4EaMPeWm3MZI2fJXIwtfml6lxTM4m9CsR6DBOS0HaT9Vag_TkFu24dA3bOSCow-tZik4PRpXkny5K2KLWvJZwGtLhUJo88iw7fnd8SkPE90bgL7J5OHn3M5JwDVUcfFEbpOJy-q9CzbdLQaOCOm-aBhtwlUUwr5kPSTq828fAhO3FJ-7uCpxnMeS7dDi24crp6hSjAvGHDYZt6HjBertC63O5uT2QiTk-W3sFrO1T2sD-C4HGqA_UuFTI8tH-4 Oct 26 08:23:48 volumio volumio[4427]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 26 08:23:48 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 26 08:23:48 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 26 08:23:48 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 26 08:23:48 volumio systemd[1]: shairport-sync.service: Consumed 1.539s CPU time. Oct 26 08:23:48 volumio go-librespot[4628]: time="2025-10-26T08:23:48Z" level=debug msg="obtained new client token: AAAWV8LLuX0J1aa+NnCnKw9b2x9r9qBn8ffQZ3RD0sBgEdbgbwpEEGu+ylVf1zW4+iI8AhGUchH4SmogZIJgxdhnCps966VTnJB7O5RFA6O0oKmWZ0BbxvrQ3Y5F+geudVw1SkHCuPjzuxmkKyj63A6mmU3cIJ4YKWOOrFMK1jlZX70JuFiN1G7LAa8rcg2wY6rSODDxhnRHpG1Am5+TdBmvVmJqxI486W42h/TL4e7e4Ib3PpXwZoY=" Oct 26 08:23:48 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::volumioGetState Oct 26 08:23:48 volumio volumio[4427]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:48 volumio sudo[4640]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:48 volumio sudo[4638]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:48 volumio go-librespot[4628]: time="2025-10-26T08:23:48Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:48 volumio sudo[4636]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:48 volumio volumio[4427]: info: Shairport-Sync Started Oct 26 08:23:48 volumio volumio[4427]: Error adding Membership: Error: addMembership EINVAL Oct 26 08:23:48 volumio volumio[4427]: info: Shairport-Sync Started Oct 26 08:23:48 volumio volumio[4427]: info: Shairport-Sync Started Oct 26 08:23:48 volumio go-librespot[4628]: time="2025-10-26T08:23:48Z" level=debug msg="completed keyexchange" Oct 26 08:23:48 volumio go-librespot[4628]: time="2025-10-26T08:23:48Z" level=debug msg="completed challenge" Oct 26 08:23:48 volumio go-librespot[4628]: time="2025-10-26T08:23:48Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:48 volumio volumio[4427]: SPOTIFY: User informations: {"country":"DE","display_name":"lapman","email":"ylm19961214@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31hyzsop5elyyfayaiyk5tmkxmky"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31hyzsop5elyyfayaiyk5tmkxmky","id":"31hyzsop5elyyfayaiyk5tmkxmky","images":[],"product":"free","type":"user","uri":"spotify:user:31hyzsop5elyyfayaiyk5tmkxmky"} Oct 26 08:23:48 volumio volumio[4427]: info: Spotify Successfully logged in Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 08:23:48 volumio volumio[4427]: info: [1761467028595] CoreMusicLibrary::Adding element Spotify Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:23:48 volumio volumio[4427]: Cannot find translation for source Spotify Oct 26 08:23:48 volumio volumio-remote-updater[896]: [2025-10-26 08:23:48] [connect] Successful connection Oct 26 08:23:48 volumio volumio-remote-updater[896]: [2025-10-26 08:23:48] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761467028 101 Oct 26 08:23:48 volumio volumio[4427]: 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: 2 Oct 26 08:23:48 volumio mpd[4592]: 2025-10-26T08:23:48 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 26 08:23:48 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 26 08:23:48 volumio sudo[4563]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:48 volumio sudo[4553]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:48 volumio volumio[4427]: error: MPD error: The expression evaluated to a falsy value: Oct 26 08:23:48 volumio volumio[4427]: assert.ok(self.idling) Oct 26 08:23:48 volumio volumio[4427]: error: The expression evaluated to a falsy value: Oct 26 08:23:48 volumio volumio[4427]: assert.ok(self.idling) Oct 26 08:23:48 volumio volumio[4427]: info: MPD running with PID4592 Oct 26 08:23:48 volumio volumio[4427]: ,establishing connection Oct 26 08:23:48 volumio volumio[4427]: error: updateQueue error: null Oct 26 08:23:48 volumio volumio[4427]: error: updateQueue error: null Oct 26 08:23:48 volumio volumio[4427]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 08:23:48 volumio volumio[4427]: info: VolumeController:: Volume=33 Mute =false Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::volumioGetState Oct 26 08:23:48 volumio volumio[4427]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:48 volumio volumio[4427]: info: CoreStateMachine::pushState Oct 26 08:23:48 volumio volumio[4427]: info: CorePlayQueue::getTrack 0 Oct 26 08:23:48 volumio volumio[4427]: info: CoreCommandRouter::volumioPushState Oct 26 08:23:48 volumio volumio[4427]: info: Completed starting Core Plugins Oct 26 08:23:48 volumio volumio[4427]: info: ------------------------------------------- Oct 26 08:23:48 volumio volumio[4427]: info: ----- MyVolumio plugins startup ---- Oct 26 08:23:48 volumio volumio[4427]: info: ------------------------------------------- Oct 26 08:23:48 volumio volumio[4427]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 26 08:23:50 volumio volumio[4427]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 26 08:23:51 volumio volumio[4427]: info: go-librespot daemon successfully initialized Oct 26 08:23:51 volumio sudo[4667]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 26 08:23:51 volumio sudo[4667]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:51 volumio sudo[4670]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 26 08:23:51 volumio sudo[4670]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 545. Oct 26 08:23:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:51 volumio go-librespot[4672]: go-librespot daemon starting... Oct 26 08:23:51 volumio go-librespot[4673]: time="2025-10-26T08:23:51Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:51 volumio go-librespot[4673]: time="2025-10-26T08:23:51Z" level=debug msg="app state loaded" Oct 26 08:23:51 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 26 08:23:51 volumio go-librespot[4673]: time="2025-10-26T08:23:51Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:51 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 26 08:23:51 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 26 08:23:51 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 26 08:23:51 volumio mpd_monitor.sh[4679]: MPD Monitor Service: Starting MPD Monitor Service Oct 26 08:23:51 volumio sudo[4667]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:51 volumio volumio[4427]: info: Successfully started MPD Monitor Oct 26 08:23:51 volumio sudo[4670]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:51 volumio volumio[4427]: info: Successfully started MPD Monitor Oct 26 08:23:51 volumio go-librespot[4673]: time="2025-10-26T08:23:51Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:51 volumio go-librespot[4673]: time="2025-10-26T08:23:51Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:51 volumio go-librespot[4673]: time="2025-10-26T08:23:51Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:51 volumio go-librespot[4673]: time="2025-10-26T08:23:51Z" level=info msg="zeroconf server listening on port 35441" Oct 26 08:23:51 volumio go-librespot[4673]: time="2025-10-26T08:23:51Z" level=debug msg="obtained new client token: AAC6H/PUOzOvXTgJaEjWGS+0CyagHF51xYRxFLiZ31+Zm5ehov2TlU8GVDjhbFsBOpSywaHNhonaW/AQOvTRgrrkZEkCmLEdya++wD1yRSWgeXNoGyrdo4qnfR+bkKndlKaWRBE14j6elpdGuZyjxIlz0ZqB7RlbvRbwz9hroiWtsS7mZJY/+wON/m62wSLKSiRtG8tYJeIO85Di+SSEKYwc3x1aMdAf8uMujJMmbeVPM/RHqaEzuwM=" Oct 26 08:23:51 volumio go-librespot[4673]: time="2025-10-26T08:23:51Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:51 volumio go-librespot[4673]: time="2025-10-26T08:23:51Z" level=debug msg="completed keyexchange" Oct 26 08:23:51 volumio go-librespot[4673]: time="2025-10-26T08:23:51Z" level=debug msg="completed challenge" Oct 26 08:23:51 volumio go-librespot[4673]: time="2025-10-26T08:23:51Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:53 volumio volumio[4427]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 26 08:23:54 volumio volumio[4427]: info: Initializing connection to go-librespot Websocket Oct 26 08:23:54 volumio volumio[4427]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:23:55 volumio volumio[4427]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 26 08:23:55 volumio sudo[4699]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 08:23:55 volumio sudo[4699]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:55 volumio sudo[4701]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 08:23:55 volumio sudo[4701]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:55 volumio sudo[4699]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:55 volumio sudo[4701]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:55 volumio sudo[4705]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 26 08:23:55 volumio sudo[4705]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 546. Oct 26 08:23:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:55 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:55 volumio go-librespot[4707]: go-librespot daemon starting... Oct 26 08:23:55 volumio sudo[4705]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:55 volumio volumio[4427]: info: Upmpdcli Daemon Started Oct 26 08:23:55 volumio go-librespot[4708]: time="2025-10-26T08:23:55Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:55 volumio go-librespot[4708]: time="2025-10-26T08:23:55Z" level=debug msg="app state loaded" Oct 26 08:23:55 volumio go-librespot[4708]: time="2025-10-26T08:23:55Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:55 volumio go-librespot[4708]: time="2025-10-26T08:23:55Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:55 volumio go-librespot[4708]: time="2025-10-26T08:23:55Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:55 volumio go-librespot[4708]: time="2025-10-26T08:23:55Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:55 volumio go-librespot[4708]: time="2025-10-26T08:23:55Z" level=info msg="zeroconf server listening on port 34809" Oct 26 08:23:55 volumio go-librespot[4708]: time="2025-10-26T08:23:55Z" level=debug msg="obtained new client token: AAB/Wb3rrQZv3FU61XLr/i4axMLI5Z3cFR13G79ZirhdOG2LY8G6DLO5tl0SsHJgnxOWjoLDgplo1CRVK6swrYGZkwbCysNUvBkoaZeHg7gBkH8vkkMlq45C4qgDAey3U1GEgM+kstBAuO5UmbCJbU9AbpUkgzkiFjdCJT6kTR2qHzqgkU4YZZvJKHGWkvusRFXKSbb0cYUpYskE/CVQ3h15cFv7AYp6XNBUqyTHKd+xiZNFvht8880=" Oct 26 08:23:55 volumio go-librespot[4708]: time="2025-10-26T08:23:55Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:55 volumio go-librespot[4708]: time="2025-10-26T08:23:55Z" level=debug msg="completed keyexchange" Oct 26 08:23:55 volumio go-librespot[4708]: time="2025-10-26T08:23:55Z" level=debug msg="completed challenge" Oct 26 08:23:55 volumio go-librespot[4708]: time="2025-10-26T08:23:55Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 26 08:23:57 volumio volumio[4427]: info: Adding plugin bluetooth to MyMusic Plugins Oct 26 08:23:57 volumio volumio[4427]: info: Adding plugin multiroom to MyMusic Plugins Oct 26 08:23:57 volumio volumio[4427]: info: Adding plugin metavolumio to MyMusic Plugins Oct 26 08:23:57 volumio volumio[4427]: info: Adding plugin cd_controller to MyMusic Plugins Oct 26 08:23:57 volumio volumio[4427]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 26 08:23:57 volumio volumio[4427]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 26 08:23:57 volumio volumio[4427]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 26 08:23:57 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:57 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:57 volumio volumio[4427]: info: Starting MyVolumio Remote Streaming Endpoints Oct 26 08:23:57 volumio volumio[4427]: info: MyVolumio login type: Token Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 26 08:23:57 volumio volumio[4427]: info: Streaming services startup Oct 26 08:23:57 volumio volumio[4427]: info: Starting Streaming Daemon Oct 26 08:23:57 volumio sudo[4716]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 26 08:23:57 volumio sudo[4716]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:57 volumio volumio[4427]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 26 08:23:57 volumio sudo[4716]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:57 volumio volumio[4427]: info: Initializing connection to go-librespot Websocket Oct 26 08:23:57 volumio volumio[4427]: error: Cannot start Volumio Streaming Daemon Oct 26 08:23:57 volumio volumio[4427]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 26 08:23:57 volumio volumio[4427]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 26 08:23:57 volumio volumio[4427]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:23:58 volumio volumio[4427]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 26 08:23:58 volumio volumio[4427]: info: MyVolumio token set successfully Oct 26 08:23:58 volumio volumio[4427]: info: MYVOLUMIO: Adding device Oct 26 08:23:58 volumio volumio[4427]: info: MYVOLUMIO: Evaluating Server Oct 26 08:23:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 547. Oct 26 08:23:58 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:58 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:23:58 volumio go-librespot[4725]: go-librespot daemon starting... Oct 26 08:23:58 volumio go-librespot[4726]: time="2025-10-26T08:23:58Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:23:58 volumio go-librespot[4726]: time="2025-10-26T08:23:58Z" level=debug msg="app state loaded" Oct 26 08:23:58 volumio go-librespot[4726]: time="2025-10-26T08:23:58Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:23:58 volumio volumio[4427]: info: MyVolumio status changed Oct 26 08:23:58 volumio volumio[4427]: info: Streaming services startup Oct 26 08:23:58 volumio volumio[4427]: info: Starting Streaming Daemon Oct 26 08:23:58 volumio volumio[4427]: info: Removing browser output: myVolumio user plan is not superstar Oct 26 08:23:58 volumio volumio[4427]: info: Removing audio output: Oct 26 08:23:58 volumio volumio[4427]: info: Stoppping Tunnel 1 Oct 26 08:23:58 volumio sudo[4749]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 26 08:23:58 volumio sudo[4749]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:58 volumio sudo[4751]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 26 08:23:58 volumio sudo[4751]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:23:58 volumio go-librespot[4726]: time="2025-10-26T08:23:58Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:23:58 volumio go-librespot[4726]: time="2025-10-26T08:23:58Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:23:58 volumio go-librespot[4726]: time="2025-10-26T08:23:58Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:23:58 volumio go-librespot[4726]: time="2025-10-26T08:23:58Z" level=info msg="zeroconf server listening on port 40551" Oct 26 08:23:58 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. Oct 26 08:23:58 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. Oct 26 08:23:58 volumio sudo[4749]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:58 volumio volumio[4427]: error: Cannot start Volumio Streaming Daemon Oct 26 08:23:58 volumio volumio[4427]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 26 08:23:58 volumio volumio[4427]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 26 08:23:58 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. Oct 26 08:23:58 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. Oct 26 08:23:58 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. Oct 26 08:23:58 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. Oct 26 08:23:58 volumio sudo[4751]: pam_unix(sudo:session): session closed for user root Oct 26 08:23:58 volumio volumio[4427]: info: Remote SSH Stopped Oct 26 08:23:58 volumio go-librespot[4726]: time="2025-10-26T08:23:58Z" level=debug msg="obtained new client token: AADQZSq02B9ouJEjeudhV0AZ1Dyazh9iEn+dyNR8WVRS7rlDeIwLNs5o+H1kiGb2SVR97QCOgG5PcQbCMolJ0469hzIZgpdmJ9b0jPv9tWDTvJRRczjlbvvjj5f/73aCbF7tTwbUjh7ly2/X5jfqk53w6KKuO/dlhUrDk+I8fv3QJ863mSdwko8kyYkiOWuTH34Of59/wKHfhowzZ6oDQ9cCR21XSR5+fWxWxVd/0RmV5En8GqOfi0o=" Oct 26 08:23:58 volumio go-librespot[4726]: time="2025-10-26T08:23:58Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:23:58 volumio go-librespot[4726]: time="2025-10-26T08:23:58Z" level=debug msg="completed keyexchange" Oct 26 08:23:58 volumio go-librespot[4726]: time="2025-10-26T08:23:58Z" level=debug msg="completed challenge" Oct 26 08:23:59 volumio go-librespot[4726]: time="2025-10-26T08:23:59Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:23:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:23:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:23:59 volumio volumio[4427]: info: Setting Geolocation for MyVolumio to eu3 Oct 26 08:23:59 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:59 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:59 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:23:59 volumio volumio[4427]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 26 08:24:00 volumio volumio[4427]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 26 08:24:00 volumio volumio[4427]: info: Updating MyVolumio device info Oct 26 08:24:00 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:00 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:00 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:00 volumio volumio[4427]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 26 08:24:00 volumio volumio[4427]: info: Initializing connection to go-librespot Websocket Oct 26 08:24:00 volumio volumio[4427]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:24:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 548. Oct 26 08:24:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:02 volumio go-librespot[4754]: go-librespot daemon starting... Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=debug msg="app state loaded" Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=info msg="zeroconf server listening on port 39855" Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=debug msg="obtained new client token: AADjMG1iAanKLyx5poYUTZ/t+txt5RzTbtYgq7VUdFHbsAur3dVNavrBS7iVJWoOPD2cIwQVooVm/MlhGhwtMrtnONeyta2a7mxQ+dvHNifGDdLbkeqxiGtNqvaMaemsAi7xBmtsShjDMy2ePB4WNO+4aa2qR1g+NptOmoksqW3uD58iDfMvl+cI3wkkyFGHIk/m3AB8WTZvkZHgCC+GheQfp2j430WkRJ8bnKh6BtK7nqmPoE77wwc=" Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.65.9:4070: connect: connection refused" Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=debug msg="connected to ap-gew1.spotify.com:443" Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=debug msg="completed keyexchange" Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=debug msg="completed challenge" Oct 26 08:24:02 volumio go-librespot[4755]: time="2025-10-26T08:24:02Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:24:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:24:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:24:03 volumio volumio[4427]: info: MYVOLUMIO: Adding device Oct 26 08:24:03 volumio volumio[4427]: info: MYVOLUMIO: Evaluating Server Oct 26 08:24:03 volumio volumio[4427]: info: Setting Geolocation for MyVolumio to eu3 Oct 26 08:24:03 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:03 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:03 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:03 volumio volumio[4427]: info: Initializing connection to go-librespot Websocket Oct 26 08:24:03 volumio volumio[4427]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:24:04 volumio volumio[4427]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 26 08:24:04 volumio volumio[4427]: info: Updating MyVolumio device info Oct 26 08:24:04 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:04 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:04 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:05 volumio volumio[4427]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Oct 26 08:24:05 volumio volumio[4427]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 26 08:24:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 549. Oct 26 08:24:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:05 volumio go-librespot[4791]: go-librespot daemon starting... Oct 26 08:24:05 volumio go-librespot[4792]: time="2025-10-26T08:24:05Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:24:05 volumio go-librespot[4792]: time="2025-10-26T08:24:05Z" level=debug msg="app state loaded" Oct 26 08:24:05 volumio go-librespot[4792]: time="2025-10-26T08:24:05Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:24:05 volumio go-librespot[4792]: time="2025-10-26T08:24:05Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:24:05 volumio go-librespot[4792]: time="2025-10-26T08:24:05Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:24:05 volumio go-librespot[4792]: time="2025-10-26T08:24:05Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:24:05 volumio go-librespot[4792]: time="2025-10-26T08:24:05Z" level=info msg="zeroconf server listening on port 42799" Oct 26 08:24:05 volumio go-librespot[4792]: time="2025-10-26T08:24:05Z" level=debug msg="obtained new client token: AACnM7PBIReAqPwvH3QvXKasORpL1OGVmHZNA9kDFc9Y3Tcau525SkP1k5hbaZkurF17gH2OBwLK4mjGbEMPrQIv7YhDMWWmZxzpwwue5zRPZMpUt3s/Tfo4m+M5/ZH47tJtfPOn46OBqem7luA2WdJjJ/nYPTc0of+IWlRfVSZRwE3YU09i+3+56qNRXcPkF8rv922Bj+mxnUVr5TS72LSDaXs3+hg6tAIm6dKKKAl//ti3+lWz9XU=" Oct 26 08:24:05 volumio go-librespot[4792]: time="2025-10-26T08:24:05Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:24:05 volumio go-librespot[4792]: time="2025-10-26T08:24:05Z" level=debug msg="completed keyexchange" Oct 26 08:24:05 volumio go-librespot[4792]: time="2025-10-26T08:24:05Z" level=debug msg="completed challenge" Oct 26 08:24:05 volumio go-librespot[4792]: time="2025-10-26T08:24:05Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:24:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:24:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:24:06 volumio volumio[4427]: info: Initializing connection to go-librespot Websocket Oct 26 08:24:06 volumio volumio[4427]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:24:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 550. Oct 26 08:24:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:09 volumio go-librespot[4800]: go-librespot daemon starting... Oct 26 08:24:09 volumio go-librespot[4801]: time="2025-10-26T08:24:09Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:24:09 volumio go-librespot[4801]: time="2025-10-26T08:24:09Z" level=debug msg="app state loaded" Oct 26 08:24:09 volumio go-librespot[4801]: time="2025-10-26T08:24:09Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:24:09 volumio go-librespot[4801]: time="2025-10-26T08:24:09Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:24:09 volumio go-librespot[4801]: time="2025-10-26T08:24:09Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:24:09 volumio go-librespot[4801]: time="2025-10-26T08:24:09Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:24:09 volumio go-librespot[4801]: time="2025-10-26T08:24:09Z" level=info msg="zeroconf server listening on port 34449" Oct 26 08:24:09 volumio go-librespot[4801]: time="2025-10-26T08:24:09Z" level=debug msg="obtained new client token: AAAB3MUEa+oaVIAiDwngkRdGxS5zu4O+kWrrIViqwNgw1fen/XKVgeaLkXqN/KwkgJKL4P86ak//tUvoqI9kUNSMkehRBmo0wL8erb4NPB9GuraB0NA3Jnq7ZxkW2ZApIN6gPrMBs+J5yuyoGQ8cRONu1GPjEW425gDdr5vVzJkdqDLvrAkULRCCMcrgsbXCgFJhQ/rr6f3b2aWgyv4xqhEAQkHVy2rf3IE9EqlWSLilxz3z3ucjRl8=" Oct 26 08:24:09 volumio go-librespot[4801]: time="2025-10-26T08:24:09Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:24:09 volumio go-librespot[4801]: time="2025-10-26T08:24:09Z" level=debug msg="completed keyexchange" Oct 26 08:24:09 volumio go-librespot[4801]: time="2025-10-26T08:24:09Z" level=debug msg="completed challenge" Oct 26 08:24:09 volumio go-librespot[4801]: time="2025-10-26T08:24:09Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:24:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:24:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:24:09 volumio volumio[4427]: info: Initializing connection to go-librespot Websocket Oct 26 08:24:09 volumio volumio[4427]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:24:12 volumio volumio[4427]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 26 08:24:12 volumio volumio[4427]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 26 08:24:12 volumio volumio[4427]: info: CoreCommandRouter::volumioGetState Oct 26 08:24:12 volumio volumio[4427]: info: CorePlayQueue::getTrack 0 Oct 26 08:24:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 551. Oct 26 08:24:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:12 volumio go-librespot[4811]: go-librespot daemon starting... Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=debug msg="app state loaded" Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=info msg="zeroconf server listening on port 43541" Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=debug msg="obtained new client token: AADS8FHPPbhuosK+2kGHgmnbLu8kMo6AiMLjX6B9SDYn4I+oSMtjUscRQwO+F8HsxE50wTujhcxYocxMoRYAJE8KaS7tQNBqHH0YtCy7HbWVCOnRQgDksYyGZCg+o46jHXFWLgzewGGTZx50Cjth90Dawfn7iktW1zyqu7x6T9G07IQ3kH19ZG/4acKxaGVYYmflqdvqISb4S/AL9LJvnjyYw876RhVZjdFoBlqsbzgUOSoanmdv2zw=" Oct 26 08:24:12 volumio volumio[4427]: info: Initializing connection to go-librespot Websocket Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=debug msg="new websocket client" Oct 26 08:24:12 volumio volumio[4427]: info: Connection to go-librespot Websocket established Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=debug msg="completed keyexchange" Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=debug msg="completed challenge" Oct 26 08:24:12 volumio go-librespot[4812]: time="2025-10-26T08:24:12Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:24:12 volumio volumio[4427]: info: Connection to go-librespot Websocket closed Oct 26 08:24:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:24:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:24:15 volumio volumio[4427]: info: Getting Spotify volume Oct 26 08:24:15 volumio volumio[4427]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 08:24:15 volumio volumio[4427]: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:24:15 volumio volumio[4427]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 26 08:24:15 volumio volumio[4427]: errno: -111, Oct 26 08:24:15 volumio volumio[4427]: code: 'ECONNREFUSED', Oct 26 08:24:15 volumio volumio[4427]: syscall: 'connect', Oct 26 08:24:15 volumio volumio[4427]: address: '127.0.0.1', Oct 26 08:24:15 volumio volumio[4427]: port: 9879, Oct 26 08:24:15 volumio volumio[4427]: response: undefined Oct 26 08:24:15 volumio volumio[4427]: } Oct 26 08:24:15 volumio volumio[4427]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 08:24:16 volumio sudo[4847]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-26 08:23' Oct 26 08:24:16 volumio sudo[4847]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 552. Oct 26 08:24:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:16 volumio sudo[4847]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:16 volumio go-librespot[4849]: go-librespot daemon starting... Oct 26 08:24:16 volumio go-librespot[4854]: time="2025-10-26T08:24:16Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:24:16 volumio go-librespot[4854]: time="2025-10-26T08:24:16Z" level=debug msg="app state loaded" Oct 26 08:24:16 volumio go-librespot[4854]: time="2025-10-26T08:24:16Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:24:16 volumio volumio-remote-updater[896]: [2025-10-26 08:24:16] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 26 08:24:16 volumio volumio-remote-updater[896]: [2025-10-26 08:24:16] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 26 08:24:16 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:24:16 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 26 08:24:16 volumio systemd[1]: volumio.service: Consumed 11.476s CPU time. Oct 26 08:24:16 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 26 08:24:16 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 26 08:24:16 volumio go-librespot[4854]: time="2025-10-26T08:24:16Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:24:16 volumio go-librespot[4854]: time="2025-10-26T08:24:16Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:24:16 volumio go-librespot[4854]: time="2025-10-26T08:24:16Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:24:16 volumio go-librespot[4854]: time="2025-10-26T08:24:16Z" level=info msg="zeroconf server listening on port 45441" Oct 26 08:24:16 volumio go-librespot[4854]: time="2025-10-26T08:24:16Z" level=debug msg="obtained new client token: AADt00/W1sqqPkC0EEl9UIqt+XI/I428yWwhqePLhSEl8A6vdryouxk8ghdVRPJJ/je66t6CIbZkPTfAWVhI5q6mQJeK3hwB6TMvQhLkV4LVzb4/gOc50LZFCFsCFLvzH6UhoNsefSP1i15a0yW7230D3TXQWFK+UpS8q2LFeLEXwx3adsCIW9nWF0xvC+3GlZKtY5oaTJLzlJWThmJTzlEtZEN2fC4rqzroWzmUx8N6TyionYyWR2c=" Oct 26 08:24:16 volumio go-librespot[4854]: time="2025-10-26T08:24:16Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:24:16 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 6751. Oct 26 08:24:16 volumio go-librespot[4854]: time="2025-10-26T08:24:16Z" level=debug msg="completed keyexchange" Oct 26 08:24:16 volumio go-librespot[4854]: time="2025-10-26T08:24:16Z" level=debug msg="completed challenge" Oct 26 08:24:16 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Oct 26 08:24:16 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Oct 26 08:24:16 volumio systemd[1]: volumio.service: Consumed 11.476s CPU time. Oct 26 08:24:16 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Oct 26 08:24:16 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Oct 26 08:24:16 volumio go-librespot[4854]: time="2025-10-26T08:24:16Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:24:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:24:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:24:16 volumio volumio[4871]: info: ------------------------------------------- Oct 26 08:24:16 volumio volumio[4871]: info: ----- Volumio3 ---- Oct 26 08:24:16 volumio volumio[4871]: info: ------------------------------------------- Oct 26 08:24:16 volumio volumio[4871]: info: ----- System startup ---- Oct 26 08:24:16 volumio volumio[4871]: info: ------------------------------------------- Oct 26 08:24:17 volumio volumio[4871]: info: MYVOLUMIO Environment detected Oct 26 08:24:17 volumio volumio[4871]: info: Plugin folders cleanup Oct 26 08:24:17 volumio volumio[4871]: info: Scanning into folder /volumio/app/plugins/ Oct 26 08:24:17 volumio volumio[4871]: info: Scanning category audio_interface Oct 26 08:24:17 volumio volumio[4871]: info: Scanning category miscellanea Oct 26 08:24:17 volumio volumio[4871]: info: Scanning category music_service Oct 26 08:24:17 volumio volumio[4871]: info: Scanning category plugins.json Oct 26 08:24:17 volumio volumio[4871]: info: Scanning category system_controller Oct 26 08:24:17 volumio volumio[4871]: info: Scanning category user_interface Oct 26 08:24:17 volumio volumio[4871]: info: Scanning into folder /data/plugins/ Oct 26 08:24:17 volumio volumio[4871]: info: Scanning category music_service Oct 26 08:24:17 volumio volumio[4871]: info: Scanning category user_interface Oct 26 08:24:17 volumio volumio[4871]: info: Plugin folders cleanup completed Oct 26 08:24:17 volumio volumio[4871]: info: ------------------------------------------- Oct 26 08:24:17 volumio volumio[4871]: info: ----- Core plugins startup ---- Oct 26 08:24:17 volumio volumio[4871]: info: ------------------------------------------- Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugins from folder /volumio/app/plugins/ Oct 26 08:24:17 volumio volumio[4871]: info: Adding plugin upnp to MyMusic Plugins Oct 26 08:24:17 volumio volumio[4871]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 26 08:24:17 volumio volumio[4871]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugins from folder /data/plugins/ Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugin "system"... Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugin "appearance"... Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugin "network"... Oct 26 08:24:17 volumio volumio[4871]: info: Refreshing Cached IP Addresses Oct 26 08:24:17 volumio sudo[4899]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 08:24:17 volumio sudo[4899]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:17 volumio sudo[4899]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:17 volumio sudo[4901]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 08:24:17 volumio sudo[4901]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugin "services"... Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugin "alsa_controller"... Oct 26 08:24:17 volumio sudo[4901]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:17 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugin "wizard"... Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugin "networkfs"... Oct 26 08:24:17 volumio volumio[4871]: info: Cannot mount NAS NAS at system boot, trial number 1 ,retrying in 5 seconds Oct 26 08:24:17 volumio volumio[4871]: info: Starting Udev Watcher for removable devices Oct 26 08:24:17 volumio volumio[4871]: info: Ignoring mount for partition: boot Oct 26 08:24:17 volumio volumio[4871]: info: Ignoring mount for partition: volumio Oct 26 08:24:17 volumio volumio[4871]: info: Ignoring mount for partition: volumio_data Oct 26 08:24:17 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugin "volumio_command_line_client"... Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugin "upnp"... Oct 26 08:24:17 volumio volumio[4871]: info: [1761467057592] Starting Upmpd Daemon Oct 26 08:24:17 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugin "my_music"... Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugin "mpd"... Oct 26 08:24:17 volumio volumio[4871]: info: Loading plugin "upnp_browser"... Oct 26 08:24:18 volumio volumio[4871]: info: Loading plugin "alarm-clock"... Oct 26 08:24:18 volumio volumio[4871]: info: Loading plugin "airplay_emulation"... Oct 26 08:24:18 volumio volumio[4871]: info: Starting Shairport Sync Oct 26 08:24:18 volumio volumio[4871]: info: Loading plugin "last_100"... Oct 26 08:24:18 volumio volumio[4871]: info: Loading plugin "webradio"... Oct 26 08:24:18 volumio volumio[4871]: info: Loading plugin "i2s_dacs"... Oct 26 08:24:18 volumio volumio[4871]: info: I2S DAC not set, start Auto-detection Oct 26 08:24:18 volumio volumio[4871]: info: Loading plugin "volumiodiscovery"... Oct 26 08:24:18 volumio volumio[4871]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 08:24:18 volumio volumio[4871]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 08:24:18 volumio volumio[4871]: *** WARNING *** For more information see Oct 26 08:24:18 volumio volumio[4871]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 08:24:18 volumio volumio[4871]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 08:24:18 volumio volumio[4871]: *** WARNING *** For more information see Oct 26 08:24:18 volumio node[4871]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 08:24:18 volumio node[4871]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 08:24:18 volumio node[4871]: *** WARNING *** For more information see Oct 26 08:24:18 volumio node[4871]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 08:24:18 volumio node[4871]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 08:24:18 volumio node[4871]: *** WARNING *** For more information see Oct 26 08:24:18 volumio volumio[4871]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 26 08:24:18 volumio volumio[4871]: info: Discovery: Started advertising with name: Volumio Oct 26 08:24:18 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 08:24:18 volumio volumio[4871]: info: Loading plugin "spop"... Oct 26 08:24:18 volumio volumio[4871]: info: Loading plugin "ytcr"... Oct 26 08:24:19 volumio volumio[4871]: info: Loading plugin "outputs"... Oct 26 08:24:19 volumio volumio[4871]: info: Loading plugin "albumart"... Oct 26 08:24:19 volumio volumio[4871]: info: Plugin example_plugin is not enabled Oct 26 08:24:19 volumio volumio[4871]: info: Loading plugin "inputs"... Oct 26 08:24:19 volumio volumio[4871]: info: Loading plugin "updater_comm"... Oct 26 08:24:19 volumio volumio[4871]: info: Plugin mpdemulation is not enabled Oct 26 08:24:19 volumio volumio[4871]: info: Loading plugin "rest_api"... Oct 26 08:24:19 volumio volumio[4871]: info: Loading plugin "websocket"... Oct 26 08:24:19 volumio volumio[4871]: info: Starting Socket.io Server version 1.7.4 Oct 26 08:24:19 volumio volumio[4871]: info: Loading plugin "Systeminfo"... Oct 26 08:24:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 553. Oct 26 08:24:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:19 volumio go-librespot[4941]: go-librespot daemon starting... Oct 26 08:24:19 volumio go-librespot[4942]: time="2025-10-26T08:24:19Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:24:19 volumio go-librespot[4942]: time="2025-10-26T08:24:19Z" level=debug msg="app state loaded" Oct 26 08:24:19 volumio go-librespot[4942]: time="2025-10-26T08:24:19Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:24:19 volumio volumio[4871]: info: Loading i18n strings for locale en Oct 26 08:24:19 volumio volumio[4871]: Updating browse sources language Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:24:19 volumio volumio[4931]: Forking 3 albumart workers Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::initPlayerControls Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 08:24:19 volumio volumio[4871]: Express server listening on port 3000 Oct 26 08:24:19 volumio volumio[4871]: [Metrics] WebUI: 2s 957.04ms Oct 26 08:24:19 volumio volumio[4871]: info: CoreStateMachine::resetVolumioState Oct 26 08:24:19 volumio volumio[4871]: info: CoreStateMachine::getcurrentVolume Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 08:24:19 volumio go-librespot[4942]: time="2025-10-26T08:24:19Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 26 08:24:19 volumio go-librespot[4942]: time="2025-10-26T08:24:19Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 26 08:24:19 volumio go-librespot[4942]: time="2025-10-26T08:24:19Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:19 volumio go-librespot[4942]: time="2025-10-26T08:24:19Z" level=info msg="zeroconf server listening on port 36977" Oct 26 08:24:19 volumio volumio[4871]: info: Cannot read play queue from file Oct 26 08:24:19 volumio volumio[4871]: info: Volumio Network Manager: Network status updated: 1 Oct 26 08:24:19 volumio volumio[4871]: info: CoreStateMachine::setRepeat null single undefined Oct 26 08:24:19 volumio volumio[4871]: info: CoreStateMachine::pushState Oct 26 08:24:19 volumio volumio[4871]: info: CorePlayQueue::getTrack 0 Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::volumioPushState Oct 26 08:24:19 volumio volumio[4871]: info: CoreStateMachine::setRandom null Oct 26 08:24:19 volumio volumio[4871]: info: CoreStateMachine::pushState Oct 26 08:24:19 volumio volumio[4871]: info: CorePlayQueue::getTrack 0 Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::volumioPushState Oct 26 08:24:19 volumio volumio[4871]: info: VolumeController:: Volume=33 Mute =false Oct 26 08:24:19 volumio volumio[4871]: info: CoreStateMachine::pushState Oct 26 08:24:19 volumio volumio[4871]: info: CorePlayQueue::getTrack 0 Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::volumioPushState Oct 26 08:24:19 volumio volumio[4871]: info: CoreStateMachine::updateTrackBlock Oct 26 08:24:19 volumio volumio[4871]: info: CorePlayQueue::getTrackBlock Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 08:24:19 volumio go-librespot[4942]: time="2025-10-26T08:24:19Z" level=debug msg="obtained new client token: AABGtW3qf+IvKIE2yzDchd+gjH/6T+H1Qp4709+SKWpo8DqLF2Y1hdCn+vkm0eninULmyDHDvcGgqXAJ+b6ZyG+sRN4jd4YKoq6fvE+lWf+fWj5t6WhYWl7cKlMmakcolUH7eisBmNKbysxOGmNL1A5oEbuW735vAEpu3to4fHZhYDe7OrjhN6EOEE9kB/wxbdmyuaGYsMXYIVFvOoIybPNT8vb9sftkbM+tUSIXT+MQ6m1N65fR09Y=" Oct 26 08:24:19 volumio volumio[4871]: info: Setting Device type: Raspberry PI Oct 26 08:24:19 volumio volumio[4871]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 26 08:24:19 volumio volumio[4871]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b04170 Oct 26 08:24:19 volumio volumio[4871]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 26 08:24:19 volumio go-librespot[4942]: time="2025-10-26T08:24:19Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:24:19 volumio volumio[4871]: info: Discovery: adding 70853f74-8210-4683-a3fa-e1217517bd40 Oct 26 08:24:19 volumio volumio[4871]: info: Discovery: Found device Volumio Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::volumioGetState Oct 26 08:24:19 volumio volumio[4871]: info: CorePlayQueue::getTrack 0 Oct 26 08:24:19 volumio volumio[4871]: info: Discovery: this is already registered, 70853f74-8210-4683-a3fa-e1217517bd40 Oct 26 08:24:19 volumio volumio[4871]: info: Discovery: Found device Volumio Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::volumioGetState Oct 26 08:24:19 volumio volumio[4871]: info: CorePlayQueue::getTrack 0 Oct 26 08:24:19 volumio go-librespot[4942]: time="2025-10-26T08:24:19Z" level=debug msg="completed keyexchange" Oct 26 08:24:19 volumio go-librespot[4942]: time="2025-10-26T08:24:19Z" level=debug msg="completed challenge" Oct 26 08:24:19 volumio volumio[4871]: info: Completed loading Core Plugins Oct 26 08:24:19 volumio volumio[4871]: info: Preparing to generate the ALSA configuration file Oct 26 08:24:19 volumio volumio[4871]: info: VolumeController:: Volume=33 Mute =false Oct 26 08:24:19 volumio volumio[4871]: info: CoreStateMachine::pushState Oct 26 08:24:19 volumio volumio[4871]: info: CorePlayQueue::getTrack 0 Oct 26 08:24:19 volumio volumio[4871]: info: CoreCommandRouter::volumioPushState Oct 26 08:24:20 volumio go-librespot[4942]: time="2025-10-26T08:24:20Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:24:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:24:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:24:20 volumio volumio[4871]: info: Asound.conf file unchanged, so no further update is needed Oct 26 08:24:20 volumio volumio[4871]: info: Output device has changed, restarting MPD Oct 26 08:24:20 volumio volumio[4871]: info: Output device has changed, restarting Shairport Sync Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:20 volumio sudo[4997]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 08:24:20 volumio sudo[4997]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:20 volumio sudo[4999]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 08:24:20 volumio sudo[4999]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:20 volumio sudo[4997]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:20 volumio volumio[4871]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 08:24:20 volumio volumio[4871]: info: ___________ START PLUGINS ___________ Oct 26 08:24:20 volumio volumio[4871]: info: ControllerMpd::onStart: Initializing MPD Oct 26 08:24:20 volumio volumio[4871]: info: Creating MPD Configuration file Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 08:24:20 volumio volumio[4871]: info: [1761467060092] CoreMusicLibrary::Adding element Media Servers Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:24:20 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Oct 26 08:24:20 volumio sudo[5007]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 08:24:20 volumio sudo[5007]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:20 volumio sudo[5007]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:20 volumio sudo[5009]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 08:24:20 volumio sudo[5009]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:20 volumio systemd[1]: mpd.service: Deactivated successfully. Oct 26 08:24:20 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Oct 26 08:24:20 volumio volumio[4871]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:20 volumio systemd[1]: mpd.socket: Deactivated successfully. Oct 26 08:24:20 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Oct 26 08:24:20 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Oct 26 08:24:20 volumio volumio[4871]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 08:24:20 volumio volumio[4871]: info: [1761467060148] CoreMusicLibrary::Adding element Last_100 Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 08:24:20 volumio volumio[4871]: info: [1761467060150] CoreMusicLibrary::Adding element Webradio Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 08:24:20 volumio volumio[4871]: info: Initializing BBC Radios Oct 26 08:24:20 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Oct 26 08:24:20 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Oct 26 08:24:20 volumio sudo[5023]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 26 08:24:20 volumio sudo[5023]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 26 08:24:20 volumio sudo[5023]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: Creating Spotify config file Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4950]: Starting albumart workers Oct 26 08:24:20 volumio volumio[4949]: Starting albumart workers Oct 26 08:24:20 volumio volumio[4951]: Starting albumart workers Oct 26 08:24:20 volumio volumio[4871]: info: Volumio Calling Home Oct 26 08:24:20 volumio volumio[4871]: info: MPD Permissions set Oct 26 08:24:20 volumio volumio[4871]: info: MPD Permissions set Oct 26 08:24:20 volumio volumio[4871]: info: Spotify config file written Oct 26 08:24:20 volumio sudo[5059]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 26 08:24:20 volumio sudo[5059]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:20 volumio volumio[4871]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 08:24:20 volumio volumio[4871]: info: No need to fix Spotify hosts Oct 26 08:24:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:20 volumio go-librespot[5066]: go-librespot daemon starting... Oct 26 08:24:20 volumio sudo[5059]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:20 volumio go-librespot[5072]: time="2025-10-26T08:24:20Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:24:20 volumio go-librespot[5072]: time="2025-10-26T08:24:20Z" level=debug msg="app state loaded" Oct 26 08:24:20 volumio go-librespot[5072]: time="2025-10-26T08:24:20Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:24:20 volumio volumio[4871]: info: Volumio called home Oct 26 08:24:20 volumio volumio[4871]: info: Starting Shairport Sync Oct 26 08:24:20 volumio volumio[4871]: info: Starting Shairport Sync Oct 26 08:24:20 volumio volumio[4871]: info: Starting Shairport Sync Oct 26 08:24:20 volumio sudo[5081]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 08:24:20 volumio sudo[5079]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 08:24:20 volumio sudo[5081]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:20 volumio sudo[5079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:20 volumio sudo[5085]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 08:24:20 volumio sudo[5085]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:20 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 26 08:24:20 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Oct 26 08:24:20 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 26 08:24:20 volumio systemd[1]: shairport-sync.service: Consumed 1.571s CPU time. Oct 26 08:24:20 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 26 08:24:20 volumio sudo[5081]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:20 volumio sudo[5079]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:20 volumio sudo[5085]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:20 volumio go-librespot[5072]: time="2025-10-26T08:24:20Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:24:20 volumio go-librespot[5072]: time="2025-10-26T08:24:20Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:24:20 volumio go-librespot[5072]: time="2025-10-26T08:24:20Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:24:20 volumio go-librespot[5072]: time="2025-10-26T08:24:20Z" level=info msg="zeroconf server listening on port 40005" Oct 26 08:24:20 volumio volumio[4871]: info: Shairport-Sync Started Oct 26 08:24:20 volumio volumio[4871]: Error adding Membership: Error: addMembership EINVAL Oct 26 08:24:20 volumio volumio[4871]: info: Shairport-Sync Started Oct 26 08:24:20 volumio volumio[4871]: info: Shairport-Sync Started Oct 26 08:24:20 volumio volumio[4871]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 08:24:20 volumio volumio[4871]: SPOTIFY: BQDlEVrp0HxJkCp4YYx8UVGKrz32DHiamErPBNRzcbFx7DQ2rFcIldN5-kmZLiq7icuA5GVk2Xwwha-sM_ZgIbjQo6-aoraTCuPJrxrZ0H5pSI6e9DyqO-6Ki-eIdpBapFmlApLSePzM7HM9SWXbu_hXCtRfo2OKqq8UH6HfZK9NEuVyALFsUPp6OY7CFxm5zXErUEIulsOJLdWXHewtJzxWDQqynm_FqtFeH8nc4mFTkTzqhU9IgfvWPI1K9QGTfJh7iSBbUcZ1EZ1WvwUXQ74oKin5jf2J18GGi1f6l4hPv17TBmM Oct 26 08:24:20 volumio volumio[4871]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 08:24:20 volumio volumio[4871]: info: New Spotify access token = BQDlEVrp0HxJkCp4YYx8UVGKrz32DHiamErPBNRzcbFx7DQ2rFcIldN5-kmZLiq7icuA5GVk2Xwwha-sM_ZgIbjQo6-aoraTCuPJrxrZ0H5pSI6e9DyqO-6Ki-eIdpBapFmlApLSePzM7HM9SWXbu_hXCtRfo2OKqq8UH6HfZK9NEuVyALFsUPp6OY7CFxm5zXErUEIulsOJLdWXHewtJzxWDQqynm_FqtFeH8nc4mFTkTzqhU9IgfvWPI1K9QGTfJh7iSBbUcZ1EZ1WvwUXQ74oKin5jf2J18GGi1f6l4hPv17TBmM Oct 26 08:24:20 volumio volumio[4871]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 26 08:24:20 volumio volumio[4871]: info: CoreCommandRouter::volumioGetState Oct 26 08:24:20 volumio volumio[4871]: info: CorePlayQueue::getTrack 0 Oct 26 08:24:20 volumio go-librespot[5072]: time="2025-10-26T08:24:20Z" level=debug msg="obtained new client token: AABgg8pExSREyOmPXGgrxw5rtFroC/CGDhJYKXHW67Z8Vnjie/5ACPM/A/B2AQKuLyIYc1nYCEHcGNOHocbMO2dUqXxov2nOOjgKJw3SxCC7A4vcXtnZaJGoltQnoXoLpI+MCo64Uiqq4pMWNk8zxsF0+1kQa6sA+NtM2aywPnE/z2HLWNA87eLvmnDH0Bu7xQQtLp9LYLk3/JP0PqDZPFXkK05Ke373szWxmUEJK9J8dlq8EgnYZtY=" Oct 26 08:24:21 volumio go-librespot[5072]: time="2025-10-26T08:24:21Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:24:21 volumio mpd[5036]: 2025-10-26T08:24:21 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 26 08:24:21 volumio systemd[1]: Started mpd.service - Music Player Daemon. Oct 26 08:24:21 volumio sudo[5009]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:21 volumio sudo[4999]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:21 volumio go-librespot[5072]: time="2025-10-26T08:24:21Z" level=debug msg="completed keyexchange" Oct 26 08:24:21 volumio go-librespot[5072]: time="2025-10-26T08:24:21Z" level=debug msg="completed challenge" Oct 26 08:24:21 volumio go-librespot[5072]: time="2025-10-26T08:24:21Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:24:21 volumio volumio[4871]: error: MPD error: The expression evaluated to a falsy value: Oct 26 08:24:21 volumio volumio[4871]: assert.ok(self.idling) Oct 26 08:24:21 volumio volumio[4871]: error: The expression evaluated to a falsy value: Oct 26 08:24:21 volumio volumio[4871]: assert.ok(self.idling) Oct 26 08:24:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:24:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:24:21 volumio volumio[4871]: error: updateQueue error: null Oct 26 08:24:21 volumio volumio[4871]: info: MPD running with PID5036 Oct 26 08:24:21 volumio volumio[4871]: ,establishing connection Oct 26 08:24:21 volumio volumio[4871]: error: updateQueue error: null Oct 26 08:24:21 volumio volumio[4871]: SPOTIFY: User informations: {"country":"DE","display_name":"lapman","email":"ylm19961214@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31hyzsop5elyyfayaiyk5tmkxmky"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31hyzsop5elyyfayaiyk5tmkxmky","id":"31hyzsop5elyyfayaiyk5tmkxmky","images":[],"product":"free","type":"user","uri":"spotify:user:31hyzsop5elyyfayaiyk5tmkxmky"} Oct 26 08:24:21 volumio volumio[4871]: info: Spotify Successfully logged in Oct 26 08:24:21 volumio volumio[4871]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 08:24:21 volumio volumio[4871]: info: [1761467061096] CoreMusicLibrary::Adding element Spotify Oct 26 08:24:21 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 08:24:21 volumio volumio[4871]: Cannot find translation for source Spotify Oct 26 08:24:21 volumio volumio-remote-updater[896]: [2025-10-26 08:24:21] [connect] Successful connection Oct 26 08:24:21 volumio volumio-remote-updater[896]: [2025-10-26 08:24:21] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761467061 101 Oct 26 08:24:21 volumio volumio[4871]: 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: 2 Oct 26 08:24:21 volumio volumio[4871]: info: [yt-cast-receiver] DIAL server listening on port 8098 Oct 26 08:24:21 volumio volumio[4871]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 08:24:21 volumio volumio[4871]: info: VolumeController:: Volume=33 Mute =false Oct 26 08:24:21 volumio volumio[4871]: info: CoreCommandRouter::volumioGetState Oct 26 08:24:21 volumio volumio[4871]: info: CorePlayQueue::getTrack 0 Oct 26 08:24:21 volumio volumio[4871]: info: CoreStateMachine::pushState Oct 26 08:24:21 volumio volumio[4871]: info: CorePlayQueue::getTrack 0 Oct 26 08:24:21 volumio volumio[4871]: info: CoreCommandRouter::volumioPushState Oct 26 08:24:21 volumio volumio[4871]: info: Completed starting Core Plugins Oct 26 08:24:21 volumio volumio[4871]: info: ------------------------------------------- Oct 26 08:24:21 volumio volumio[4871]: info: ----- MyVolumio plugins startup ---- Oct 26 08:24:21 volumio volumio[4871]: info: ------------------------------------------- Oct 26 08:24:21 volumio volumio[4871]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 26 08:24:22 volumio volumio[4871]: info: Cannot mount NAS NAS at system boot, trial number 2 ,retrying in 5 seconds Oct 26 08:24:23 volumio volumio[4871]: info: go-librespot daemon successfully initialized Oct 26 08:24:24 volumio sudo[5111]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 26 08:24:24 volumio sudo[5111]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:24 volumio sudo[5113]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Oct 26 08:24:24 volumio sudo[5113]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:24 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Oct 26 08:24:24 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Oct 26 08:24:24 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Oct 26 08:24:24 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Oct 26 08:24:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 554. Oct 26 08:24:24 volumio sudo[5113]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:24 volumio mpd_monitor.sh[5116]: MPD Monitor Service: Starting MPD Monitor Service Oct 26 08:24:24 volumio sudo[5111]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:24 volumio volumio[4871]: info: Successfully started MPD Monitor Oct 26 08:24:24 volumio volumio[4871]: info: Successfully started MPD Monitor Oct 26 08:24:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:24 volumio go-librespot[5119]: go-librespot daemon starting... Oct 26 08:24:24 volumio go-librespot[5121]: time="2025-10-26T08:24:24Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:24:24 volumio go-librespot[5121]: time="2025-10-26T08:24:24Z" level=debug msg="app state loaded" Oct 26 08:24:24 volumio go-librespot[5121]: time="2025-10-26T08:24:24Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:24:24 volumio go-librespot[5121]: time="2025-10-26T08:24:24Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 26 08:24:24 volumio go-librespot[5121]: time="2025-10-26T08:24:24Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 26 08:24:24 volumio go-librespot[5121]: time="2025-10-26T08:24:24Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 26 08:24:24 volumio go-librespot[5121]: time="2025-10-26T08:24:24Z" level=info msg="zeroconf server listening on port 41247" Oct 26 08:24:24 volumio go-librespot[5121]: time="2025-10-26T08:24:24Z" level=debug msg="obtained new client token: AAAWQF+V1nmnYclYrU6/xMdhi3GgG/t0FW2LVYqZEa0HU8xB4jODsueqmaqdYn5s7fz4JBkXpBambKZo3qbiyLQ/JjK8JePw69035Ec+5FUxt6Y4kUrmz288O/fOil18Dn9i/mJxril8A57QZBEciBfEV/j54Bt/j8captC7X1z3AbJF/ASWreI/aJD2zDDZY9hF0kozHoXE/cOQw+xo5GvfkIyeTmHpZvhYEbpe/ph3TpMMf9OxFjU=" Oct 26 08:24:25 volumio go-librespot[5121]: time="2025-10-26T08:24:25Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:24:25 volumio go-librespot[5121]: time="2025-10-26T08:24:25Z" level=debug msg="completed keyexchange" Oct 26 08:24:25 volumio go-librespot[5121]: time="2025-10-26T08:24:25Z" level=debug msg="completed challenge" Oct 26 08:24:25 volumio go-librespot[5121]: time="2025-10-26T08:24:25Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:24:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:24:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:24:26 volumio volumio[4871]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 26 08:24:26 volumio volumio[4871]: info: Initializing connection to go-librespot Websocket Oct 26 08:24:26 volumio volumio[4871]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:24:27 volumio volumio[4871]: info: Cannot mount NAS NAS at system boot, trial number 3 ,retrying in 5 seconds Oct 26 08:24:27 volumio sudo[5144]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 08:24:27 volumio sudo[5144]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:27 volumio sudo[5146]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 08:24:27 volumio sudo[5146]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:27 volumio sudo[5144]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:27 volumio sudo[5146]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:27 volumio sudo[5150]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 26 08:24:27 volumio sudo[5150]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:27 volumio sudo[5150]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:27 volumio volumio[4871]: info: Upmpdcli Daemon Started Oct 26 08:24:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 555. Oct 26 08:24:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:28 volumio go-librespot[5152]: go-librespot daemon starting... Oct 26 08:24:28 volumio go-librespot[5153]: time="2025-10-26T08:24:28Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:24:28 volumio go-librespot[5153]: time="2025-10-26T08:24:28Z" level=debug msg="app state loaded" Oct 26 08:24:28 volumio go-librespot[5153]: time="2025-10-26T08:24:28Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:24:28 volumio go-librespot[5153]: time="2025-10-26T08:24:28Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 26 08:24:28 volumio go-librespot[5153]: time="2025-10-26T08:24:28Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 26 08:24:28 volumio go-librespot[5153]: time="2025-10-26T08:24:28Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 26 08:24:28 volumio go-librespot[5153]: time="2025-10-26T08:24:28Z" level=info msg="zeroconf server listening on port 44299" Oct 26 08:24:28 volumio go-librespot[5153]: time="2025-10-26T08:24:28Z" level=debug msg="obtained new client token: AACVROyUscs618/hDsEC0dClCi9+HZ6X85PY5tjn9A8IGd5OH/IC1l8XVlYw6JqDXGHStkjnk4qTeZw8a7JPATQ0hAGSk47o//lGJ6rbnvfS6/eXjdNiMaOCaFsh8yE6YKa8nbsbUaV6rRH9OYil9AyfS+7dgD0j08OtPtn320mBg+l7I73sdu38W6Tq5+fCwNdqHqWchiL4hRxkdVys2o9FCktSQ/odbfgH+ReKnd5cgETlJnWgUyc=" Oct 26 08:24:28 volumio go-librespot[5153]: time="2025-10-26T08:24:28Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:24:28 volumio go-librespot[5153]: time="2025-10-26T08:24:28Z" level=debug msg="completed keyexchange" Oct 26 08:24:28 volumio go-librespot[5153]: time="2025-10-26T08:24:28Z" level=debug msg="completed challenge" Oct 26 08:24:28 volumio go-librespot[5153]: time="2025-10-26T08:24:28Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:24:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:24:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 26 08:24:29 volumio volumio[4871]: info: Adding plugin bluetooth to MyMusic Plugins Oct 26 08:24:29 volumio volumio[4871]: info: Adding plugin multiroom to MyMusic Plugins Oct 26 08:24:29 volumio volumio[4871]: info: Adding plugin metavolumio to MyMusic Plugins Oct 26 08:24:29 volumio volumio[4871]: info: Adding plugin cd_controller to MyMusic Plugins Oct 26 08:24:29 volumio volumio[4871]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 26 08:24:29 volumio volumio[4871]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 26 08:24:29 volumio volumio[4871]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 26 08:24:29 volumio volumio[4871]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 26 08:24:30 volumio volumio[4871]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 26 08:24:30 volumio volumio[4871]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 26 08:24:30 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:30 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:30 volumio volumio[4871]: info: Starting MyVolumio Remote Streaming Endpoints Oct 26 08:24:30 volumio volumio[4871]: info: MyVolumio login type: Token Oct 26 08:24:30 volumio volumio[4871]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 26 08:24:30 volumio volumio[4871]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 26 08:24:30 volumio volumio[4871]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 26 08:24:30 volumio volumio[4871]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 26 08:24:30 volumio volumio[4871]: info: Streaming services startup Oct 26 08:24:30 volumio volumio[4871]: info: Starting Streaming Daemon Oct 26 08:24:30 volumio sudo[5161]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 26 08:24:30 volumio sudo[5161]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:30 volumio volumio[4871]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 26 08:24:30 volumio sudo[5161]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:30 volumio volumio[4871]: info: Initializing connection to go-librespot Websocket Oct 26 08:24:30 volumio volumio[4871]: error: Cannot start Volumio Streaming Daemon Oct 26 08:24:30 volumio volumio[4871]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 26 08:24:30 volumio volumio[4871]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 26 08:24:30 volumio volumio[4871]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 26 08:24:30 volumio volumio[4871]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 26 08:24:31 volumio volumio[4871]: info: MyVolumio token set successfully Oct 26 08:24:31 volumio volumio[4871]: info: MYVOLUMIO: Adding device Oct 26 08:24:31 volumio volumio[4871]: info: MYVOLUMIO: Evaluating Server Oct 26 08:24:31 volumio volumio[4871]: info: MyVolumio status changed Oct 26 08:24:31 volumio volumio[4871]: info: Streaming services startup Oct 26 08:24:31 volumio volumio[4871]: info: Starting Streaming Daemon Oct 26 08:24:31 volumio volumio[4871]: info: Removing browser output: myVolumio user plan is not superstar Oct 26 08:24:31 volumio volumio[4871]: info: Removing audio output: Oct 26 08:24:31 volumio volumio[4871]: info: Stoppping Tunnel 1 Oct 26 08:24:31 volumio sudo[5186]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 26 08:24:31 volumio sudo[5186]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:31 volumio sudo[5188]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 26 08:24:31 volumio sudo[5188]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 26 08:24:31 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. Oct 26 08:24:31 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. Oct 26 08:24:31 volumio sudo[5186]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:31 volumio volumio[4871]: error: Cannot start Volumio Streaming Daemon Oct 26 08:24:31 volumio volumio[4871]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 26 08:24:31 volumio volumio[4871]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 26 08:24:31 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. Oct 26 08:24:31 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. Oct 26 08:24:31 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. Oct 26 08:24:31 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. Oct 26 08:24:31 volumio sudo[5188]: pam_unix(sudo:session): session closed for user root Oct 26 08:24:31 volumio volumio[4871]: info: Remote SSH Stopped Oct 26 08:24:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 556. Oct 26 08:24:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:31 volumio volumio[4871]: info: Setting Geolocation for MyVolumio to eu3 Oct 26 08:24:31 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:31 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:31 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 26 08:24:31 volumio go-librespot[5191]: go-librespot daemon starting... Oct 26 08:24:31 volumio go-librespot[5192]: time="2025-10-26T08:24:31Z" level=info msg="running go-librespot 0.4.0" Oct 26 08:24:31 volumio go-librespot[5192]: time="2025-10-26T08:24:31Z" level=debug msg="app state loaded" Oct 26 08:24:31 volumio go-librespot[5192]: time="2025-10-26T08:24:31Z" level=info msg="api server listening on 127.0.0.1:9879" Oct 26 08:24:32 volumio volumio[4871]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 26 08:24:32 volumio volumio[4871]: info: Cannot mount NAS NAS at system boot, trial number 4 ,retrying in 5 seconds Oct 26 08:24:32 volumio volumio[4871]: info: Updating MyVolumio device info Oct 26 08:24:32 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:32 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:32 volumio volumio[4871]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 08:24:33 volumio volumio[4871]: info: Initializing connection to go-librespot Websocket Oct 26 08:24:33 volumio go-librespot[5192]: time="2025-10-26T08:24:33Z" level=debug msg="new websocket client" Oct 26 08:24:33 volumio volumio[4871]: info: Connection to go-librespot Websocket established Oct 26 08:24:33 volumio volumio[4871]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 26 08:24:36 volumio volumio[4871]: info: MYVOLUMIO: Adding device Oct 26 08:24:36 volumio volumio[4871]: info: MYVOLUMIO: Evaluating Server Oct 26 08:24:36 volumio volumio[4871]: info: Getting Spotify volume Oct 26 08:24:36 volumio volumio[4871]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 26 08:24:36 volumio go-librespot[5192]: time="2025-10-26T08:24:36Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 08:24:36 volumio go-librespot[5192]: time="2025-10-26T08:24:36Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 08:24:36 volumio go-librespot[5192]: time="2025-10-26T08:24:36Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 08:24:36 volumio go-librespot[5192]: time="2025-10-26T08:24:36Z" level=info msg="zeroconf server listening on port 40611" Oct 26 08:24:36 volumio volumio[4871]: info: CoreCommandRouter::volumioGetState Oct 26 08:24:36 volumio volumio[4871]: info: CorePlayQueue::getTrack 0 Oct 26 08:24:36 volumio volumio[4871]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Oct 26 08:24:36 volumio volumio[4871]: SPOTIFY: SPOTIFY VOLUME undefined Oct 26 08:24:36 volumio volumio[4871]: SPOTIFY: VOLUMIO VOLUME 33 Oct 26 08:24:36 volumio volumio[4871]: info: Aligning Spotify Volume to Volumio Volume Oct 26 08:24:36 volumio volumio[4871]: info: CoreCommandRouter::volumioGetState Oct 26 08:24:36 volumio volumio[4871]: info: CorePlayQueue::getTrack 0 Oct 26 08:24:36 volumio volumio[4871]: info: Setting Spotify Volume from Volumio: 33 Oct 26 08:24:36 volumio go-librespot[5192]: time="2025-10-26T08:24:36Z" level=debug msg="obtained new client token: AADE//3ebNVgHLoK8YREH0mSkBgtTEfQ6EKaKq/wmWOfdnw+F8i+hcS8y5p3zFrTQ64I9TZac88WgtgyXQy8uWNMzUE+8Jv8P4MS0Eo1UQzjlEQ6q35xdkwo5GPo6gi9Kb9w5zwyR83htMZZ+48A85t4wtO4hSbqL0EJg8v6J0Phs3Y9gN1XfzagzD3R4cNPmQZSOkuSFe/HrImbJFt052DNgz/IVG1j+TacYaywghgl4H97dHRJ5s4=" Oct 26 08:24:36 volumio go-librespot[5192]: time="2025-10-26T08:24:36Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 26 08:24:36 volumio go-librespot[5192]: time="2025-10-26T08:24:36Z" level=debug msg="completed keyexchange" Oct 26 08:24:36 volumio go-librespot[5192]: time="2025-10-26T08:24:36Z" level=debug msg="completed challenge" Oct 26 08:24:36 volumio go-librespot[5192]: time="2025-10-26T08:24:36Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 26 08:24:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 26 08:24:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 26 08:24:36 volumio volumio[4871]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 08:24:36 volumio volumio[4871]: Error: socket hang up Oct 26 08:24:36 volumio volumio[4871]: at connResetException (node:internal/errors:720:14) Oct 26 08:24:36 volumio volumio[4871]: at Socket.socketOnEnd (node:_http_client:519:23) Oct 26 08:24:36 volumio volumio[4871]: at Socket.emit (node:events:526:35) Oct 26 08:24:36 volumio volumio[4871]: at endReadableNT (node:internal/streams/readable:1376:12) Oct 26 08:24:36 volumio volumio[4871]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Oct 26 08:24:36 volumio volumio[4871]: code: 'ECONNRESET', Oct 26 08:24:36 volumio volumio[4871]: response: undefined Oct 26 08:24:36 volumio volumio[4871]: } Oct 26 08:24:36 volumio volumio[4871]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 08:24:36 volumio sudo[5229]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-26 08:23' Oct 26 08:24:36 volumio sudo[5229]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="c22b72a8acb34a699a626adb0a09a6b88ee7233a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="40400d6a6fa57cf20e36499e510876b3654e9c4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Oct 4 16:40:08 UTC 2025" VOLUMIO_VERSION="4.061" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="7f8ace80645f85765fa10c72d1769d04"