-- Logs begin at Thu 2019-02-14 19:12:00 KST, end at Thu 2024-11-21 14:29:18 KST. -- Nov 21 14:28:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56. Nov 21 14:28:01 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:01 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:01 volumio go-librespot[2358]: Librespot-go daemon starting... Nov 21 14:28:01 volumio go-librespot[2358]: time="2024-11-21T14:28:01+09:00" level=info msg="generated new device id: 07f861d639d7e98df8e67f8c1a8e13ef1a84c151" Nov 21 14:28:01 volumio go-librespot[2358]: time="2024-11-21T14:28:01+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:01 volumio go-librespot[2358]: time="2024-11-21T14:28:01+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:28:01 volumio go-librespot[2358]: time="2024-11-21T14:28:01+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:28:01 volumio go-librespot[2358]: time="2024-11-21T14:28:01+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:28:01 volumio go-librespot[2358]: time="2024-11-21T14:28:01+09:00" level=debug msg="zeroconf server listening on port 40889" Nov 21 14:28:01 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:01 volumio go-librespot[2358]: time="2024-11-21T14:28:01+09:00" level=debug msg="new websocket client" Nov 21 14:28:01 volumio volumio[817]: info: Connection to go-librespot Websocket established Nov 21 14:28:01 volumio go-librespot[2358]: time="2024-11-21T14:28:01+09:00" level=debug msg="obtained new client token: AAB2WueItmlNMOUbXcxqu2dQs22dnytu1YRkNMP+6/9aaXlmoLpIMtqN+Py+iKYJ/XbIQWJlPR8Zc6x1siHqqT4JgaAywObvuoH6gQMkPPeHuPqvvB6NZ0k+adb7PCDKeTjZ4MdM3UeW0OBaHAAbE0mt7WIpWfu9oBMOmlumxaxJ4hSobCOOIjeFFeKSXRv9JMdJMDdxRfenRKSQaCTdhWUkIw3V5Xtml3LfxICK5pj7zGWREvHkYSmR9YQHjKs=" Nov 21 14:28:01 volumio go-librespot[2358]: time="2024-11-21T14:28:01+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:01 volumio go-librespot[2358]: time="2024-11-21T14:28:01+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:02 volumio go-librespot[2358]: time="2024-11-21T14:28:02+09:00" level=debug msg="completed challenge" Nov 21 14:28:02 volumio go-librespot[2358]: time="2024-11-21T14:28:02+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:02 volumio volumio[817]: info: Connection to go-librespot Websocket closed Nov 21 14:28:04 volumio kernel: hwmon hwmon1: Voltage normalised Nov 21 14:28:04 volumio volumio[817]: info: Getting Spotify volume Nov 21 14:28:04 volumio volumio[817]: (node:817) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:04 volumio volumio[817]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 21 14:28:04 volumio volumio[817]: (node:817) 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: 19) Nov 21 14:28:04 volumio volumio[817]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Nov 21 14:28:04 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Nov 21 14:28:04 volumio volumio[817]: info: CorePlayQueue::getTrack 0 Nov 21 14:28:05 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:05 volumio volumio[817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:05 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57. Nov 21 14:28:05 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:05 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:05 volumio go-librespot[2371]: Librespot-go daemon starting... Nov 21 14:28:05 volumio go-librespot[2371]: time="2024-11-21T14:28:05+09:00" level=info msg="generated new device id: c42c22c39644f4e35e8b3de477648924433f2250" Nov 21 14:28:05 volumio go-librespot[2371]: time="2024-11-21T14:28:05+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:05 volumio go-librespot[2371]: time="2024-11-21T14:28:05+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:28:05 volumio go-librespot[2371]: time="2024-11-21T14:28:05+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:28:05 volumio go-librespot[2371]: time="2024-11-21T14:28:05+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:28:05 volumio go-librespot[2371]: time="2024-11-21T14:28:05+09:00" level=debug msg="zeroconf server listening on port 45915" Nov 21 14:28:05 volumio go-librespot[2371]: time="2024-11-21T14:28:05+09:00" level=debug msg="obtained new client token: AAC5wb+fhEcdHuQ5Z/7SnW6VdwnrXVt2Edz3jIYhfc1BvU/uvkEkxPKxFYV1qC85rtqNPMdRiuxv2jl6/WMz7kFKoCz8ZeTLTwPmj8USC6oC5eEVSSUXuvKfxRj226zxWALU/PkFowUUlFus8xCGkgPGZIapSMC4KY0GAAgWj9lNpWWzjDve2G6NSso7tW/EfWipfjPgbNpXivqBo23LdA952jab06Wi+XK/DAp2b0/xbggVjPLv8g/J9y7YCTw=" Nov 21 14:28:05 volumio go-librespot[2371]: time="2024-11-21T14:28:05+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:05 volumio go-librespot[2371]: time="2024-11-21T14:28:05+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:06 volumio go-librespot[2371]: time="2024-11-21T14:28:06+09:00" level=debug msg="completed challenge" Nov 21 14:28:06 volumio go-librespot[2371]: time="2024-11-21T14:28:06+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:08 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:08 volumio volumio[817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:09 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 58. Nov 21 14:28:09 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:09 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:09 volumio go-librespot[2394]: Librespot-go daemon starting... Nov 21 14:28:09 volumio go-librespot[2394]: time="2024-11-21T14:28:09+09:00" level=info msg="generated new device id: 695c9b9fa1e2c2d4c02c87832ed6dcafbe149f8e" Nov 21 14:28:09 volumio go-librespot[2394]: time="2024-11-21T14:28:09+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:09 volumio go-librespot[2394]: time="2024-11-21T14:28:09+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:28:09 volumio go-librespot[2394]: time="2024-11-21T14:28:09+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:28:09 volumio go-librespot[2394]: time="2024-11-21T14:28:09+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:28:09 volumio go-librespot[2394]: time="2024-11-21T14:28:09+09:00" level=debug msg="zeroconf server listening on port 44019" Nov 21 14:28:09 volumio go-librespot[2394]: time="2024-11-21T14:28:09+09:00" level=debug msg="obtained new client token: AABOW0U+Vedzmv9YivTMT4GOQjhVs4XPObE7OCOYfTquhEhH5XpK52DqlY0hfDKCiAGZq3UhVmgCOaF+1FVU5NnEEaacS5GK0P9+512nyjcbWCEcQpyWANiJEUPkkqn1Ny1xdVLWHtkM5XsXjnbXm6qOQIGdPgbhIu4mDKKFZcuTprZYa8wdowAeBQUcH2V6uEbE+xo2a+2qDuhl3jd4Ln+A+2dD6gaUeWrdrAR4lKaRnJO+8o3LTe1i0Oq+y/I=" Nov 21 14:28:10 volumio go-librespot[2394]: time="2024-11-21T14:28:10+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:10 volumio go-librespot[2394]: time="2024-11-21T14:28:10+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:10 volumio go-librespot[2394]: time="2024-11-21T14:28:10+09:00" level=debug msg="completed challenge" Nov 21 14:28:10 volumio go-librespot[2394]: time="2024-11-21T14:28:10+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:11 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:11 volumio volumio[817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 59. Nov 21 14:28:13 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:13 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:13 volumio go-librespot[2405]: Librespot-go daemon starting... Nov 21 14:28:13 volumio go-librespot[2405]: time="2024-11-21T14:28:13+09:00" level=info msg="generated new device id: 0de5fe5e12358942ce6f2ba123b2667ca74fcbb7" Nov 21 14:28:13 volumio go-librespot[2405]: time="2024-11-21T14:28:13+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:14 volumio go-librespot[2405]: time="2024-11-21T14:28:14+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:28:14 volumio go-librespot[2405]: time="2024-11-21T14:28:14+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:28:14 volumio go-librespot[2405]: time="2024-11-21T14:28:14+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:28:14 volumio go-librespot[2405]: time="2024-11-21T14:28:14+09:00" level=debug msg="zeroconf server listening on port 35745" Nov 21 14:28:14 volumio go-librespot[2405]: time="2024-11-21T14:28:14+09:00" level=debug msg="obtained new client token: AABdSF0rO8LVUQ5z0rSfU64QXdHFGQ/vF4Ax6dZIS+nRgws/p/zQ19FpzNF2FKR74oCAIVA0X1dfT8frGASJj03dxG32+LJlJpn1F3//K0oRVY/gvvo8ESJBxB2KPrnb56tx09WNPesSmBCQVMjsZj/w32TRW5zSMvgGJc8kBVdRHSnxw4krVAdbpK1FUGEO29IvuIMKN7unDKOcB0NOE0ImoOU658TirFxreF6luu3OeERwmCH/btMnBlfR" Nov 21 14:28:14 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:14 volumio go-librespot[2405]: time="2024-11-21T14:28:14+09:00" level=debug msg="new websocket client" Nov 21 14:28:14 volumio volumio[817]: info: Connection to go-librespot Websocket established Nov 21 14:28:14 volumio go-librespot[2405]: time="2024-11-21T14:28:14+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:14 volumio go-librespot[2405]: time="2024-11-21T14:28:14+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:14 volumio go-librespot[2405]: time="2024-11-21T14:28:14+09:00" level=debug msg="completed challenge" Nov 21 14:28:14 volumio go-librespot[2405]: time="2024-11-21T14:28:14+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:14 volumio volumio[817]: info: Connection to go-librespot Websocket closed Nov 21 14:28:17 volumio volumio[817]: info: Getting Spotify volume Nov 21 14:28:17 volumio volumio[817]: (node:817) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:17 volumio volumio[817]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 21 14:28:17 volumio volumio[817]: (node:817) 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: 20) Nov 21 14:28:17 volumio volumio[817]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Nov 21 14:28:17 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Nov 21 14:28:17 volumio volumio[817]: info: CorePlayQueue::getTrack 0 Nov 21 14:28:17 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:17 volumio volumio[817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 60. Nov 21 14:28:18 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:18 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:18 volumio go-librespot[2427]: Librespot-go daemon starting... Nov 21 14:28:18 volumio go-librespot[2427]: time="2024-11-21T14:28:18+09:00" level=info msg="generated new device id: 55f364c62e55793f4b0ac93364a2508c5281b5f6" Nov 21 14:28:18 volumio go-librespot[2427]: time="2024-11-21T14:28:18+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:18 volumio go-librespot[2427]: time="2024-11-21T14:28:18+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Nov 21 14:28:18 volumio go-librespot[2427]: time="2024-11-21T14:28:18+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 21 14:28:18 volumio go-librespot[2427]: time="2024-11-21T14:28:18+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 21 14:28:18 volumio go-librespot[2427]: time="2024-11-21T14:28:18+09:00" level=debug msg="zeroconf server listening on port 38431" Nov 21 14:28:18 volumio go-librespot[2427]: time="2024-11-21T14:28:18+09:00" level=debug msg="obtained new client token: AABs4V9SvdKv07fwJpOl91GusjTfw0OzafHt0XTNSGce+T8D0ueMV2xzG4TRwpsuCnoNVjhisnsm9xM9a+Q8YY53D245+eHyhRJaVMuwvPAKkYMekg83gNTH216dmA9PbQt3pD29RyNPittkJqK8Cx9Vb2HDhgFvrIxfOjr/v2HhNntMmg+PmneDnoeGwT/6YuBibIMTUJxl7XIfj0yNwT92blDyq4dvB/Dhg+t6LmhK3z/bt1q2/pkgq21+WSw=" Nov 21 14:28:18 volumio go-librespot[2427]: time="2024-11-21T14:28:18+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:18 volumio go-librespot[2427]: time="2024-11-21T14:28:18+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:19 volumio go-librespot[2427]: time="2024-11-21T14:28:19+09:00" level=debug msg="completed challenge" Nov 21 14:28:19 volumio go-librespot[2427]: time="2024-11-21T14:28:19+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:20 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:20 volumio volumio[817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:22 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 61. Nov 21 14:28:22 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:22 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:22 volumio go-librespot[2435]: Librespot-go daemon starting... Nov 21 14:28:22 volumio go-librespot[2435]: time="2024-11-21T14:28:22+09:00" level=info msg="generated new device id: 8956571f829737ae9c5698246f7926e9b4ebcb3d" Nov 21 14:28:22 volumio go-librespot[2435]: time="2024-11-21T14:28:22+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:22 volumio go-librespot[2435]: time="2024-11-21T14:28:22+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:28:22 volumio go-librespot[2435]: time="2024-11-21T14:28:22+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:28:22 volumio go-librespot[2435]: time="2024-11-21T14:28:22+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:28:22 volumio go-librespot[2435]: time="2024-11-21T14:28:22+09:00" level=debug msg="zeroconf server listening on port 39271" Nov 21 14:28:22 volumio go-librespot[2435]: time="2024-11-21T14:28:22+09:00" level=debug msg="obtained new client token: AABGaqPcWUBmyPpoUgsBzC3Qnrs9eqIR8I0rM0jEGiaV5Db1A5IQiqLTbGMzXXHBKvTWP4wysgGpoZbURRr7+2vPF4T/kKbU3gIULmcbINoscPQO4Mc3/xEDnNquD8ANyo0G6mipUTktXvoANowF44l6DEUcjoRVtLY1drnwNSKemGQpgwiyRYhoYdpouHhMHZOtTS8cmyr3hTT7pSIGOyZIE4ZqkHm4kVT9hpe61cNLzpYLis/cGZNqeZ4aKFA=" Nov 21 14:28:22 volumio go-librespot[2435]: time="2024-11-21T14:28:22+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:22 volumio go-librespot[2435]: time="2024-11-21T14:28:22+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:23 volumio go-librespot[2435]: time="2024-11-21T14:28:23+09:00" level=debug msg="completed challenge" Nov 21 14:28:23 volumio go-librespot[2435]: time="2024-11-21T14:28:23+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:23 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:23 volumio volumio[817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:26 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 62. Nov 21 14:28:26 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:26 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:26 volumio go-librespot[2448]: Librespot-go daemon starting... Nov 21 14:28:26 volumio go-librespot[2448]: time="2024-11-21T14:28:26+09:00" level=info msg="generated new device id: f6fc3745a5e2b3a020a04e36562567cfc8266ff4" Nov 21 14:28:26 volumio go-librespot[2448]: time="2024-11-21T14:28:26+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:26 volumio go-librespot[2448]: time="2024-11-21T14:28:26+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:28:26 volumio go-librespot[2448]: time="2024-11-21T14:28:26+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:28:26 volumio go-librespot[2448]: time="2024-11-21T14:28:26+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:28:26 volumio go-librespot[2448]: time="2024-11-21T14:28:26+09:00" level=debug msg="zeroconf server listening on port 45755" Nov 21 14:28:26 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:26 volumio go-librespot[2448]: time="2024-11-21T14:28:26+09:00" level=debug msg="new websocket client" Nov 21 14:28:26 volumio volumio[817]: info: Connection to go-librespot Websocket established Nov 21 14:28:26 volumio go-librespot[2448]: time="2024-11-21T14:28:26+09:00" level=debug msg="obtained new client token: AABPLiQezmIaIn5BqNnvQeM2PHzZ7OrinTt7sPDuQimP/pz2lKiaE9fxL1UtBdXH5ctDUQwIXsvrYavOePSkv4IbqvxsKptjTWBkhiJQeQ2ZSf6A0FZvFqCGE0cyQTpVXWJ/krPIBWqCCAHthBUudIQtWYtEThe11KiU1QOLd/oT3QwnDYVZ5+i05aK7f9S1fuL82ru45IsaVUfTG3pdCwyVDrpiFLxWpEFbDWdJrbtKXaaGn0B7VlyhRtx2u+w=" Nov 21 14:28:27 volumio go-librespot[2448]: time="2024-11-21T14:28:27+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:27 volumio go-librespot[2448]: time="2024-11-21T14:28:27+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:27 volumio go-librespot[2448]: time="2024-11-21T14:28:27+09:00" level=debug msg="completed challenge" Nov 21 14:28:27 volumio go-librespot[2448]: time="2024-11-21T14:28:27+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:27 volumio volumio[817]: info: Connection to go-librespot Websocket closed Nov 21 14:28:29 volumio volumio[817]: info: Getting Spotify volume Nov 21 14:28:29 volumio volumio[817]: (node:817) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:29 volumio volumio[817]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 21 14:28:29 volumio volumio[817]: (node:817) 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: 21) Nov 21 14:28:29 volumio volumio[817]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Nov 21 14:28:29 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Nov 21 14:28:29 volumio volumio[817]: info: CorePlayQueue::getTrack 0 Nov 21 14:28:30 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:30 volumio volumio[817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 63. Nov 21 14:28:30 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:30 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:30 volumio go-librespot[2470]: Librespot-go daemon starting... Nov 21 14:28:30 volumio go-librespot[2470]: time="2024-11-21T14:28:30+09:00" level=info msg="generated new device id: d261c07b2a2fb9985966915e4ee68f712b9a3af5" Nov 21 14:28:30 volumio go-librespot[2470]: time="2024-11-21T14:28:30+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:31 volumio go-librespot[2470]: time="2024-11-21T14:28:31+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Nov 21 14:28:31 volumio go-librespot[2470]: time="2024-11-21T14:28:31+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 21 14:28:31 volumio go-librespot[2470]: time="2024-11-21T14:28:31+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 21 14:28:31 volumio go-librespot[2470]: time="2024-11-21T14:28:31+09:00" level=debug msg="zeroconf server listening on port 45581" Nov 21 14:28:31 volumio go-librespot[2470]: time="2024-11-21T14:28:31+09:00" level=debug msg="obtained new client token: AABcWd8CH7+hH0RHByrkQUECRE6u2YTj2+9FnDJboeRyTkMm9U3xSIOKNan4IGsGrnv6SbvOWAoBOcUTGN9f3CJyMkpMz8/5K5V/wVQk323Pd8RolaQZYgNJQZGMowjUTSfe2T3vJBVRxwsYCRQIp+RMUZye7y2jLfLOoAvR2UNumeLXG1wb2Jezyee9/1IOwPvsntDqxYk6gKrLn4qJczHiJZa23AwxMrHcObT1DLD/qP5G/26kphSD/NpL" Nov 21 14:28:31 volumio go-librespot[2470]: time="2024-11-21T14:28:31+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:31 volumio go-librespot[2470]: time="2024-11-21T14:28:31+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:31 volumio go-librespot[2470]: time="2024-11-21T14:28:31+09:00" level=debug msg="completed challenge" Nov 21 14:28:31 volumio go-librespot[2470]: time="2024-11-21T14:28:31+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:33 volumio sudo[2479]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 21 14:28:33 volumio sudo[2482]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 21 14:28:33 volumio sudo[2479]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:28:33 volumio sudo[2482]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:28:33 volumio sudo[2479]: pam_unix(sudo:session): session closed for user root Nov 21 14:28:33 volumio sudo[2482]: pam_unix(sudo:session): session closed for user root Nov 21 14:28:33 volumio volumio[817]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.38 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36 Edg/131.0.0.0 Engine version: 3 Transport: polling Total Clients: 5 Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::volumioGetVisibleSources Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Nov 21 14:28:33 volumio volumio[817]: info: CorePlayQueue::getTrack 0 Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::volumioGetQueue Nov 21 14:28:33 volumio volumio[817]: info: CoreStateMachine::getQueue Nov 21 14:28:33 volumio volumio[817]: info: CorePlayQueue::getQueue Nov 21 14:28:33 volumio volumio[817]: info: Listing playlists Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Nov 21 14:28:33 volumio volumio[817]: info: Received Get System Info Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 21 14:28:33 volumio volumio[817]: info: Discovery: Getting this device information Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Nov 21 14:28:33 volumio volumio[817]: info: CorePlayQueue::getTrack 0 Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Nov 21 14:28:33 volumio volumio[817]: info: CorePlayQueue::getTrack 0 Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 21 14:28:33 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Nov 21 14:28:33 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:33 volumio volumio[817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:34 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Nov 21 14:28:35 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 21 14:28:35 volumio volumio[817]: info: Received Get System Info Nov 21 14:28:35 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 21 14:28:35 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 21 14:28:35 volumio volumio[817]: info: Discovery: Getting this device information Nov 21 14:28:35 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Nov 21 14:28:35 volumio volumio[817]: info: CorePlayQueue::getTrack 0 Nov 21 14:28:35 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 21 14:28:35 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 64. Nov 21 14:28:35 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:35 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:35 volumio go-librespot[2487]: Librespot-go daemon starting... Nov 21 14:28:35 volumio go-librespot[2487]: time="2024-11-21T14:28:35+09:00" level=info msg="generated new device id: 09c417915b00c556a4f59e18de90d884ddc58ee8" Nov 21 14:28:35 volumio go-librespot[2487]: time="2024-11-21T14:28:35+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:35 volumio go-librespot[2487]: time="2024-11-21T14:28:35+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:28:35 volumio go-librespot[2487]: time="2024-11-21T14:28:35+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:28:35 volumio go-librespot[2487]: time="2024-11-21T14:28:35+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:28:35 volumio go-librespot[2487]: time="2024-11-21T14:28:35+09:00" level=debug msg="zeroconf server listening on port 45855" Nov 21 14:28:35 volumio go-librespot[2487]: time="2024-11-21T14:28:35+09:00" level=debug msg="obtained new client token: AABJISBA1dWiNvzWtnfkv03t24wfF5LkuecHD/EfnVjixyf6FeJjFiDH+sPCzd6v3mymG5JuAk2D7+AU/3bMDvMwhOzm9TB5Fjh67RoELbqIMsHiqOjvdgzfYqD8sVamScjJ+2k6r7vN/CMVvwJ0HjTvY6eYR3UFcjHZ8p4Iygx33tc4snPayeo0Uoztr0VFt7oKxwEbV0YV9CloDQRJdS4ZMX4Vi0Mz8LdMaV+Vv8Dvyy9Z5NbDz3K5++y1nks=" Nov 21 14:28:35 volumio go-librespot[2487]: time="2024-11-21T14:28:35+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:35 volumio go-librespot[2487]: time="2024-11-21T14:28:35+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:36 volumio go-librespot[2487]: time="2024-11-21T14:28:36+09:00" level=debug msg="completed challenge" Nov 21 14:28:36 volumio go-librespot[2487]: time="2024-11-21T14:28:36+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:36 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Nov 21 14:28:36 volumio volumio[817]: info: CorePlayQueue::getTrack 0 Nov 21 14:28:36 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:36 volumio volumio[817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:36 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 21 14:28:36 volumio volumio[817]: info: Received Get System Info Nov 21 14:28:36 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 21 14:28:36 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 21 14:28:36 volumio volumio[817]: info: Discovery: Getting this device information Nov 21 14:28:36 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Nov 21 14:28:36 volumio volumio[817]: info: CorePlayQueue::getTrack 0 Nov 21 14:28:36 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 21 14:28:37 volumio volumio[817]: info: Retrieving Cloud Streaming UI Nov 21 14:28:37 volumio volumio[817]: info: Getting Tidal Cloud Configuration Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 21 14:28:37 volumio volumio[817]: info: Getting Qobuz Cloud Configuration Nov 21 14:28:37 volumio volumio[817]: info: Asking plugin for UI Config Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 21 14:28:37 volumio volumio[817]: info: Getting Spotify Cloud Configuration Nov 21 14:28:37 volumio volumio[817]: info: Asking plugin for UI Config Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 21 14:28:37 volumio volumio[817]: info: Saving Spotify Acccount Nov 21 14:28:37 volumio volumio[817]: info: Got Tidal Cloud Configuration Nov 21 14:28:37 volumio volumio[817]: info: Got it Nov 21 14:28:37 volumio volumio[817]: info: Got it Nov 21 14:28:37 volumio volumio[817]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 21 14:28:37 volumio volumio[817]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::volumioGetBrowseSources Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::volumioGetBrowseSources Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::volumioGetBrowseSources Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 21 14:28:37 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Nov 21 14:28:39 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 65. Nov 21 14:28:39 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:39 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:39 volumio go-librespot[2551]: Librespot-go daemon starting... Nov 21 14:28:39 volumio go-librespot[2551]: time="2024-11-21T14:28:39+09:00" level=info msg="generated new device id: 59f3e8c0e4bd215e8f0665851d23e9f519fda334" Nov 21 14:28:39 volumio go-librespot[2551]: time="2024-11-21T14:28:39+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:39 volumio go-librespot[2551]: time="2024-11-21T14:28:39+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Nov 21 14:28:39 volumio go-librespot[2551]: time="2024-11-21T14:28:39+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Nov 21 14:28:39 volumio go-librespot[2551]: time="2024-11-21T14:28:39+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Nov 21 14:28:39 volumio go-librespot[2551]: time="2024-11-21T14:28:39+09:00" level=debug msg="zeroconf server listening on port 45423" Nov 21 14:28:39 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:39 volumio go-librespot[2551]: time="2024-11-21T14:28:39+09:00" level=debug msg="new websocket client" Nov 21 14:28:39 volumio volumio[817]: info: Connection to go-librespot Websocket established Nov 21 14:28:39 volumio go-librespot[2551]: time="2024-11-21T14:28:39+09:00" level=debug msg="obtained new client token: AABrzXx6T/5Kjadsok9wX29lDNIgxwzME+t5YDIu6hJQIi7vKRhHVwGN16pAjVHFTjWr34PYu86vrHW12emJ+s3Fn5Pm7j3CiQTlVMQRApDLWi4G8MLi3JOOUkbrQoY1Dlt4Ncf6DX5KAMCliM+JaWVmDUOr+uZ+CSilbiwaDNcMmyp2qHDQj41Vg6fEqFdqKcbonqVOlLg+Y88XCFvlglUZ/xSHhiwkDm3urfii2+RYYJ2RJCvLh0fz8GZZCTI=" Nov 21 14:28:39 volumio go-librespot[2551]: time="2024-11-21T14:28:39+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:39 volumio go-librespot[2551]: time="2024-11-21T14:28:39+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:40 volumio go-librespot[2551]: time="2024-11-21T14:28:40+09:00" level=debug msg="completed challenge" Nov 21 14:28:40 volumio go-librespot[2551]: time="2024-11-21T14:28:40+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:40 volumio volumio[817]: info: Connection to go-librespot Websocket closed Nov 21 14:28:41 volumio volumio[817]: info: Disabling MyMusic plugin upnp_browser Nov 21 14:28:41 volumio volumio[817]: info: CoreCommandRouter::volumioRemoveToBrowseSources미디어 서버 Nov 21 14:28:41 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 21 14:28:41 volumio volumio[817]: Cannot find translation for source YouTube2 Nov 21 14:28:41 volumio volumio[817]: Cannot find translation for source YouTube Music Nov 21 14:28:41 volumio volumio[817]: Cannot find translation for source Mother Earth Radio Nov 21 14:28:41 volumio volumio[817]: info: Disabling plugin upnp_browser Nov 21 14:28:41 volumio volumio[817]: info: Done. Nov 21 14:28:41 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 21 14:28:42 volumio volumio[817]: info: Getting Spotify volume Nov 21 14:28:42 volumio volumio[817]: (node:817) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:42 volumio volumio[817]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 21 14:28:42 volumio volumio[817]: (node:817) 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: 22) Nov 21 14:28:42 volumio volumio[817]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Nov 21 14:28:42 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Nov 21 14:28:42 volumio volumio[817]: info: CorePlayQueue::getTrack 0 Nov 21 14:28:43 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Nov 21 14:28:43 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:43 volumio volumio[817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 66. Nov 21 14:28:43 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:43 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:43 volumio go-librespot[2564]: Librespot-go daemon starting... Nov 21 14:28:43 volumio go-librespot[2564]: time="2024-11-21T14:28:43+09:00" level=info msg="generated new device id: 7c5f8af41f925ce45157704b54f535f1a9f6c698" Nov 21 14:28:43 volumio go-librespot[2564]: time="2024-11-21T14:28:43+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:43 volumio go-librespot[2564]: time="2024-11-21T14:28:43+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:28:43 volumio go-librespot[2564]: time="2024-11-21T14:28:43+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:28:43 volumio go-librespot[2564]: time="2024-11-21T14:28:43+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:28:43 volumio go-librespot[2564]: time="2024-11-21T14:28:43+09:00" level=debug msg="zeroconf server listening on port 35613" Nov 21 14:28:43 volumio go-librespot[2564]: time="2024-11-21T14:28:43+09:00" level=debug msg="obtained new client token: AAC5mLxto8payTSlmm1xLWr+fanTnHHNY2jcNRSMs9FhTp1DY2OEXGfVeEcLV3eHh6FHz5gI76UbRTeUS6IxDBTCureLCINolnSjPdYECf66R8bdyui0QiEtbIe/TmgaproI84DiTCt59EYKcYONKV+N0mOvB2gvWdF+LAQC1AkAkvvjcyNGfG2QH/xYso243WkIEcHPi8BwcQfpgNQR7jPl3HsNMQSvH6dASjW8WcNvNqfYDa3VoHSAYGn84SQ=" Nov 21 14:28:44 volumio go-librespot[2564]: time="2024-11-21T14:28:44+09:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070 (error: dial tcp 104.199.241.202:4070: connect: connection refused), retrying with a different AP" Nov 21 14:28:44 volumio go-librespot[2564]: time="2024-11-21T14:28:44+09:00" level=info msg="connected to ap-gae2.spotify.com:443" Nov 21 14:28:44 volumio go-librespot[2564]: time="2024-11-21T14:28:44+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:45 volumio go-librespot[2564]: time="2024-11-21T14:28:45+09:00" level=debug msg="completed challenge" Nov 21 14:28:45 volumio go-librespot[2564]: time="2024-11-21T14:28:45+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:45 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 21 14:28:46 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:46 volumio volumio[817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:47 volumio volumio[817]: info: Enabling MyMusic plugin upnp_browser Nov 21 14:28:47 volumio volumio[817]: info: Enabling plugin upnp_browser Nov 21 14:28:47 volumio volumio[817]: info: Loading plugin "upnp_browser"... Nov 21 14:28:47 volumio volumio[817]: info: PLUGIN START: upnp_browser Nov 21 14:28:47 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 21 14:28:47 volumio volumio[817]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 21 14:28:47 volumio volumio[817]: info: [1732166927050] CoreMusicLibrary::Adding element 미디어 서버 Nov 21 14:28:47 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 21 14:28:47 volumio volumio[817]: Cannot find translation for source YouTube2 Nov 21 14:28:47 volumio volumio[817]: Cannot find translation for source YouTube Music Nov 21 14:28:47 volumio volumio[817]: Cannot find translation for source Mother Earth Radio Nov 21 14:28:47 volumio volumio[817]: info: Done. Nov 21 14:28:47 volumio volumio[817]: info: Disabling MyMusic plugin airplay_emulation Nov 21 14:28:47 volumio volumio[817]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesShairport-Sync Nov 21 14:28:47 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 21 14:28:47 volumio volumio[817]: Cannot find translation for source YouTube2 Nov 21 14:28:47 volumio volumio[817]: Cannot find translation for source YouTube Music Nov 21 14:28:47 volumio volumio[817]: Cannot find translation for source Mother Earth Radio Nov 21 14:28:47 volumio volumio[817]: info: Disabling plugin airplay_emulation Nov 21 14:28:47 volumio volumio[817]: info: Done. Nov 21 14:28:47 volumio sudo[2588]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop shairport-sync Nov 21 14:28:47 volumio sudo[2588]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:28:47 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 21 14:28:47 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 21 14:28:47 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 21 14:28:47 volumio sudo[2588]: pam_unix(sudo:session): session closed for user root Nov 21 14:28:47 volumio volumio[817]: info: Shairport-Sync Stopped Nov 21 14:28:48 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 67. Nov 21 14:28:48 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:48 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:48 volumio go-librespot[2590]: Librespot-go daemon starting... Nov 21 14:28:48 volumio go-librespot[2590]: time="2024-11-21T14:28:48+09:00" level=info msg="generated new device id: e04eaead80b659d57676efc29178a525d54c8881" Nov 21 14:28:48 volumio go-librespot[2590]: time="2024-11-21T14:28:48+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:48 volumio go-librespot[2590]: time="2024-11-21T14:28:48+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:28:48 volumio go-librespot[2590]: time="2024-11-21T14:28:48+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:28:48 volumio go-librespot[2590]: time="2024-11-21T14:28:48+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:28:48 volumio go-librespot[2590]: time="2024-11-21T14:28:48+09:00" level=debug msg="zeroconf server listening on port 41993" Nov 21 14:28:48 volumio go-librespot[2590]: time="2024-11-21T14:28:48+09:00" level=debug msg="obtained new client token: AAA9I4nGMrwGgYvkoWKxFGdkJ57FX8W/mC6pmrB3hjAzAzp08+g5zm3J7MnqLUWiRLlm9Wmd+Bmv1S6SLNluKI85V7kQR8KUCF/VKrqoxtdYcHupe8dbnas4sLnVJe2NZT3GJsuc+w50XrBviHQlrGE/jCvVLEgnkoa/PAv5x7+KeVUMy+An4jySDPswo9g4aBljw93FgXpQ4O47S7vdDd2p+HzMYKSlQawfbZh++1S95KLp6hAtmXI6GqK7oPM=" Nov 21 14:28:49 volumio volumio[817]: info: Enabling MyMusic plugin airplay_emulation Nov 21 14:28:49 volumio volumio[817]: info: Enabling plugin airplay_emulation Nov 21 14:28:49 volumio volumio[817]: info: Loading plugin "airplay_emulation"... Nov 21 14:28:49 volumio volumio[817]: info: Starting Shairport Sync Nov 21 14:28:49 volumio volumio[817]: info: PLUGIN START: airplay_emulation Nov 21 14:28:49 volumio go-librespot[2590]: time="2024-11-21T14:28:49+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:49 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:28:49 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 21 14:28:49 volumio go-librespot[2590]: time="2024-11-21T14:28:49+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:49 volumio volumio[817]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 21 14:28:49 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:28:49 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 21 14:28:49 volumio volumio[817]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 21 14:28:49 volumio volumio[817]: info: Done. Nov 21 14:28:49 volumio volumio[817]: info: Starting Shairport Sync Nov 21 14:28:49 volumio volumio[817]: info: Starting Shairport Sync Nov 21 14:28:49 volumio sudo[2605]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 21 14:28:49 volumio sudo[2605]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:28:49 volumio sudo[2608]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 21 14:28:49 volumio sudo[2608]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:28:49 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 21 14:28:49 volumio sudo[2605]: pam_unix(sudo:session): session closed for user root Nov 21 14:28:49 volumio volumio[817]: info: Shairport-Sync Started Nov 21 14:28:49 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 21 14:28:49 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Nov 21 14:28:49 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 21 14:28:49 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 21 14:28:49 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 21 14:28:49 volumio sudo[2608]: pam_unix(sudo:session): session closed for user root Nov 21 14:28:49 volumio volumio[817]: info: Shairport-Sync Started Nov 21 14:28:49 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:49 volumio go-librespot[2590]: time="2024-11-21T14:28:49+09:00" level=debug msg="new websocket client" Nov 21 14:28:49 volumio volumio[817]: info: Connection to go-librespot Websocket established Nov 21 14:28:49 volumio go-librespot[2590]: time="2024-11-21T14:28:49+09:00" level=debug msg="completed challenge" Nov 21 14:28:49 volumio go-librespot[2590]: time="2024-11-21T14:28:49+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:49 volumio volumio[817]: info: Connection to go-librespot Websocket closed Nov 21 14:28:49 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 21 14:28:50 volumio volumio[817]: info: Disabling MyMusic plugin upnp Nov 21 14:28:51 volumio sudo[2615]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Nov 21 14:28:51 volumio sudo[2615]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:28:51 volumio systemd[1]: Stopping UPnP Renderer front-end to MPD... Nov 21 14:28:51 volumio volumio[817]: error: Upnp client error: Error: This socket has been ended by the other party Nov 21 14:28:51 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 21 14:28:51 volumio volumio[817]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Nov 21 14:28:51 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Nov 21 14:28:51 volumio volumio[817]: info: Received Get System Version Nov 21 14:28:51 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 21 14:28:51 volumio volumio[817]: info: Received Get System Info Nov 21 14:28:51 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 21 14:28:51 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 21 14:28:51 volumio volumio[817]: info: Discovery: Getting this device information Nov 21 14:28:51 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Nov 21 14:28:51 volumio volumio[817]: info: CorePlayQueue::getTrack 0 Nov 21 14:28:51 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 21 14:28:52 volumio volumio[817]: info: Getting Spotify volume Nov 21 14:28:52 volumio volumio[817]: (node:817) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:52 volumio volumio[817]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 21 14:28:52 volumio volumio[817]: (node:817) 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: 23) Nov 21 14:28:52 volumio volumio[817]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Nov 21 14:28:52 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Nov 21 14:28:52 volumio volumio[817]: info: CorePlayQueue::getTrack 0 Nov 21 14:28:52 volumio volumio[817]: info: Initializing connection to go-librespot Websocket Nov 21 14:28:52 volumio volumio[817]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 21 14:28:52 volumio volumio[817]: info: Enabling MyMusic plugin upnp Nov 21 14:28:52 volumio volumio[817]: info: Enabling plugin upnp Nov 21 14:28:52 volumio volumio[817]: info: Loading plugin "upnp"... Nov 21 14:28:52 volumio volumio[817]: info: [1732166932740] Starting Upmpd Daemon Nov 21 14:28:52 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 21 14:28:52 volumio volumio[817]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 21 14:28:52 volumio volumio[817]: Error: listen EADDRINUSE: address already in use :::6599 Nov 21 14:28:52 volumio volumio[817]: at Server.setupListenHandle [as _listen2] (net.js:1318:16) Nov 21 14:28:52 volumio volumio[817]: at listenInCluster (net.js:1366:12) Nov 21 14:28:52 volumio volumio[817]: at Server.listen (net.js:1452:7) Nov 21 14:28:52 volumio volumio[817]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Nov 21 14:28:52 volumio volumio[817]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Nov 21 14:28:52 volumio volumio[817]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Nov 21 14:28:52 volumio volumio[817]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Nov 21 14:28:52 volumio volumio[817]: at processTicksAndRejections (internal/process/task_queues.js:75:11) { Nov 21 14:28:52 volumio volumio[817]: code: 'EADDRINUSE', Nov 21 14:28:52 volumio volumio[817]: errno: -98, Nov 21 14:28:52 volumio volumio[817]: syscall: 'listen', Nov 21 14:28:52 volumio volumio[817]: address: '::', Nov 21 14:28:52 volumio volumio[817]: port: 6599 Nov 21 14:28:52 volumio volumio[817]: } Nov 21 14:28:52 volumio volumio[817]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 21 14:28:52 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 68. Nov 21 14:28:52 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:52 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:52 volumio go-librespot[2624]: Librespot-go daemon starting... Nov 21 14:28:52 volumio go-librespot[2624]: time="2024-11-21T14:28:52+09:00" level=info msg="generated new device id: e6850e4d09a366441759fe9a369a45c12813d6a1" Nov 21 14:28:52 volumio go-librespot[2624]: time="2024-11-21T14:28:52+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:53 volumio go-librespot[2624]: time="2024-11-21T14:28:53+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:28:53 volumio go-librespot[2624]: time="2024-11-21T14:28:53+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:28:53 volumio go-librespot[2624]: time="2024-11-21T14:28:53+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:28:53 volumio go-librespot[2624]: time="2024-11-21T14:28:53+09:00" level=debug msg="zeroconf server listening on port 34305" Nov 21 14:28:53 volumio go-librespot[2624]: time="2024-11-21T14:28:53+09:00" level=debug msg="obtained new client token: AACl63WkSXW1BcwP2j4LW1Pwkobzo9W63Bj5yGFBQvxcmmiWlJvG6+JofUDcK6Be9XdMmYMMKh9fx+YesGYZ0vQQCbt66q3GVi20BWozS2c3gvpwpjLhcHmK64QKE8Xwj2POZW7bGPhF508g+5LYxKwoZWlk/GSOaf2wDoBt4hQsKGZegPZdkUOd8snL4wnXV2BdvCZZLQM8hd+3aTJ6JADPWzvTwfdPbthG92Wj1LJBozgKKmyOGkDZLOqs" Nov 21 14:28:53 volumio go-librespot[2624]: time="2024-11-21T14:28:53+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:53 volumio go-librespot[2624]: time="2024-11-21T14:28:53+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:53 volumio sudo[2638]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-21 14:27 Nov 21 14:28:53 volumio sudo[2638]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:28:53 volumio sudo[2638]: pam_unix(sudo:session): session closed for user root Nov 21 14:28:53 volumio go-librespot[2624]: time="2024-11-21T14:28:53+09:00" level=debug msg="completed challenge" Nov 21 14:28:53 volumio go-librespot[2624]: time="2024-11-21T14:28:53+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:55 volumio volumio-remote-updater[599]: [2024-11-21 14:28:55] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Nov 21 14:28:55 volumio volumio-remote-updater[599]: [2024-11-21 14:28:55] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Nov 21 14:28:55 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:55 volumio sudo[2615]: pam_unix(sudo:session): session closed for user root Nov 21 14:28:55 volumio systemd[1]: media-music17.mount: Succeeded. Nov 21 14:28:55 volumio systemd[1]: upmpdcli.service: Succeeded. Nov 21 14:28:55 volumio systemd[1]: Stopped UPnP Renderer front-end to MPD. Nov 21 14:28:55 volumio ntfs-3g[980]: Unmounting /dev/sda1 (music17) Nov 21 14:28:56 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Nov 21 14:28:56 volumio systemd[1]: Started dynamicswap service. Nov 21 14:28:56 volumio systemd[1]: dynamicswap.service: Succeeded. Nov 21 14:28:56 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Nov 21 14:28:56 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Nov 21 14:28:56 volumio systemd[1]: Started dynamicswap service. Nov 21 14:28:56 volumio systemd[1]: Stopped Volumio Backend Module. Nov 21 14:28:56 volumio systemd[1]: Started Volumio Backend Module. Nov 21 14:28:56 volumio systemd[1]: dynamicswap.service: Succeeded. Nov 21 14:28:57 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:28:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 69. Nov 21 14:28:57 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:28:57 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:28:57 volumio go-librespot[2667]: Librespot-go daemon starting... Nov 21 14:28:57 volumio go-librespot[2667]: time="2024-11-21T14:28:57+09:00" level=info msg="generated new device id: a252a7e9b060927f70be76968a63cc48e3ae9668" Nov 21 14:28:57 volumio go-librespot[2667]: time="2024-11-21T14:28:57+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:28:57 volumio go-librespot[2667]: time="2024-11-21T14:28:57+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:28:57 volumio go-librespot[2667]: time="2024-11-21T14:28:57+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:28:57 volumio go-librespot[2667]: time="2024-11-21T14:28:57+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:28:57 volumio go-librespot[2667]: time="2024-11-21T14:28:57+09:00" level=debug msg="zeroconf server listening on port 35543" Nov 21 14:28:57 volumio go-librespot[2667]: time="2024-11-21T14:28:57+09:00" level=debug msg="obtained new client token: AADoOoT3OCaQt3awRGB6ACi+zSAtZQdKb1iVWYzuz6r6KPTFPd/bS+tLpAlUmGgMXOgg+E+OXrBGZ91ZQ6kxJD7AOghVY8OK2dG8MIUbQnJmGiFEPKFX1NQwd1IVbF9JzVF5btrHWK5vrgO7DKo/9fB4jQMpwyqopZiciM5Wi1obiJTCvoA0rUmDWcJNCz1uENeL3VVgwURqf2okcLQ9b6epIaI8kzEcdHTs1eB4963FMWzi3aIomQIIqedlXiQ=" Nov 21 14:28:57 volumio go-librespot[2667]: time="2024-11-21T14:28:57+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:28:57 volumio go-librespot[2667]: time="2024-11-21T14:28:57+09:00" level=debug msg="completed keyexchange" Nov 21 14:28:58 volumio go-librespot[2667]: time="2024-11-21T14:28:58+09:00" level=debug msg="completed challenge" Nov 21 14:28:58 volumio go-librespot[2667]: time="2024-11-21T14:28:58+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:28:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:28:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:28:59 volumio volumio[2655]: info: ------------------------------------------- Nov 21 14:28:59 volumio volumio[2655]: info: ----- Volumio3 ---- Nov 21 14:28:59 volumio volumio[2655]: info: ------------------------------------------- Nov 21 14:28:59 volumio volumio[2655]: info: ----- System startup ---- Nov 21 14:28:59 volumio volumio[2655]: info: ------------------------------------------- Nov 21 14:29:00 volumio volumio-remote-updater[599]: [2024-11-21 14:29:00] [connect] Successful connection Nov 21 14:29:00 volumio volumio[2655]: info: MYVOLUMIO Environment detected Nov 21 14:29:00 volumio volumio[2655]: info: Plugin folders cleanup Nov 21 14:29:00 volumio volumio[2655]: info: Scanning into folder /volumio/app/plugins/ Nov 21 14:29:00 volumio volumio[2655]: info: Scanning category audio_interface Nov 21 14:29:00 volumio volumio[2655]: info: Scanning category miscellanea Nov 21 14:29:00 volumio volumio[2655]: info: Scanning category music_service Nov 21 14:29:00 volumio volumio[2655]: info: Scanning category plugins.json Nov 21 14:29:00 volumio volumio[2655]: info: Scanning category system_controller Nov 21 14:29:00 volumio volumio[2655]: info: Scanning category user_interface Nov 21 14:29:00 volumio volumio[2655]: info: Scanning into folder /data/plugins/ Nov 21 14:29:00 volumio volumio[2655]: info: Scanning category music_service Nov 21 14:29:00 volumio volumio[2655]: info: Plugin folders cleanup completed Nov 21 14:29:00 volumio volumio[2655]: info: ------------------------------------------- Nov 21 14:29:00 volumio volumio[2655]: info: ----- Core plugins startup ---- Nov 21 14:29:00 volumio volumio[2655]: info: ------------------------------------------- Nov 21 14:29:00 volumio volumio[2655]: info: Loading plugins from folder /volumio/app/plugins/ Nov 21 14:29:00 volumio volumio[2655]: info: Adding plugin upnp to MyMusic Plugins Nov 21 14:29:00 volumio volumio[2655]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 21 14:29:00 volumio volumio[2655]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 21 14:29:00 volumio volumio[2655]: info: Loading plugins from folder /data/plugins/ Nov 21 14:29:00 volumio volumio[2655]: info: Loading plugin "system"... Nov 21 14:29:00 volumio volumio[2655]: info: Loading plugin "appearance"... Nov 21 14:29:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:29:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 70. Nov 21 14:29:01 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:29:01 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:29:01 volumio go-librespot[2690]: Librespot-go daemon starting... Nov 21 14:29:01 volumio go-librespot[2690]: time="2024-11-21T14:29:01+09:00" level=info msg="generated new device id: 9b3dc367cd97e4e2cbe87cc68c6e59bea12bb087" Nov 21 14:29:01 volumio go-librespot[2690]: time="2024-11-21T14:29:01+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:29:01 volumio go-librespot[2690]: time="2024-11-21T14:29:01+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:29:01 volumio go-librespot[2690]: time="2024-11-21T14:29:01+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:29:01 volumio go-librespot[2690]: time="2024-11-21T14:29:01+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:29:01 volumio go-librespot[2690]: time="2024-11-21T14:29:01+09:00" level=debug msg="zeroconf server listening on port 40003" Nov 21 14:29:01 volumio go-librespot[2690]: time="2024-11-21T14:29:01+09:00" level=debug msg="obtained new client token: AABcsodGsWf869GrduLZq0CbAWPiMQezXGmed63OYfrbZK6yCdlEsn1mXj4g2up2UCTZ1rxGB9JvhwZsvJRb5gQt1yc2qJV9EtKj6arD6P2mmt7pzxFrzp4j2QEF/pm1soq0kUUMkjRBWnyTH9FvMmXnG268S5EsPFdjlfHvSqTK/8iwROJrBt9OJISRI0UpxQiQqN7LrZg+N+ImVNAqLjBkUNHmX5BQhQQlZcjsuGO701rsgy+cf/Yuf/LYF5g=" Nov 21 14:29:01 volumio go-librespot[2690]: time="2024-11-21T14:29:01+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:29:01 volumio go-librespot[2690]: time="2024-11-21T14:29:01+09:00" level=debug msg="completed keyexchange" Nov 21 14:29:02 volumio volumio[2655]: info: Loading plugin "network"... Nov 21 14:29:02 volumio go-librespot[2690]: time="2024-11-21T14:29:02+09:00" level=debug msg="completed challenge" Nov 21 14:29:02 volumio volumio[2655]: info: Refreshing Cached IP Addresses Nov 21 14:29:02 volumio sudo[2699]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 21 14:29:02 volumio sudo[2699]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:29:02 volumio sudo[2699]: pam_unix(sudo:session): session closed for user root Nov 21 14:29:02 volumio sudo[2701]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 21 14:29:02 volumio sudo[2701]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:29:02 volumio volumio[2655]: info: Loading plugin "services"... Nov 21 14:29:02 volumio go-librespot[2690]: time="2024-11-21T14:29:02+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:29:02 volumio volumio[2655]: info: Loading plugin "alsa_controller"... Nov 21 14:29:02 volumio sudo[2701]: pam_unix(sudo:session): session closed for user root Nov 21 14:29:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:29:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:29:02 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 21 14:29:02 volumio volumio[2655]: info: Loading plugin "wizard"... Nov 21 14:29:02 volumio volumio[2655]: info: Loading plugin "networkfs"... Nov 21 14:29:02 volumio volumio[2655]: info: Starting Udev Watcher for removable devices Nov 21 14:29:02 volumio volumio[2655]: info: Ignoring mount for partition: boot Nov 21 14:29:02 volumio volumio[2655]: info: Ignoring mount for partition: volumio Nov 21 14:29:02 volumio volumio[2655]: info: Ignoring mount for partition: volumio_data Nov 21 14:29:02 volumio volumio[2655]: info: Mounting Device music17 Nov 21 14:29:02 volumio sudo[2725]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/music17 -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Nov 21 14:29:02 volumio sudo[2725]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:29:04 volumio ntfs-3g[2731]: Version 2017.3.23AR.3 integrated FUSE 28 Nov 21 14:29:04 volumio ntfs-3g[2731]: Mounted /dev/sda1 (Read-Write, label "music17", NTFS 3.1) Nov 21 14:29:04 volumio ntfs-3g[2731]: Cmdline options: rw,noatime,dmask=0000,fmask=0000,iocharset=utf8 Nov 21 14:29:04 volumio ntfs-3g[2731]: Mount options: iocharset=utf8,allow_other,nonempty,noatime,rw,default_permissions,fsname=/dev/sda1,blkdev,blksize=4096 Nov 21 14:29:04 volumio ntfs-3g[2731]: Global ownership and permissions enforced, configuration type 7 Nov 21 14:29:04 volumio sudo[2725]: pam_unix(sudo:session): session closed for user root Nov 21 14:29:04 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 21 14:29:04 volumio volumio[2655]: info: Loading plugin "volumio_command_line_client"... Nov 21 14:29:04 volumio volumio[2655]: info: Loading plugin "upnp"... Nov 21 14:29:04 volumio volumio[2655]: info: [1732166944185] Starting Upmpd Daemon Nov 21 14:29:04 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 21 14:29:04 volumio volumio[2655]: info: Loading plugin "my_music"... Nov 21 14:29:04 volumio volumio[2655]: info: Loading plugin "mpd"... Nov 21 14:29:04 volumio volumio[2655]: info: Loading plugin "upnp_browser"... Nov 21 14:29:05 volumio volumio[2655]: info: Loading plugin "alarm-clock"... Nov 21 14:29:05 volumio volumio[2655]: info: Loading plugin "airplay_emulation"... Nov 21 14:29:05 volumio volumio[2655]: info: Starting Shairport Sync Nov 21 14:29:05 volumio volumio[2655]: info: Loading plugin "last_100"... Nov 21 14:29:05 volumio volumio[2655]: info: Loading plugin "webradio"... Nov 21 14:29:05 volumio volumio[2655]: info: Loading plugin "i2s_dacs"... Nov 21 14:29:05 volumio volumio[2655]: info: I2S DAC not set, start Auto-detection Nov 21 14:29:05 volumio volumio[2655]: info: Loading plugin "volumiodiscovery"... Nov 21 14:29:05 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:29:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 71. Nov 21 14:29:05 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:29:05 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:29:05 volumio go-librespot[2733]: Librespot-go daemon starting... Nov 21 14:29:05 volumio volumio[2655]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 21 14:29:05 volumio volumio[2655]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 21 14:29:05 volumio volumio[2655]: *** WARNING *** For more information see Nov 21 14:29:05 volumio volumio[2655]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 21 14:29:05 volumio node[2655]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 21 14:29:05 volumio volumio[2655]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 21 14:29:05 volumio volumio[2655]: *** WARNING *** For more information see Nov 21 14:29:05 volumio node[2655]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 21 14:29:05 volumio node[2655]: *** WARNING *** For more information see Nov 21 14:29:05 volumio node[2655]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 21 14:29:05 volumio node[2655]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 21 14:29:05 volumio node[2655]: *** WARNING *** For more information see Nov 21 14:29:05 volumio volumio[2655]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 21 14:29:05 volumio go-librespot[2733]: time="2024-11-21T14:29:05+09:00" level=info msg="generated new device id: 048f691be2c59f25446be3af02f245ba19bbac3d" Nov 21 14:29:05 volumio go-librespot[2733]: time="2024-11-21T14:29:05+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:29:05 volumio volumio[2655]: info: Discovery: Started advertising with name: Volumio Nov 21 14:29:05 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 21 14:29:05 volumio volumio[2655]: info: Loading plugin "spop"... Nov 21 14:29:05 volumio go-librespot[2733]: time="2024-11-21T14:29:05+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:29:05 volumio go-librespot[2733]: time="2024-11-21T14:29:05+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:29:05 volumio go-librespot[2733]: time="2024-11-21T14:29:05+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:29:05 volumio go-librespot[2733]: time="2024-11-21T14:29:05+09:00" level=debug msg="zeroconf server listening on port 34011" Nov 21 14:29:05 volumio go-librespot[2733]: time="2024-11-21T14:29:05+09:00" level=debug msg="obtained new client token: AAACHf3NNEED+RalyJKQTB275ci1c5JHfO9wWygRADmVJ1IKeqDZfVYt5vfrJdDSFUMpQsf9b7RTCnXQkBTwh0XCJhYAsXfm/aPCkrrFPVAWqkV9Gs1tRE+z7VPiLLxmLN3gUspeoWCl0HAFy1obS/WEOiu2r+r+oE9TWAVYhOF2UP9+RBdwBeM6wWMpltKwsLoQ3HtQGYASrefueEkmpYhG/LvNRuA0qx9HWwZQ4My8gZNDFdPWYWi22Flegus=" Nov 21 14:29:06 volumio go-librespot[2733]: time="2024-11-21T14:29:06+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:29:06 volumio go-librespot[2733]: time="2024-11-21T14:29:06+09:00" level=debug msg="completed keyexchange" Nov 21 14:29:06 volumio go-librespot[2733]: time="2024-11-21T14:29:06+09:00" level=debug msg="completed challenge" Nov 21 14:29:06 volumio go-librespot[2733]: time="2024-11-21T14:29:06+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:29:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:29:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:29:07 volumio volumio[2655]: info: Loading plugin "youtube2"... Nov 21 14:29:09 volumio volumio[2655]: info: Loading plugin "ytcr"... Nov 21 14:29:09 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:29:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 72. Nov 21 14:29:09 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:29:09 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:29:09 volumio go-librespot[2746]: Librespot-go daemon starting... Nov 21 14:29:09 volumio go-librespot[2746]: time="2024-11-21T14:29:09+09:00" level=info msg="generated new device id: f72e9c3950cac33a8e27b9b2d7d6798b733e4b0b" Nov 21 14:29:09 volumio go-librespot[2746]: time="2024-11-21T14:29:09+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:29:10 volumio go-librespot[2746]: time="2024-11-21T14:29:10+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:29:10 volumio go-librespot[2746]: time="2024-11-21T14:29:10+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:29:10 volumio go-librespot[2746]: time="2024-11-21T14:29:10+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:29:10 volumio go-librespot[2746]: time="2024-11-21T14:29:10+09:00" level=debug msg="zeroconf server listening on port 41595" Nov 21 14:29:10 volumio go-librespot[2746]: time="2024-11-21T14:29:10+09:00" level=debug msg="obtained new client token: AAAQBnlOFRJujSARZLMXmHktBXA+wRTF0QUwxQIkq8Xdzdxgvxk6nRZHz+G6GQoJl/Dbcis9JoEO+DsTxUsCZtU/3MPoTNfsz3Pk4b8RXiECopkKzX17+fTA+Sg7QN+ljz/723BqDiY3vvEFA8+Z2ieRyHiHvW9/K6g7fNPndfA4cq5l6h/q/ufdsnEF5ekNf/1lVYDq8Suz0L1BzvBVfH97SBwmpPYsT2lsol4yg2nhOCdim57JF22T9STwcOc=" Nov 21 14:29:10 volumio go-librespot[2746]: time="2024-11-21T14:29:10+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:29:10 volumio go-librespot[2746]: time="2024-11-21T14:29:10+09:00" level=debug msg="completed keyexchange" Nov 21 14:29:10 volumio go-librespot[2746]: time="2024-11-21T14:29:10+09:00" level=debug msg="completed challenge" Nov 21 14:29:11 volumio go-librespot[2746]: time="2024-11-21T14:29:11+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:29:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:29:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:29:12 volumio volumio[2655]: info: Loading plugin "ytmusic"... Nov 21 14:29:13 volumio volumio-remote-updater[599]: [2024-11-21 14:29:13] [connect] Successful connection Nov 21 14:29:13 volumio volumio[2655]: info: Loading plugin "outputs"... Nov 21 14:29:13 volumio volumio[2655]: info: Loading plugin "albumart"... Nov 21 14:29:13 volumio volumio[2655]: info: Plugin example_plugin is not enabled Nov 21 14:29:13 volumio volumio[2655]: info: Loading plugin "inputs"... Nov 21 14:29:13 volumio volumio[2655]: info: Loading plugin "updater_comm"... Nov 21 14:29:13 volumio volumio[2655]: info: Plugin mpdemulation is not enabled Nov 21 14:29:13 volumio volumio[2655]: info: Loading plugin "rest_api"... Nov 21 14:29:13 volumio volumio[2655]: info: Loading plugin "websocket"... Nov 21 14:29:13 volumio volumio[2655]: info: Starting Socket.io Server version 2.3.0 Nov 21 14:29:13 volumio volumio[2655]: info: Loading plugin "minidlna"... Nov 21 14:29:14 volumio volumio[2655]: Forking 3 albumart workers Nov 21 14:29:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:29:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 73. Nov 21 14:29:14 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:29:14 volumio volumio[2655]: info: Applying required configuration parameters for plugin minidlna Nov 21 14:29:14 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:29:14 volumio go-librespot[2779]: Librespot-go daemon starting... Nov 21 14:29:14 volumio go-librespot[2779]: time="2024-11-21T14:29:14+09:00" level=info msg="generated new device id: 8813ae4ab8006f8f2300d5fd3471ec3b48d4a57d" Nov 21 14:29:14 volumio go-librespot[2779]: time="2024-11-21T14:29:14+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" Nov 21 14:29:14 volumio go-librespot[2779]: time="2024-11-21T14:29:14+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 21 14:29:14 volumio go-librespot[2779]: time="2024-11-21T14:29:14+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 21 14:29:14 volumio go-librespot[2779]: time="2024-11-21T14:29:14+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 21 14:29:14 volumio go-librespot[2779]: time="2024-11-21T14:29:14+09:00" level=debug msg="zeroconf server listening on port 35269" Nov 21 14:29:14 volumio volumio[2655]: info: Loading plugin "motherearthradio"... Nov 21 14:29:14 volumio go-librespot[2779]: time="2024-11-21T14:29:14+09:00" level=debug msg="obtained new client token: AAC9Y7S0OMZpb6TcCkN/YZ+t2Rw7XumYbmoXBAOjWXD2xaGj0AFLKpM1wHuc6oRqehc7B9rICoN6uMMxzGRflHnHuzjX52ioWO6e0jkUDTcAy7GPcmarsIbA8xJOhvk/wz6GhwPDtFZ757zDxBRNwLerr94gHlmYH9ODzFheSIj9nRCTd/kvMUMQd9cr1SBFngpXpCdy7/BYYuYQyqDiyoZnaLDp+8fwE92dHyKjQsy39NvV6bKCsTOGmfVE3OY=" Nov 21 14:29:14 volumio go-librespot[2779]: time="2024-11-21T14:29:14+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 21 14:29:14 volumio go-librespot[2779]: time="2024-11-21T14:29:14+09:00" level=debug msg="completed keyexchange" Nov 21 14:29:15 volumio go-librespot[2779]: time="2024-11-21T14:29:15+09:00" level=debug msg="completed challenge" Nov 21 14:29:15 volumio volumio[2655]: info: Applying required configuration parameters for plugin motherearthradio Nov 21 14:29:15 volumio volumio[2655]: info: [1732166955230] [MotherEarth] API delay: 5 Nov 21 14:29:15 volumio volumio[2655]: Starting albumart workers Nov 21 14:29:15 volumio volumio[2655]: info: Loading i18n strings for locale ko Nov 21 14:29:15 volumio go-librespot[2779]: time="2024-11-21T14:29:15+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 21 14:29:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 21 14:29:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 21 14:29:15 volumio volumio[2655]: error: minidlna: Fetching language file: Error: i18n file complementing the system language not found. Nov 21 14:29:15 volumio volumio[2655]: Updating browse sources language Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 21 14:29:15 volumio volumio[2655]: Starting albumart workers Nov 21 14:29:15 volumio volumio[2655]: Starting albumart workers Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::initPlayerControls Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 21 14:29:15 volumio volumio[2655]: Express server listening on port 3000 Nov 21 14:29:15 volumio volumio[2655]: [Metrics] WebUI: 16s 953.20ms Nov 21 14:29:15 volumio volumio[2655]: info: CoreStateMachine::resetVolumioState Nov 21 14:29:15 volumio volumio[2655]: info: CoreStateMachine::getcurrentVolume Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::volumioRetrievevolume Nov 21 14:29:15 volumio volumio[2655]: info: CoreStateMachine::pushState Nov 21 14:29:15 volumio volumio[2655]: info: CorePlayQueue::getTrack 0 Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::volumioPushState Nov 21 14:29:15 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 21 14:29:15 volumio sudo[2812]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 21 14:29:15 volumio sudo[2812]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:29:15 volumio sudo[2812]: pam_unix(sudo:session): session closed for user root Nov 21 14:29:15 volumio sudo[2814]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 21 14:29:15 volumio sudo[2814]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:29:15 volumio sudo[2814]: pam_unix(sudo:session): session closed for user root Nov 21 14:29:16 volumio volumio[2655]: info: Volumio Network Manager: Network status updated: 1 Nov 21 14:29:16 volumio volumio[2655]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.38 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36 Edg/131.0.0.0 Engine version: 3 Transport: polling Total Clients: 1 Nov 21 14:29:16 volumio volumio[2655]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.38 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36 Edg/131.0.0.0 Engine version: 3 Transport: polling Total Clients: 2 Nov 21 14:29:16 volumio volumio[2655]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.38 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36 Edg/131.0.0.0 Engine version: 3 Transport: polling Total Clients: 3 Nov 21 14:29:16 volumio volumio-remote-updater[599]: [2024-11-21 14:29:16] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1732166953 101 Nov 21 14:29:16 volumio volumio[2655]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 4 Nov 21 14:29:16 volumio volumio[2655]: info: Reloading queue from file Nov 21 14:29:16 volumio volumio[2655]: info: CoreStateMachine::setRepeat null single undefined Nov 21 14:29:16 volumio volumio[2655]: info: CoreStateMachine::pushState Nov 21 14:29:16 volumio volumio[2655]: info: CorePlayQueue::getTrack 0 Nov 21 14:29:16 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 21 14:29:16 volumio volumio[2655]: info: CoreCommandRouter::volumioPushState Nov 21 14:29:16 volumio volumio[2655]: info: CoreStateMachine::setRandom null Nov 21 14:29:16 volumio volumio[2655]: info: CoreStateMachine::pushState Nov 21 14:29:16 volumio volumio[2655]: info: CorePlayQueue::getTrack 0 Nov 21 14:29:16 volumio volumio[2655]: info: CoreCommandRouter::volumioPushState Nov 21 14:29:16 volumio volumio[2655]: info: Setting Device type: Raspberry PI Nov 21 14:29:16 volumio volumio[2655]: info: Completed loading Core Plugins Nov 21 14:29:16 volumio volumio[2655]: info: Preparing to generate the ALSA configuration file Nov 21 14:29:16 volumio volumio[2655]: info: Discovery: adding ccc85282-40ce-4e92-94c8-1a2cccd1125e Nov 21 14:29:16 volumio volumio[2655]: info: Discovery: Found device Volumio Nov 21 14:29:16 volumio volumio[2655]: info: CoreCommandRouter::volumioGetState Nov 21 14:29:16 volumio volumio[2655]: info: CorePlayQueue::getTrack 0 Nov 21 14:29:16 volumio sudo[2839]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 21 14:29:16 volumio sudo[2839]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:29:16 volumio volumio[2655]: info: Asound.conf file unchanged, so no further update is needed Nov 21 14:29:16 volumio volumio[2655]: info: Output device has changed, restarting MPD Nov 21 14:29:16 volumio sudo[2846]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 21 14:29:16 volumio sudo[2846]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:29:16 volumio volumio[2655]: info: Output device has changed, restarting Shairport Sync Nov 21 14:29:16 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:29:16 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 21 14:29:16 volumio sudo[2846]: pam_unix(sudo:session): session closed for user root Nov 21 14:29:16 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Nov 21 14:29:16 volumio sudo[2854]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 21 14:29:16 volumio sudo[2854]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:29:16 volumio sudo[2839]: pam_unix(sudo:session): session closed for user root Nov 21 14:29:16 volumio systemd[1]: Stopping Music Player Daemon... Nov 21 14:29:16 volumio volumio[2655]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 21 14:29:16 volumio volumio[2655]: info: ___________ START PLUGINS ___________ Nov 21 14:29:16 volumio volumio[2655]: info: ControllerMpd::onStart: Initializing MPD Nov 21 14:29:16 volumio volumio[2655]: info: Creating MPD Configuration file Nov 21 14:29:16 volumio sudo[2860]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 21 14:29:16 volumio sudo[2860]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:29:16 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 21 14:29:16 volumio volumio[2655]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 21 14:29:16 volumio volumio[2655]: info: [1732166956958] CoreMusicLibrary::Adding element 미디어 서버 Nov 21 14:29:16 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 21 14:29:16 volumio sudo[2860]: pam_unix(sudo:session): session closed for user root Nov 21 14:29:16 volumio sudo[2863]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 21 14:29:16 volumio sudo[2863]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:29:16 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 21 14:29:17 volumio volumio[2655]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 21 14:29:17 volumio systemd[1]: mpd.service: Succeeded. Nov 21 14:29:17 volumio volumio[2655]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 21 14:29:17 volumio systemd[1]: Stopped Music Player Daemon. Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 21 14:29:17 volumio volumio[2655]: info: [1732166957128] CoreMusicLibrary::Adding element Last_100 Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 21 14:29:17 volumio volumio[2655]: info: [1732166957138] CoreMusicLibrary::Adding element Webradio Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 21 14:29:17 volumio volumio[2655]: info: Initializing BBC Radios Nov 21 14:29:17 volumio systemd[1]: Starting Music Player Daemon... Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 21 14:29:17 volumio volumio[2655]: info: Creating Spotify config file Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 21 14:29:17 volumio sudo[2871]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 21 14:29:17 volumio sudo[2871]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:29:17 volumio sudo[2871]: pam_unix(sudo:session): session closed for user root Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 21 14:29:17 volumio volumio[2655]: info: [1732166957380] CoreMusicLibrary::Adding element YouTube2 Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 21 14:29:17 volumio volumio[2655]: Cannot find translation for source YouTube2 Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 21 14:29:17 volumio volumio[2655]: info: [1732166957441] CoreMusicLibrary::Adding element YouTube Music Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 21 14:29:17 volumio volumio[2655]: Cannot find translation for source YouTube2 Nov 21 14:29:17 volumio volumio[2655]: Cannot find translation for source YouTube Music Nov 21 14:29:17 volumio volumio[2655]: info: Loading i18n strings for locale ko Nov 21 14:29:17 volumio volumio[2655]: error: minidlna: Fetching language file: Error: i18n file complementing the system language not found. Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 21 14:29:17 volumio volumio[2655]: info: [1732166957500] CoreMusicLibrary::Adding element Mother Earth Radio Nov 21 14:29:17 volumio volumio[2655]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 21 14:29:17 volumio volumio[2655]: Cannot find translation for source YouTube2 Nov 21 14:29:17 volumio volumio[2655]: Cannot find translation for source YouTube Music Nov 21 14:29:17 volumio volumio[2655]: Cannot find translation for source Mother Earth Radio Nov 21 14:29:17 volumio volumio[2655]: info: Volumio Calling Home Nov 21 14:29:17 volumio volumio[2655]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.38 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36 Edg/131.0.0.0 Engine version: 3 Transport: polling Total Clients: 5 Nov 21 14:29:17 volumio volumio[2655]: info: MPD Permissions set Nov 21 14:29:17 volumio volumio[2655]: info: MPD Permissions set Nov 21 14:29:17 volumio volumio[2655]: info: Upmpdcli Daemon Started Nov 21 14:29:17 volumio volumio[2655]: info: Enabling MyMusic plugin tidalconnect Nov 21 14:29:17 volumio volumio[2655]: info: [MyVolumio PluginManager] Enabling and starting plugin music_service tidalconnect Nov 21 14:29:17 volumio volumio[2655]: info: [MyVolumio PluginManager] Plugin music_service tidalconnect not in user plan, not enabling Nov 21 14:29:17 volumio volumio[2655]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 21 14:29:17 volumio volumio[2655]: TypeError: Cannot read property 'toUpperCase' of undefined Nov 21 14:29:17 volumio volumio[2655]: at MyVolumioPluginManager.pushMyVolumioRequiredAccountModal (/myvolumio/app/myvolumio-pluginmanager/myvolumio_pluginmanager_real:1:19516) Nov 21 14:29:17 volumio volumio[2655]: at MyVolumioPluginManager.enablePlugin (/myvolumio/app/myvolumio-pluginmanager/myvolumio_pluginmanager_real:1:18418) Nov 21 14:29:17 volumio volumio[2655]: at MyVolumioPluginManager.enableAndStartPlugin (/myvolumio/app/myvolumio-pluginmanager/myvolumio_pluginmanager_real:1:17039) Nov 21 14:29:17 volumio volumio[2655]: at PluginManager.enableDisableMyMusicPlugin (/volumio/app/pluginmanager.js:2024:48) Nov 21 14:29:17 volumio volumio[2655]: at CoreCommandRouter.enableDisableMyMusicPlugin (/volumio/app/index.js:2102:29) Nov 21 14:29:17 volumio volumio[2655]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1929:59) Nov 21 14:29:17 volumio volumio[2655]: at Socket.emit (events.js:315:20) Nov 21 14:29:17 volumio volumio[2655]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Nov 21 14:29:17 volumio volumio[2655]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Nov 21 14:29:17 volumio volumio[2655]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 21 14:29:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 21 14:29:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 74. Nov 21 14:29:18 volumio systemd[1]: Stopped go-librespot Daemon. Nov 21 14:29:18 volumio sudo[2899]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-21 14:28 Nov 21 14:29:18 volumio sudo[2899]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 21 14:29:18 volumio systemd[1]: Started go-librespot Daemon. Nov 21 14:29:18 volumio go-librespot[2898]: Librespot-go daemon starting... Nov 21 14:29:18 volumio go-librespot[2898]: time="2024-11-21T14:29:18+09:00" level=info msg="generated new device id: 88d5ef18d5b862a30942d9e5e0aef9ecc9bd95a5" Nov 21 14:29:18 volumio go-librespot[2898]: time="2024-11-21T14:29:18+09:00" level=debug msg="stored credentials found for 31cfgj6ozcovh3gr5a4ax4w2kvhe" 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="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"