-- Logs begin at Thu 2019-02-14 10:12:00 UTC, end at Sun 2024-08-25 15:00:09 UTC. -- Aug 25 14:59:01 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:01 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 231. Aug 25 14:59:01 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:01 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:01 volumio-optical go-librespot[4583]: Librespot-go daemon starting... Aug 25 14:59:01 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:01 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:01 volumio-optical go-librespot[4583]: time="2024-08-25T14:59:01Z" level=info msg="generated new device id: f018bed2fbfd8a869abf20813dfe775be33eecfb" Aug 25 14:59:01 volumio-optical go-librespot[4583]: time="2024-08-25T14:59:01Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:01 volumio-optical volumio[951]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 25 14:59:01 volumio-optical go-librespot[4583]: time="2024-08-25T14:59:01Z" level=debug msg="obtained new client token: AADQhtG2Oyh0w9phmTL2akMlvCPbZmipmFCbCJld6S8+pCBYF6fLAs0KYGeF7O/rmTWmubK+vfYlC4XQHEkrJk9gUykMORHuvBVtcHuNxpSY7MXDBpSRsoG1ALR0SodES67Xa9ijP9wASATf5xJ5WLx0a+Te7Cod9YtzuWVehKoAKGR6db6nW4OGUs7YY7anC02bfM3iYvnE5NcZPpxFFBhSG96+ZP61849YK6oCyGDkrrDyKnygj6WaQqZKVw==" Aug 25 14:59:01 volumio-optical volumio[951]: info: Preload queue cleared Aug 25 14:59:01 volumio-optical go-librespot[4583]: time="2024-08-25T14:59:01Z" 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]" Aug 25 14:59:01 volumio-optical go-librespot[4583]: time="2024-08-25T14:59:01Z" level=debug msg="completed keyexchange" Aug 25 14:59:02 volumio-optical go-librespot[4583]: time="2024-08-25T14:59:02Z" level=debug msg="completed challenge" Aug 25 14:59:02 volumio-optical go-librespot[4583]: time="2024-08-25T14:59:02Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 14:59:02 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:02 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:03 volumio-optical volumio[951]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 25 14:59:03 volumio-optical volumio[951]: info: Preload queue cleared Aug 25 14:59:04 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:04 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:05 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:05 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 232. Aug 25 14:59:05 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:05 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:05 volumio-optical go-librespot[4591]: Librespot-go daemon starting... Aug 25 14:59:05 volumio-optical go-librespot[4591]: time="2024-08-25T14:59:05Z" level=info msg="generated new device id: 971f7cfd986f8f026cef3327fe480b8257257378" Aug 25 14:59:05 volumio-optical go-librespot[4591]: time="2024-08-25T14:59:05Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:06 volumio-optical go-librespot[4591]: time="2024-08-25T14:59:06Z" level=debug msg="obtained new client token: AABwDi+zmBCh/IA/fmR6GYpVXbp+OPIv9JNTq1Wykl/5/3rXgdNVT7MiZl+V30uhTW4JB5SVTvTHaRA4BvwxvB0p4vRkAgkdNuLtPFBcFWuuYKvdR4dOjYSmrraHiIJL9AWkSRhPAZQWFNGZw/mb48SSVh7J+Ns8far9CHDgSmBV+S11txj+t765D4XcN3ovNuNuhO+ieXujHHP26exdiVYGUG13KA36Yj3ZyEQpRgBuuxkT8nQDUjdWyo4=" Aug 25 14:59:06 volumio-optical go-librespot[4591]: time="2024-08-25T14:59:06Z" 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]" Aug 25 14:59:06 volumio-optical go-librespot[4591]: time="2024-08-25T14:59:06Z" level=debug msg="completed keyexchange" Aug 25 14:59:06 volumio-optical go-librespot[4591]: time="2024-08-25T14:59:06Z" level=debug msg="completed challenge" Aug 25 14:59:06 volumio-optical go-librespot[4591]: time="2024-08-25T14:59:06Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 14:59:06 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:06 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:07 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:07 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:07 volumio-optical volumio[951]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 25 14:59:08 volumio-optical volumio[951]: info: Preload queue cleared Aug 25 14:59:10 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:10 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 233. Aug 25 14:59:10 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:10 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:10 volumio-optical go-librespot[4600]: Librespot-go daemon starting... Aug 25 14:59:10 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:10 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:10 volumio-optical go-librespot[4600]: time="2024-08-25T14:59:10Z" level=info msg="generated new device id: 15b54e5df6d7aa74e79224b19f41393dd226e86c" Aug 25 14:59:10 volumio-optical go-librespot[4600]: time="2024-08-25T14:59:10Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:10 volumio-optical go-librespot[4600]: time="2024-08-25T14:59:10Z" level=debug msg="obtained new client token: AACLid1YW4s+IrBfHo762xVYT9++bfAlLzs7B/1sCcpe9S+Z9BLYNJLRdEnLcu7kHIkfpjswHZET9oq/Ua2ot2ZIXRK8QHMxF1NcXEJhLyQUEL0WN68Ild2d/cKXxwtk9G7N3/5WIwBIcoxgZNvF0mzzl45ZPdQ9zoRtDAap0uPNk3vMYt19Lmlq6+YImQIV1cACoqnE9mFdPn9cg78QioUQkiVg8iBkfVWr+Wb/dJeK/THJejxD/QQiHiLdNQ==" Aug 25 14:59:10 volumio-optical go-librespot[4600]: time="2024-08-25T14:59:10Z" 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]" Aug 25 14:59:10 volumio-optical go-librespot[4600]: time="2024-08-25T14:59:10Z" level=debug msg="completed keyexchange" Aug 25 14:59:11 volumio-optical volumio[951]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 25 14:59:11 volumio-optical go-librespot[4600]: time="2024-08-25T14:59:11Z" level=debug msg="completed challenge" Aug 25 14:59:11 volumio-optical go-librespot[4600]: time="2024-08-25T14:59:11Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 14:59:11 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:11 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:14 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:14 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 234. Aug 25 14:59:14 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:14 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:14 volumio-optical go-librespot[4608]: Librespot-go daemon starting... Aug 25 14:59:14 volumio-optical go-librespot[4608]: time="2024-08-25T14:59:14Z" level=info msg="generated new device id: 6ee921129a61b317b0aebec2ac2c40d6aa807278" Aug 25 14:59:14 volumio-optical go-librespot[4608]: time="2024-08-25T14:59:14Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:14 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:14 volumio-optical go-librespot[4608]: time="2024-08-25T14:59:14Z" level=debug msg="new websocket client" Aug 25 14:59:14 volumio-optical volumio[951]: info: Connection to go-librespot Websocket established Aug 25 14:59:14 volumio-optical volumio[951]: info: Preload queue cleared Aug 25 14:59:14 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@9c7bd2572e0f16ff54a3 Aug 25 14:59:14 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@160954d6c60588966388 Aug 25 14:59:14 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8ec07759da2390d2ead4 Aug 25 14:59:14 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@1eece6c838c56e22d9e1 Aug 25 14:59:14 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@eb45e107c09f80db1d41 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@5ee0da11d1eda407c9f1 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@a31b18db3eb8cad223f9 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@2bb843783350ebde6143 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@601c7d8c3d9dc191b7f9 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@eb166dc0ac54d365f580 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@a773eaef0d494b7b03b8 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@943e74ebf53aed854120 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@d72e290401971ce817d3 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8980837b1f4ae1296f12 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@bc3aac0adbb74ec201e7 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f33fdf3bc34a6d57ceb6 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@b08f36e857c5bdb7b3a7 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@7e6f795d0e6b8f270cb9 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f7b6d023a1c2c3fd39c9 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@143e7fad137c42d0730c Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@35e7e4f28b03798fa753 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@891db629d85f8b5ebb5a Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@a441f10ee3bad048b969 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@e52df0bc18a52e047bd9 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f8c1772b2de3bfa707c7 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@a680ecf5db94969769d0 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@99b4112045bd42baa87d Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@ee3329d70a22c2d9c6f5 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@b24a0342e666624274c2 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@fabb69dd69623a16673b Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6f7fb9ff7ca9530d9c9b Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@17dbabfdb7b370d9f3eb Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@06caa8c0dadcb37ace88 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@3a2adfc137975ea64660 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f6e60242446e7dd47f4d Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@c58f44f8bef9a9fc9a17 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f075baa8e42818caf2f6 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@cff53a859ddbbd44a6f5 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@2e1abccb6b6954fab63e Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@00d7a87495297c9515fe Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@bd1737af5eb06811bf11 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@4f77928675569971d1c0 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@5eeffeaac804bc5c6587 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f878c4ed9eef262cd9a7 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@ccb4756632ca3ae04c1f Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@15393f8b907ae921fa2f Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@07ed1bdd2ad184f81c82 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@bab57eca0b03a38f4fa4 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6a4ca50c577a98ca6450 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@9ad7f6dad1665c671619 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@861855f4021c9342175c Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@ad5abb3c7eee96e9509a Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8cd81ee552fa8a64c3cc Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8d4123734ebe70fa316d Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@2d9c3d88392de894a295 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@e120b87cccd11829533e Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@e14c0519e5141f581bb8 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@4bd48de3cf7499dd88fd Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@fc36e671508d4a0ddeb6 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6895ad5b14ea275727e5 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@1f2c6a9e1dca639c2839 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f4ea2eabcf354ee2fe33 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8b924dfa677249a1210e Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@b336bc21dca0d81c0fba Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6fa6b3ac10dc0916ddea Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@49ebbc6ac1d0888f849e Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@91d307a94a4a927439d0 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@b0551526bc6966680650 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@259c91512736ed413394 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@cb656b1958591a2246ef Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@85419209a886d9465010 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6ca1fe168c80a431f7e9 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@b23f1f1f7ad43ffc4ac9 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@20d079e73e3eee3b1bca Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8b021374841367a88825 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@252e1348e258468a19f5 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@489eb02006016fc4b2ce Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@47c3ea521454331fb9c0 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@5bc5681e70085d4d52d3 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@5e9c1c1bcd576eebc5d2 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@85f68e557e3a22ec13e8 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@ac552e0d73fcc3182d7c Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6eb809a8a4f357e81e4b Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8c76e965c8dcca1c44cc Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@e938a0fff21fa9545637 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@37a8c6a2a3918c65fc93 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@382cbc48a330efa4b965 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@1d41c00a8df7fcb7e12e Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6015d85295022719dbe3 Aug 25 14:59:15 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@458e868556f376171f96 Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@9c7bd2572e0f16ff54a3 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@160954d6c60588966388 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8ec07759da2390d2ead4 in service upnp_browser Aug 25 14:59:15 volumio-optical go-librespot[4608]: time="2024-08-25T14:59:15Z" level=debug msg="obtained new client token: AABTjRb2AaNIOEJYFxiGWbNRFKfVSSa0jRvp7tTpTSZ0SPF/nl58PIa6oDFlxGxk/9Y9FHhSddtS+mpo6eykHUZmm9Qppxsx3Yv5JcZxB9rt6+PKEm2P/2JWrUt4aXkwmqJCM6oys5EMZwl7u4ZtBha5zs0ac3+PVCsaZBfG1ZSsCRRhfoAwScvm+tOzTUiYxS55A8XjKBQX5owOOqSQez1ekczQ0I4fYyIuJ2wpQ8ic77FLhyVyqfXfAp4=" Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@1eece6c838c56e22d9e1 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@eb45e107c09f80db1d41 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@5ee0da11d1eda407c9f1 in service upnp_browser Aug 25 14:59:15 volumio-optical go-librespot[4608]: time="2024-08-25T14:59: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]" Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@a31b18db3eb8cad223f9 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@2bb843783350ebde6143 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@601c7d8c3d9dc191b7f9 in service upnp_browser Aug 25 14:59:15 volumio-optical go-librespot[4608]: time="2024-08-25T14:59:15Z" level=debug msg="completed keyexchange" Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@eb166dc0ac54d365f580 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@a773eaef0d494b7b03b8 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@943e74ebf53aed854120 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@d72e290401971ce817d3 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8980837b1f4ae1296f12 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@bc3aac0adbb74ec201e7 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f33fdf3bc34a6d57ceb6 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@b08f36e857c5bdb7b3a7 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@7e6f795d0e6b8f270cb9 in service upnp_browser Aug 25 14:59:15 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f7b6d023a1c2c3fd39c9 in service upnp_browser Aug 25 14:59:15 volumio-optical go-librespot[4608]: time="2024-08-25T14:59:15Z" level=debug msg="completed challenge" Aug 25 14:59:15 volumio-optical go-librespot[4608]: time="2024-08-25T14:59:15Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@143e7fad137c42d0730c in service upnp_browser Aug 25 14:59:16 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:16 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:16 volumio-optical volumio[951]: info: Connection to go-librespot Websocket closed Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@35e7e4f28b03798fa753 in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@891db629d85f8b5ebb5a in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@a441f10ee3bad048b969 in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@e52df0bc18a52e047bd9 in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f8c1772b2de3bfa707c7 in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@a680ecf5db94969769d0 in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@99b4112045bd42baa87d in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@ee3329d70a22c2d9c6f5 in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@b24a0342e666624274c2 in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@fabb69dd69623a16673b in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6f7fb9ff7ca9530d9c9b in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@17dbabfdb7b370d9f3eb in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@06caa8c0dadcb37ace88 in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@3a2adfc137975ea64660 in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f6e60242446e7dd47f4d in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@c58f44f8bef9a9fc9a17 in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f075baa8e42818caf2f6 in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@cff53a859ddbbd44a6f5 in service upnp_browser Aug 25 14:59:16 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@2e1abccb6b6954fab63e in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@00d7a87495297c9515fe in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@bd1737af5eb06811bf11 in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@4f77928675569971d1c0 in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@5eeffeaac804bc5c6587 in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f878c4ed9eef262cd9a7 in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@ccb4756632ca3ae04c1f in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@15393f8b907ae921fa2f in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@07ed1bdd2ad184f81c82 in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@bab57eca0b03a38f4fa4 in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6a4ca50c577a98ca6450 in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@9ad7f6dad1665c671619 in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@861855f4021c9342175c in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@ad5abb3c7eee96e9509a in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8cd81ee552fa8a64c3cc in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8d4123734ebe70fa316d in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@2d9c3d88392de894a295 in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@e120b87cccd11829533e in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@e14c0519e5141f581bb8 in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@4bd48de3cf7499dd88fd in service upnp_browser Aug 25 14:59:17 volumio-optical volumio[951]: info: Getting Spotify volume Aug 25 14:59:17 volumio-optical volumio[951]: (node:951) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:17 volumio-optical volumio[951]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Aug 25 14:59:17 volumio-optical volumio[951]: (node:951) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 27) Aug 25 14:59:17 volumio-optical volumio[951]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Aug 25 14:59:17 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@fc36e671508d4a0ddeb6 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: CoreCommandRouter::volumioGetState Aug 25 14:59:18 volumio-optical volumio[951]: info: CorePlayQueue::getTrack 0 Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6895ad5b14ea275727e5 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@1f2c6a9e1dca639c2839 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@f4ea2eabcf354ee2fe33 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8b924dfa677249a1210e in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@b336bc21dca0d81c0fba in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6fa6b3ac10dc0916ddea in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@49ebbc6ac1d0888f849e in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@91d307a94a4a927439d0 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@b0551526bc6966680650 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@259c91512736ed413394 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@cb656b1958591a2246ef in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@85419209a886d9465010 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6ca1fe168c80a431f7e9 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@b23f1f1f7ad43ffc4ac9 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@20d079e73e3eee3b1bca in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8b021374841367a88825 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@252e1348e258468a19f5 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@489eb02006016fc4b2ce in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@47c3ea521454331fb9c0 in service upnp_browser Aug 25 14:59:18 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@5bc5681e70085d4d52d3 in service upnp_browser Aug 25 14:59:19 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@5e9c1c1bcd576eebc5d2 in service upnp_browser Aug 25 14:59:19 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:19 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:19 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@85f68e557e3a22ec13e8 in service upnp_browser Aug 25 14:59:19 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:19 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 235. Aug 25 14:59:19 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:19 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@ac552e0d73fcc3182d7c in service upnp_browser Aug 25 14:59:19 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6eb809a8a4f357e81e4b in service upnp_browser Aug 25 14:59:19 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:19 volumio-optical go-librespot[4617]: Librespot-go daemon starting... Aug 25 14:59:19 volumio-optical go-librespot[4617]: time="2024-08-25T14:59:19Z" level=info msg="generated new device id: 4800e709c13b5024addb0e8c1016ce3f299dbaaf" Aug 25 14:59:19 volumio-optical go-librespot[4617]: time="2024-08-25T14:59:19Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:19 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@8c76e965c8dcca1c44cc in service upnp_browser Aug 25 14:59:19 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@e938a0fff21fa9545637 in service upnp_browser Aug 25 14:59:19 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@37a8c6a2a3918c65fc93 in service upnp_browser Aug 25 14:59:19 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@382cbc48a330efa4b965 in service upnp_browser Aug 25 14:59:19 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@1d41c00a8df7fcb7e12e in service upnp_browser Aug 25 14:59:19 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@6015d85295022719dbe3 in service upnp_browser Aug 25 14:59:19 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@458e868556f376171f96 in service upnp_browser Aug 25 14:59:19 volumio-optical go-librespot[4617]: time="2024-08-25T14:59:19Z" level=debug msg="obtained new client token: AADFDuJFLofAHp9ESWT5dCQtMCR1RE83/7cQn8ya+INf9J2cFs16VzHr8NFvNLwOiKIRtEkQKam869tWvwzDT/KSswfAd4wbbxPkY/cY8y+/jDLOAGqhF/gbkTq+MWpOv+eioMHOXjc72Ru6bW+2vwa14OLrD9OzYsoMDTb+g8DUxP2Tg/unuJ8GKTAbAwRgr6R0Xnwy7rcY8fFFEqlnUwCkIxXiEuoSr5SUz1q9TLbfkyw1WFVtG4rl6qoVmg==" Aug 25 14:59:19 volumio-optical go-librespot[4617]: time="2024-08-25T14:59: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]" Aug 25 14:59:19 volumio-optical go-librespot[4617]: time="2024-08-25T14:59:19Z" level=debug msg="completed keyexchange" Aug 25 14:59:20 volumio-optical go-librespot[4617]: time="2024-08-25T14:59:20Z" level=debug msg="completed challenge" Aug 25 14:59:20 volumio-optical go-librespot[4617]: time="2024-08-25T14:59:20Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 14:59:20 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:20 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:22 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:22 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:23 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:23 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 236. Aug 25 14:59:23 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:23 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:23 volumio-optical go-librespot[4625]: Librespot-go daemon starting... Aug 25 14:59:23 volumio-optical go-librespot[4625]: time="2024-08-25T14:59:23Z" level=info msg="generated new device id: 4304fd5c9116f6dcd476a4b38c0a28b556de9c45" Aug 25 14:59:23 volumio-optical go-librespot[4625]: time="2024-08-25T14:59:23Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:23 volumio-optical go-librespot[4625]: time="2024-08-25T14:59:23Z" level=debug msg="obtained new client token: AACiIK+lNqAckNOMTvSeM9pAEPCKbvc+6qposqi9ll26GyYKRVm3fcNkmYvFBpZzTDpXj2p18Whx8n/MU09AANzJpsnZFaBIkjlO7AOOYfdDbcbHkJhNSoHJvck3zs0PV/MyJX8ObEkIU5CbfEg/9zsHoMmfAUsIfjsrmn7PL7rF9gMW4WF+Tp8I8tscyyCjmnq+Ysaez0fGGhh+BT/J7fs7HX+oP3q2Cot5bl/J39rCKqcW+dKPGR+Ct7ooZw==" Aug 25 14:59:24 volumio-optical go-librespot[4625]: time="2024-08-25T14:59:24Z" 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]" Aug 25 14:59:24 volumio-optical go-librespot[4625]: time="2024-08-25T14:59:24Z" level=debug msg="completed keyexchange" Aug 25 14:59:24 volumio-optical go-librespot[4625]: time="2024-08-25T14:59:24Z" level=debug msg="completed challenge" Aug 25 14:59:24 volumio-optical go-librespot[4625]: time="2024-08-25T14:59:24Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 14:59:24 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:24 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:25 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:25 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:26 volumio-optical volumio[951]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 25 14:59:27 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:27 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 237. Aug 25 14:59:27 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:27 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:27 volumio-optical go-librespot[4634]: Librespot-go daemon starting... Aug 25 14:59:27 volumio-optical go-librespot[4634]: time="2024-08-25T14:59:27Z" level=info msg="generated new device id: bee2a7d26e29e8899296c80fdd62ee5505c5bcd0" Aug 25 14:59:27 volumio-optical go-librespot[4634]: time="2024-08-25T14:59:27Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:28 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:28 volumio-optical go-librespot[4634]: time="2024-08-25T14:59:28Z" level=debug msg="new websocket client" Aug 25 14:59:28 volumio-optical volumio[951]: info: Connection to go-librespot Websocket established Aug 25 14:59:28 volumio-optical go-librespot[4634]: time="2024-08-25T14:59:28Z" level=debug msg="obtained new client token: AAAoNPVhJpD9R1KFmrmTkYMFFff4otXj7YT+1RQWMgZIUOiI1O2MHRP0YrsJcnReCiiQ9Fa0kF415J2CZfxX5cwPHb6TY1j1qQhqGG6YL+o9pcWd3WISuxziTktRgotclQQTNSBc+2q28jH6qhYjvutYZRG3C3fi8T3QcaK8A8jyOOUV7/TlsRoDM28fSVIQIU0WA8ZfVAfovW29I8W7gagM+uPI3e1B3F5PuqpW5L5K+4sjuflivAFOacvWIA==" Aug 25 14:59:28 volumio-optical go-librespot[4634]: time="2024-08-25T14:59:28Z" 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]" Aug 25 14:59:28 volumio-optical go-librespot[4634]: time="2024-08-25T14:59:28Z" level=debug msg="completed keyexchange" Aug 25 14:59:29 volumio-optical go-librespot[4634]: time="2024-08-25T14:59:29Z" level=debug msg="completed challenge" Aug 25 14:59:29 volumio-optical go-librespot[4634]: time="2024-08-25T14:59:29Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 14:59:29 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:29 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:29 volumio-optical volumio[951]: info: Connection to go-librespot Websocket closed Aug 25 14:59:29 volumio-optical volumio[951]: info: Preload queue cleared Aug 25 14:59:31 volumio-optical volumio[951]: info: Getting Spotify volume Aug 25 14:59:31 volumio-optical volumio[951]: (node:951) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:31 volumio-optical volumio[951]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Aug 25 14:59:31 volumio-optical volumio[951]: (node:951) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 28) Aug 25 14:59:31 volumio-optical volumio[951]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Aug 25 14:59:31 volumio-optical volumio[951]: info: CoreCommandRouter::volumioGetState Aug 25 14:59:31 volumio-optical volumio[951]: info: CorePlayQueue::getTrack 0 Aug 25 14:59:32 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:32 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:32 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:32 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 238. Aug 25 14:59:32 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:32 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:32 volumio-optical go-librespot[4643]: Librespot-go daemon starting... Aug 25 14:59:32 volumio-optical go-librespot[4643]: time="2024-08-25T14:59:32Z" level=info msg="generated new device id: b692b566fbc45f6ae71d9c308796585b6ff3abf6" Aug 25 14:59:32 volumio-optical go-librespot[4643]: time="2024-08-25T14:59:32Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:32 volumio-optical go-librespot[4643]: time="2024-08-25T14:59:32Z" level=debug msg="obtained new client token: AABNDesSIgcDGVyADR8fqJ2Yq2PVgPg6hvIg3Gg7dljohX1aUY67vBILFnOSocLMhPq2R3U6jqOluG5bgkbcQHC1rQ0g+TE1oF94t32kxXf6K1I9dWJAjIcZAfeB07VtIhApzg+v+euNNZ4lPDYurHj/TnujMfMiu91mFfy8epDs9YvEdRyj3CoRR9Ec6Ik+H0ycGhwXDBDLceYQxd6Z+wRSX0T63lxqgeYXB1//fxgLEnO4K0A9FUEcmlX2fA==" Aug 25 14:59:33 volumio-optical go-librespot[4643]: time="2024-08-25T14:59: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 25 14:59:33 volumio-optical go-librespot[4643]: time="2024-08-25T14:59:33Z" level=debug msg="completed keyexchange" Aug 25 14:59:33 volumio-optical go-librespot[4643]: time="2024-08-25T14:59:33Z" level=debug msg="completed challenge" Aug 25 14:59:33 volumio-optical go-librespot[4643]: time="2024-08-25T14:59:33Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 14:59:33 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:33 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:34 volumio-optical volumio[951]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 25 14:59:35 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:35 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:36 volumio-optical volumio[951]: info: Preload queue cleared Aug 25 14:59:36 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@480d8f6932936af93f54 Aug 25 14:59:36 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@79f1109f06a41aa25532 Aug 25 14:59:36 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@3bb71e5434842e7aca86 Aug 25 14:59:36 volumio-optical volumio[951]: info: Preloading song: upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@797a1a85a53b27b6a435 Aug 25 14:59:36 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@480d8f6932936af93f54 in service upnp_browser Aug 25 14:59:36 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@79f1109f06a41aa25532 in service upnp_browser Aug 25 14:59:36 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@3bb71e5434842e7aca86 in service upnp_browser Aug 25 14:59:36 volumio-optical volumio[951]: info: Exploding uri upnp/http://192.168.1.18:32469/ContentDirectory/d5b611f5-f758-da44-f4d1-3d6177b6a32a/control.xml@797a1a85a53b27b6a435 in service upnp_browser Aug 25 14:59:36 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:36 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 239. Aug 25 14:59:36 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:36 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:36 volumio-optical go-librespot[4651]: Librespot-go daemon starting... Aug 25 14:59:36 volumio-optical go-librespot[4651]: time="2024-08-25T14:59:36Z" level=info msg="generated new device id: f6d7f5ac386ab1e9c764e9ae9f6df08dc537a794" Aug 25 14:59:36 volumio-optical go-librespot[4651]: time="2024-08-25T14:59:36Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:37 volumio-optical go-librespot[4651]: time="2024-08-25T14:59:37Z" level=debug msg="obtained new client token: AADOsJXU4QkiuV6+vvK7oXfatQ0UtbEEZBIbGOgCWmSz5dhuxnwrww6NabteKAyHSfmBgHdSyGAJgfhYjERnbZCDg85Ds1OKv3+iQqQsKBBD4xz+2fr3eNW9HiFMcL/u9DxeBlrLT5GQfXJ+ATmpYa/lUtf8qqwkukEcb9xUCkJJvXQLraRMYoP20UEuNXMXbCktziJYaZeONiwhIrxP7XMLJLjvi1hk9rSwcvAicV7BOeyCXT12iRlYZ1RVWQ==" Aug 25 14:59:37 volumio-optical go-librespot[4651]: time="2024-08-25T14:59:37Z" 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]" Aug 25 14:59:37 volumio-optical go-librespot[4651]: time="2024-08-25T14:59:37Z" level=debug msg="completed keyexchange" Aug 25 14:59:38 volumio-optical go-librespot[4651]: time="2024-08-25T14:59:38Z" level=debug msg="completed challenge" Aug 25 14:59:38 volumio-optical go-librespot[4651]: time="2024-08-25T14:59:38Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 14:59:38 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:38 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:38 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:38 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:41 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:41 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:41 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:41 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 240. Aug 25 14:59:41 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:41 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:41 volumio-optical go-librespot[4659]: Librespot-go daemon starting... Aug 25 14:59:41 volumio-optical go-librespot[4659]: time="2024-08-25T14:59:41Z" level=info msg="generated new device id: 64d4b1fd28152f3bc39879d837c2369112eb0967" Aug 25 14:59:41 volumio-optical go-librespot[4659]: time="2024-08-25T14:59:41Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:41 volumio-optical go-librespot[4659]: time="2024-08-25T14:59:41Z" level=debug msg="obtained new client token: AACPsNLT6QTSBbabaUnXfL7+TefqrjVckXNRr6htavEetUR+xaWdhmtIU0p+/A7idn2kRlrUmN7G/60HoSyawdvyvYLvNWE9QAs0+F/9qntdWnoSUCuLDcGijBtThFNwVtc2Qv10OTmuTss+Gp+RYB6L5CsFqmyrzZ1oKSCkl0yXzk492K1Bui82mP6m8+1Q6JvpItm+5qLY7AbQffZIqX4BwPeyphHj7nVOVokr0V8j3+T0qULgXOorfieHdA==" Aug 25 14:59:41 volumio-optical go-librespot[4659]: time="2024-08-25T14:59:41Z" 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]" Aug 25 14:59:42 volumio-optical go-librespot[4659]: time="2024-08-25T14:59:42Z" level=debug msg="completed keyexchange" Aug 25 14:59:42 volumio-optical go-librespot[4659]: time="2024-08-25T14:59:42Z" level=debug msg="completed challenge" Aug 25 14:59:42 volumio-optical go-librespot[4659]: time="2024-08-25T14:59:42Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 14:59:42 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:42 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:44 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:44 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:45 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:45 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 241. Aug 25 14:59:45 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:45 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:45 volumio-optical go-librespot[4667]: Librespot-go daemon starting... Aug 25 14:59:45 volumio-optical go-librespot[4667]: time="2024-08-25T14:59:45Z" level=info msg="generated new device id: 3ba93df233bb94046b8d75e64157ed1d10fc0efe" Aug 25 14:59:45 volumio-optical go-librespot[4667]: time="2024-08-25T14:59:45Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:46 volumio-optical go-librespot[4667]: time="2024-08-25T14:59:46Z" level=debug msg="obtained new client token: AADODG/Q/3Z3XrO48r+BKNOEerVjOSmmZRBZFrEjmaqUqi4OdKimyoOAHI8L8ewtLmpVM5HA3P86ZV1kOogow8cvfCHNBV/ZelQprD7JGZbjF4BZI/ZQjOVpf57m0YpQ0kzyv7LNZz67HDCcFkbDl29Nzqf8eCobuDkne7Rl+ChxfgHPEMa/pP4t2PfljyKq3mDUBL8e0qVqpaYlnMN/8DnmbTcBWWNT5wufkF8lyNe7t7Im0Mzj1Tc9ZKpFXA==" Aug 25 14:59:46 volumio-optical go-librespot[4667]: time="2024-08-25T14:59:46Z" 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]" Aug 25 14:59:46 volumio-optical go-librespot[4667]: time="2024-08-25T14:59:46Z" level=debug msg="completed keyexchange" Aug 25 14:59:47 volumio-optical go-librespot[4667]: time="2024-08-25T14:59:47Z" level=debug msg="completed challenge" Aug 25 14:59:47 volumio-optical go-librespot[4667]: time="2024-08-25T14:59:47Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 14:59:47 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:47 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:47 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:47 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:50 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:50 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:50 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:50 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 242. Aug 25 14:59:50 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:50 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:50 volumio-optical go-librespot[4676]: Librespot-go daemon starting... Aug 25 14:59:50 volumio-optical go-librespot[4676]: time="2024-08-25T14:59:50Z" level=info msg="generated new device id: 35771e50d6e084b95a7040a76cc192418dbd24ae" Aug 25 14:59:50 volumio-optical go-librespot[4676]: time="2024-08-25T14:59:50Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:50 volumio-optical go-librespot[4676]: time="2024-08-25T14:59:50Z" level=debug msg="obtained new client token: AABQCqyPBPlKXJrT7R00UID9Nsa2puM2Q8bsFKrGTUUVcZhhzNtbxj5pVYJ6m366x9BQUnv8rtvxZduILe/zlRP5unab/44OZD3od0oQ+NwpqxmiWXP7sMhJl2HJYpfjapXWqhMPOr3+wr3hqz0NKXoLWWkF3ED/xfpKs9gCUxzg3tEBGanb9uMfR0MYYZo6sAz/cUE66w9WOmqIxXcBub5RadlxwFQaaN8s04GaohHVKuvHpBPd+qtzZHl4UA==" Aug 25 14:59:51 volumio-optical go-librespot[4676]: time="2024-08-25T14:59: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-gew4.spotify.com:80]" Aug 25 14:59:51 volumio-optical go-librespot[4676]: time="2024-08-25T14:59:51Z" level=debug msg="completed keyexchange" Aug 25 14:59:51 volumio-optical go-librespot[4676]: time="2024-08-25T14:59:51Z" level=debug msg="completed challenge" Aug 25 14:59:51 volumio-optical go-librespot[4676]: time="2024-08-25T14:59:51Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 14:59:51 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:51 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:53 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:53 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:54 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:54 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 243. Aug 25 14:59:54 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:54 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:54 volumio-optical go-librespot[4685]: Librespot-go daemon starting... Aug 25 14:59:54 volumio-optical volumiologrotate[609]: ls: cannot access '/var/log/samba/log.wb-VOLUMIO': No such file or directory Aug 25 14:59:54 volumio-optical go-librespot[4685]: time="2024-08-25T14:59:54Z" level=info msg="generated new device id: 2aec5ab2ec95ea9110698f26ce320467b6271591" Aug 25 14:59:54 volumio-optical go-librespot[4685]: time="2024-08-25T14:59:54Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:54 volumio-optical volumiologrotate[609]: ls: cannot access 'OPTICAL': No such file or directory Aug 25 14:59:55 volumio-optical go-librespot[4685]: time="2024-08-25T14:59:55Z" level=debug msg="obtained new client token: AABSIwrt7YuD2qpFWkOABoPjCRIpzkvBd5U2qqzIoNT6MNtRN2t3QtTn4w3AsPdAxoRIyshzH6Lh3iMqvyxlRkiHw8dxkpDHbKro+7CmLvskqGVNTGhiJeGwqSe+o4k3YZdY6cF7QMo8Brh//9ZuAakFsGr1VznhIziQJlM7BS1thuExg5kKAMK5zjZ9AqTwOsc5xiZ6ry/E6iuabYZ48Om/KvjC9H/9PUZ+pyeZBFwCcBy4MGsWf0JOwEQMSg==" Aug 25 14:59:55 volumio-optical go-librespot[4685]: time="2024-08-25T14:59: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]" Aug 25 14:59:55 volumio-optical go-librespot[4685]: time="2024-08-25T14:59:55Z" level=debug msg="completed keyexchange" Aug 25 14:59:55 volumio-optical go-librespot[4685]: time="2024-08-25T14:59:55Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed solving challenge: failed login: BadCredentials" Aug 25 14:59:55 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 14:59:55 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 14:59:56 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:56 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 14:59:58 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 14:59:58 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 244. Aug 25 14:59:58 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 14:59:58 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 14:59:58 volumio-optical go-librespot[4736]: Librespot-go daemon starting... Aug 25 14:59:58 volumio-optical go-librespot[4736]: time="2024-08-25T14:59:58Z" level=info msg="generated new device id: 000fb93f069ef799d07c5523eb5d3b2dde9e8ded" Aug 25 14:59:58 volumio-optical go-librespot[4736]: time="2024-08-25T14:59:58Z" level=debug msg="stored credentials found for lupin1877" Aug 25 14:59:59 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 14:59:59 volumio-optical go-librespot[4736]: time="2024-08-25T14:59:59Z" level=debug msg="new websocket client" Aug 25 14:59:59 volumio-optical go-librespot[4736]: time="2024-08-25T14:59:59Z" level=debug msg="obtained new client token: AADnlt6p9cYamHrpjt1LNihC+9oldTJC18zkb/5JY5acATIaMaOtq5usckAGfI7sA+hdrDBrt8Aombh9J63DUvdYkI1T8cCbiMbP1uQ1qByOloPZ7E+AjGXI0g89LXfsXyV0r7Uc+OlT0FwAQA3aw/twm3JjciVuxMXC5tQjo3iUFJZw6WM3RG7qwirG/oB8Ky/jvI3YX9HAKnFYgLOrE1OfzTvKoy5//nV7A3q0seuE8QA2jKLznfGHUHmnGA==" Aug 25 14:59:59 volumio-optical volumio[951]: info: Connection to go-librespot Websocket established Aug 25 14:59:59 volumio-optical go-librespot[4736]: time="2024-08-25T14:59:59Z" 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]" Aug 25 14:59:59 volumio-optical go-librespot[4736]: time="2024-08-25T14:59:59Z" level=debug msg="completed keyexchange" Aug 25 15:00:00 volumio-optical go-librespot[4736]: time="2024-08-25T15:00:00Z" level=debug msg="completed challenge" Aug 25 15:00:00 volumio-optical go-librespot[4736]: time="2024-08-25T15:00:00Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 15:00:00 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 15:00:00 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 15:00:00 volumio-optical volumio[951]: info: Connection to go-librespot Websocket closed Aug 25 15:00:01 volumio-optical volumio[951]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 25 15:00:01 volumio-optical volumio[951]: info: Preload queue cleared Aug 25 15:00:02 volumio-optical volumio[951]: info: Getting Spotify volume Aug 25 15:00:02 volumio-optical volumio[951]: (node:951) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 15:00:02 volumio-optical volumio[951]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Aug 25 15:00:02 volumio-optical volumio[951]: (node:951) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 29) Aug 25 15:00:02 volumio-optical volumio[951]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Aug 25 15:00:02 volumio-optical volumio[951]: info: CoreCommandRouter::volumioGetState Aug 25 15:00:02 volumio-optical volumio[951]: info: CorePlayQueue::getTrack 0 Aug 25 15:00:03 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 15:00:03 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 15:00:03 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 15:00:03 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 245. Aug 25 15:00:03 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 15:00:03 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 15:00:03 volumio-optical go-librespot[4744]: Librespot-go daemon starting... Aug 25 15:00:03 volumio-optical go-librespot[4744]: time="2024-08-25T15:00:03Z" level=info msg="generated new device id: 27acaecd51a3f421cb4052c8f27f15a4fa205413" Aug 25 15:00:03 volumio-optical go-librespot[4744]: time="2024-08-25T15:00:03Z" level=debug msg="stored credentials found for lupin1877" Aug 25 15:00:03 volumio-optical go-librespot[4744]: time="2024-08-25T15:00:03Z" level=debug msg="obtained new client token: AADfT6noBB1HdOx6D4m5IfMZgVmueqNJId8SgRi5M8QF3smywAvCtqDxitOV3InYbU1G6/UfjvCbHgwMiw5MBQ07gynJfDQ6pwviXSMUloi7yczcIH3U3LnZThgga4eyjWe1PvQ9V6Yo9VBa8eNa/mt17ZXUgaCngxDklH0DxfO9qWDlNbZnwqp/uMGNABIGOx7ouC8JqQD/kFaGd8aplshwENDTeLlmQIFPUplQwg3UKjyV00METxGeaQoh9w==" Aug 25 15:00:03 volumio-optical go-librespot[4744]: time="2024-08-25T15:00:03Z" 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]" Aug 25 15:00:04 volumio-optical go-librespot[4744]: time="2024-08-25T15:00:04Z" level=debug msg="completed keyexchange" Aug 25 15:00:04 volumio-optical go-librespot[4744]: time="2024-08-25T15:00:04Z" level=debug msg="completed challenge" Aug 25 15:00:04 volumio-optical go-librespot[4744]: time="2024-08-25T15:00:04Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 15:00:04 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 15:00:04 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 15:00:05 volumio-optical volumio[951]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 25 15:00:05 volumio-optical volumio[951]: info: Preload queue cleared Aug 25 15:00:06 volumio-optical volumio[951]: info: Initializing connection to go-librespot Websocket Aug 25 15:00:06 volumio-optical volumio[951]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 25 15:00:07 volumio-optical systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 25 15:00:07 volumio-optical systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 246. Aug 25 15:00:07 volumio-optical systemd[1]: Stopped go-librespot Daemon. Aug 25 15:00:07 volumio-optical systemd[1]: Started go-librespot Daemon. Aug 25 15:00:07 volumio-optical go-librespot[4753]: Librespot-go daemon starting... Aug 25 15:00:07 volumio-optical go-librespot[4753]: time="2024-08-25T15:00:07Z" level=info msg="generated new device id: 397016fa745d64826eafab2b7e4f5a5d33adb5b0" Aug 25 15:00:07 volumio-optical go-librespot[4753]: time="2024-08-25T15:00:07Z" level=debug msg="stored credentials found for lupin1877" Aug 25 15:00:08 volumio-optical volumio[951]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 25 15:00:08 volumio-optical volumio[951]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 15:00:08 volumio-optical volumio[951]: TypeError: Cannot read property 'length' of undefined Aug 25 15:00:08 volumio-optical volumio[951]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Aug 25 15:00:08 volumio-optical volumio[951]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Aug 25 15:00:08 volumio-optical volumio[951]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Aug 25 15:00:08 volumio-optical volumio[951]: at Parser.emit (events.js:315:20) Aug 25 15:00:08 volumio-optical volumio[951]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Aug 25 15:00:08 volumio-optical volumio[951]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Aug 25 15:00:08 volumio-optical volumio[951]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Aug 25 15:00:08 volumio-optical volumio[951]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Aug 25 15:00:08 volumio-optical volumio[951]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Aug 25 15:00:08 volumio-optical volumio[951]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Aug 25 15:00:08 volumio-optical volumio[951]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Aug 25 15:00:08 volumio-optical volumio[951]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Aug 25 15:00:08 volumio-optical volumio[951]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Aug 25 15:00:08 volumio-optical volumio[951]: at IncomingMessage.emit (events.js:327:22) Aug 25 15:00:08 volumio-optical volumio[951]: at endReadableNT (internal/streams/readable.js:1327:12) Aug 25 15:00:08 volumio-optical volumio[951]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Aug 25 15:00:08 volumio-optical volumio[951]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 15:00:08 volumio-optical go-librespot[4753]: time="2024-08-25T15:00:08Z" level=debug msg="obtained new client token: AABkBGRi6MUneC/exIetMWHm49gp8O0rPaNoQaRJHRy76ylcpa9tqXf2gbCuK0VmKFbBE7XsT+82MftrA1b8BdC7BFSvCZeGXdcwxjnz8fLKiSXlc9GvK8LaUY/q+uaFfwivzMWG8GfIIdGH6Gj8mB87YInHWv2CiEJGUSSFZOgS0qjrG3dsDCnCZysyX8+gzszSqMDuqbUbQs2LroRylGxn7C5+MZ7cK+G8fx8Ilw5CNDUAZjS0hsuC19G3gQ==" Aug 25 15:00:08 volumio-optical go-librespot[4753]: time="2024-08-25T15:00:08Z" 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]" Aug 25 15:00:08 volumio-optical go-librespot[4753]: time="2024-08-25T15:00:08Z" level=debug msg="completed keyexchange" Aug 25 15:00:09 volumio-optical go-librespot[4753]: time="2024-08-25T15:00:09Z" level=debug msg="completed challenge" Aug 25 15:00:09 volumio-optical go-librespot[4753]: time="2024-08-25T15:00:09Z" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 25 15:00:09 volumio-optical systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 25 15:00:09 volumio-optical systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 25 15:00:09 volumio-optical sudo[4770]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-25 14:59 Aug 25 15:00:09 volumio-optical sudo[4770]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"