-- Logs begin at Thu 2024-04-25 06:43:03 CDT, end at Thu 2024-04-25 13:41:37 CDT. -- Apr 25 12:40:08 volumio go-librespot[28513]: time="2024-04-25T12:40:08-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: i/o timeout" Apr 25 12:40:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 12:40:08 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 12:40:08 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 12:40:08 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 12:40:08 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 12:40:08 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 12:40:08 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 12:40:08 volumio volumio[832]: (node:832) 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: 195) Apr 25 12:40:08 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 12:40:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 12:40:11 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:40:11 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 12:40:12 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 12:40:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 199. Apr 25 12:40:12 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 12:40:12 volumio systemd[1]: Started go-librespot Daemon. Apr 25 12:40:12 volumio go-librespot[28584]: Librespot-go daemon starting... Apr 25 12:40:12 volumio go-librespot[28584]: time="2024-04-25T12:40:12-05:00" level=info msg="generated new device id: 714cb8b8b090e40e605a8d3548e9155fc612763c" Apr 25 12:40:12 volumio go-librespot[28584]: time="2024-04-25T12:40:12-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:40:14 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:40:14 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 12:40:14 volumio go-librespot[28584]: time="2024-04-25T12:40:14-05:00" level=debug msg="new websocket client" Apr 25 12:40:18 volumio volumio[832]: info: Getting Spotify volume Apr 25 12:40:18 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 12:40:18 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 12:40:18 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 12:40:18 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 12:40:34 volumio go-librespot[28584]: time="2024-04-25T12:40:34-05:00" level=debug msg="obtained new client token: AAAYnXsOnLB8xkVygDx8Q56lWBpolGCmG1RhDlrxSHC5vLBftm7XFd9y3cDk06fowfG3BgEUYnP4gzqTnwjdkZ0SKPA4UtAOKvF1DlIat/quzCtAY3MVChUNtC/o+3LHE9XQECBawaW3ksSHTMVGWz1yb7fqxQy3c/YgyomSZUuqj4zEVsIli0ygtxYZP6nkPR1/xckVstZa7wnAImXu7UXXhjKMaLWQgqOthNz7LImWG4xI+I9miJPH4K4xIi6ntQ==" Apr 25 12:41:18 volumio go-librespot[28584]: time="2024-04-25T12:41:18-05:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 25 12:41:48 volumio go-librespot[28584]: time="2024-04-25T12:41:48-05:00" level=debug msg="completed keyexchange" Apr 25 12:41:49 volumio go-librespot[28584]: time="2024-04-25T12:41:49-05:00" level=debug msg="completed challenge" Apr 25 12:41:49 volumio go-librespot[28584]: time="2024-04-25T12:41:49-05:00" level=debug msg="authenticated as txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:42:16 volumio go-librespot[28584]: time="2024-04-25T12:42:16-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed requesting login5 endpoint: failed requesting login5: Post \"https://login5.spotify.com/v3/login\": net/http: TLS handshake timeout" Apr 25 12:42:16 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 12:42:16 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 12:42:16 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 12:42:16 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 12:42:16 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 12:42:16 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 12:42:16 volumio volumio[832]: (node:832) 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: 196) Apr 25 12:42:16 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 12:42:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 12:42:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 12:42:19 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:42:19 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 12:42:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 12:42:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 200. Apr 25 12:42:19 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 12:42:19 volumio systemd[1]: Started go-librespot Daemon. Apr 25 12:42:19 volumio go-librespot[28722]: Librespot-go daemon starting... Apr 25 12:42:19 volumio go-librespot[28722]: time="2024-04-25T12:42:19-05:00" level=info msg="generated new device id: d7a0f2126b1388db5a36d578c4da2a1c09f154a4" Apr 25 12:42:19 volumio go-librespot[28722]: time="2024-04-25T12:42:19-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:42:22 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:42:22 volumio go-librespot[28722]: time="2024-04-25T12:42:22-05:00" level=debug msg="new websocket client" Apr 25 12:42:22 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 12:42:25 volumio volumio[832]: info: Getting Spotify volume Apr 25 12:42:25 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 12:42:25 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 12:42:25 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 12:42:25 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 12:42:57 volumio go-librespot[28722]: time="2024-04-25T12:42:57-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": net/http: TLS handshake timeout" Apr 25 12:42:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 12:42:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 12:42:57 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 12:42:57 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 12:42:57 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 12:42:57 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 12:42:57 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 12:42:57 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 12:42:57 volumio volumio[832]: (node:832) 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: 197) Apr 25 12:42:57 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 12:43:00 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:43:00 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 12:43:00 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 12:43:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 201. Apr 25 12:43:00 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 12:43:00 volumio systemd[1]: Started go-librespot Daemon. Apr 25 12:43:00 volumio go-librespot[28788]: Librespot-go daemon starting... Apr 25 12:43:00 volumio go-librespot[28788]: time="2024-04-25T12:43:00-05:00" level=info msg="generated new device id: acca51c80130faff90dd85644a09903650d581b5" Apr 25 12:43:00 volumio go-librespot[28788]: time="2024-04-25T12:43:00-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:43:03 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:43:03 volumio go-librespot[28788]: time="2024-04-25T12:43:03-05:00" level=debug msg="new websocket client" Apr 25 12:43:03 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 12:43:06 volumio volumio[832]: info: Getting Spotify volume Apr 25 12:43:06 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 12:43:06 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 12:43:06 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 12:43:06 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 12:43:14 volumio systemd[1]: Stopping Network Time Service... Apr 25 12:43:14 volumio ntpd[1156]: ntpd exiting on signal 15 (Terminated) Apr 25 12:43:14 volumio ntpd[1156]: 193.182.111.13 local addr 192.168.1.244 -> Apr 25 12:43:14 volumio ntpd[1156]: 192.36.143.130 local addr 192.168.1.244 -> Apr 25 12:43:14 volumio ntpd[1156]: 45.183.178.195 local addr 192.168.1.244 -> Apr 25 12:43:14 volumio ntpd[1156]: 45.231.168.6 local addr 192.168.1.244 -> Apr 25 12:43:14 volumio ntpd[1156]: 132.248.30.3 local addr 192.168.1.244 -> Apr 25 12:43:14 volumio ntpd[1156]: 216.238.85.87 local addr 192.168.1.244 -> Apr 25 12:43:14 volumio systemd[1]: ntp.service: Succeeded. Apr 25 12:43:15 volumio systemd[1]: Stopped Network Time Service. Apr 25 12:43:15 volumio systemd[1]: Starting Network Time Service... Apr 25 12:43:15 volumio ntpd[28833]: ntpd 4.2.8p12@1.3728-o (1): Starting Apr 25 12:43:15 volumio ntpd[28833]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Apr 25 12:43:15 volumio systemd[1]: Started Network Time Service. Apr 25 12:43:15 volumio ntpd[28840]: proto: precision = 1.396 usec (-19) Apr 25 12:43:15 volumio ntpd[28840]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Apr 25 12:43:15 volumio ntpd[28840]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Apr 25 12:43:15 volumio ntpd[28840]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 485 days ago Apr 25 12:43:15 volumio ntpd[28840]: Listen and drop on 0 v6wildcard [::]:123 Apr 25 12:43:15 volumio ntpd[28840]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Apr 25 12:43:15 volumio ntpd[28840]: Listen normally on 2 lo 127.0.0.1:123 Apr 25 12:43:15 volumio ntpd[28840]: Listen normally on 3 eth0 192.168.1.244:123 Apr 25 12:43:15 volumio ntpd[28840]: Listen normally on 4 wlan0 192.168.211.1:123 Apr 25 12:43:15 volumio ntpd[28840]: Listen normally on 5 wlan0 169.254.4.24:123 Apr 25 12:43:15 volumio ntpd[28840]: Listening on routing socket on fd #22 for interface updates Apr 25 12:43:15 volumio ntpd[28840]: kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized Apr 25 12:43:15 volumio ntpd[28840]: kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized Apr 25 12:43:15 volumio ntpd[28840]: ntpd exiting on signal 15 (Terminated) Apr 25 12:43:15 volumio systemd[1]: Stopping Network Time Service... Apr 25 12:43:15 volumio systemd[1]: ntp.service: Succeeded. Apr 25 12:43:15 volumio systemd[1]: Stopped Network Time Service. Apr 25 12:43:15 volumio systemd[1]: Starting Network Time Service... Apr 25 12:43:15 volumio ntpd[28874]: ntpd 4.2.8p12@1.3728-o (1): Starting Apr 25 12:43:15 volumio ntpd[28874]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Apr 25 12:43:15 volumio systemd[1]: Started Network Time Service. Apr 25 12:43:15 volumio ntpd[28880]: proto: precision = 1.397 usec (-19) Apr 25 12:43:15 volumio ntpd[28880]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Apr 25 12:43:15 volumio ntpd[28880]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Apr 25 12:43:15 volumio ntpd[28880]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 485 days ago Apr 25 12:43:15 volumio ntpd[28880]: Listen and drop on 0 v6wildcard [::]:123 Apr 25 12:43:15 volumio ntpd[28880]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Apr 25 12:43:15 volumio ntpd[28880]: Listen normally on 2 lo 127.0.0.1:123 Apr 25 12:43:15 volumio ntpd[28880]: Listen normally on 3 eth0 192.168.1.244:123 Apr 25 12:43:15 volumio ntpd[28880]: Listen normally on 4 wlan0 192.168.211.1:123 Apr 25 12:43:15 volumio ntpd[28880]: Listen normally on 5 wlan0 169.254.4.24:123 Apr 25 12:43:15 volumio ntpd[28880]: Listening on routing socket on fd #22 for interface updates Apr 25 12:43:15 volumio ntpd[28880]: kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized Apr 25 12:43:15 volumio ntpd[28880]: kernel reports TIME_ERROR: 0x2041: Clock Unsynchronized Apr 25 12:43:22 volumio ntpd[28880]: Soliciting pool server 192.36.143.130 Apr 25 12:43:30 volumio go-librespot[28788]: time="2024-04-25T12:43:30-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp 35.186.224.25:443: i/o timeout" Apr 25 12:43:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 12:43:30 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 12:43:30 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 12:43:30 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 12:43:30 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 12:43:30 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 12:43:30 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 12:43:30 volumio volumio[832]: (node:832) 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: 198) Apr 25 12:43:30 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 12:43:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 12:43:32 volumio ntpd[28880]: Soliciting pool server 45.231.168.6 Apr 25 12:43:33 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:43:33 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 12:43:33 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 12:43:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 202. Apr 25 12:43:33 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 12:43:33 volumio systemd[1]: Started go-librespot Daemon. Apr 25 12:43:33 volumio go-librespot[28883]: Librespot-go daemon starting... Apr 25 12:43:33 volumio go-librespot[28883]: time="2024-04-25T12:43:33-05:00" level=info msg="generated new device id: bdd85d2ae9f99f17434acae8939e29749ea42789" Apr 25 12:43:33 volumio go-librespot[28883]: time="2024-04-25T12:43:33-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:43:36 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:43:36 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 12:43:36 volumio go-librespot[28883]: time="2024-04-25T12:43:36-05:00" level=debug msg="new websocket client" Apr 25 12:43:37 volumio ntpd[28880]: Soliciting pool server 192.36.143.130 Apr 25 12:43:39 volumio volumio[832]: info: Getting Spotify volume Apr 25 12:43:39 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 12:43:39 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 12:43:39 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 12:43:39 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 12:43:42 volumio ntpd[28880]: Soliciting pool server 192.36.143.130 Apr 25 12:43:48 volumio go-librespot[28883]: time="2024-04-25T12:43:48-05:00" level=debug msg="obtained new client token: AADyt28RDEIhZcRil9Sp2aOADEV/vTIPAfvv0Fwlht4BgeoHlJOBnEFlPtCbOK2qdlbhBf13xbSiqlSM374B8MJFHd+Aq3UpMD8/1uMNsj75FAEZhPlFcGG6W+AlD5A7fvJOoBjq1FI9L1Jg6Vm4oSApkS34UOI1pKereuy4BbSqwtt6nHm+HILYDp5fdjBozDf1tSbj9syrO7Rx26E/T+igRLHrZzEDCLmc8gpP4EU7/+R3oRmOA75pU+c7YCztSQ==" Apr 25 12:43:48 volumio go-librespot[28883]: time="2024-04-25T12:43:48-05:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 25 12:43:48 volumio go-librespot[28883]: time="2024-04-25T12:43:48-05:00" level=debug msg="completed keyexchange" Apr 25 12:43:49 volumio go-librespot[28883]: time="2024-04-25T12:43:49-05:00" level=debug msg="completed challenge" Apr 25 12:43:49 volumio go-librespot[28883]: time="2024-04-25T12:43:49-05:00" level=debug msg="authenticated as txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:43:50 volumio go-librespot[28883]: time="2024-04-25T12:43:50-05:00" level=debug msg="authenticated as txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:43:51 volumio go-librespot[28883]: time="2024-04-25T12:43:51-05:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 25 12:43:52 volumio go-librespot[28883]: time="2024-04-25T12:43:52-05:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 25 12:43:58 volumio go-librespot[28883]: time="2024-04-25T12:43:58-05:00" level=debug msg="dealer connection opened" Apr 25 12:43:58 volumio go-librespot[28883]: time="2024-04-25T12:43:58-05:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 25 12:43:58 volumio go-librespot[28883]: time="2024-04-25T12:43:58-05:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 25 12:43:58 volumio go-librespot[28883]: time="2024-04-25T12:43:58-05:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 25 12:43:58 volumio go-librespot[28883]: time="2024-04-25T12:43:58-05:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 25 12:43:58 volumio go-librespot[28883]: time="2024-04-25T12:43:58-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" Apr 25 12:43:58 volumio volumio[832]: info: Spotify volume: 100 Apr 25 12:43:58 volumio go-librespot[28883]: time="2024-04-25T12:43:58-05:00" level=debug msg="received connection id: YzM4ZDFhOTYtNjEwNC00NzlmLTg5NjgtNWMwODNhMjBlZmQ0K2RlYWxlcit0Y3A6Ly9ndWMzLWRlYWxlci1hLXAyaG4uZ3VjMy5zcG90aWZ5Lm5ldDo1NzAwKzEwNkY2MjZFNzM1OTM2MjEyNjhGQTVGNjc4MkVEODhERUMyNTVCMENCMjhBNDJEODNGNUZGM0RDRUUyQzY3MDk=" Apr 25 12:44:21 volumio ntpd[28880]: Soliciting pool server 193.182.111.13 Apr 25 12:44:22 volumio ntpd[28880]: Soliciting pool server 45.183.178.195 Apr 25 12:44:23 volumio ntpd[28880]: Soliciting pool server 45.231.168.6 Apr 25 12:44:25 volumio ntpd[28880]: Soliciting pool server 193.182.111.13 Apr 25 12:44:31 volumio go-librespot[28883]: time="2024-04-25T12:44:31-05:00" level=debug msg="put connect state because NEW_DEVICE" Apr 25 12:45:27 volumio ntpd[28880]: Soliciting pool server 45.231.168.6 Apr 25 12:45:28 volumio ntpd[28880]: Soliciting pool server 193.182.111.13 Apr 25 12:45:28 volumio go-librespot[28883]: time="2024-04-25T12:45:28-05:00" level=error msg="did not receive last pong from dealer, 59s passed" Apr 25 12:45:30 volumio ntpd[28880]: Soliciting pool server 193.182.111.13 Apr 25 12:45:33 volumio go-librespot[28883]: time="2024-04-25T12:45:33-05:00" level=error msg="failed receiving dealer message" error="failed to get reader: WebSocket closed: sent close frame: status = StatusServiceRestart and reason = \"\"" Apr 25 12:45:34 volumio ntpd[28880]: Soliciting pool server 132.248.30.3 Apr 25 12:45:35 volumio ntpd[28880]: Soliciting pool server 45.231.168.6 Apr 25 12:45:58 volumio go-librespot[28883]: time="2024-04-25T12:45:58-05:00" level=error msg="did not receive last pong from dealer, 89s passed" Apr 25 12:45:58 volumio go-librespot[28883]: panic: runtime error: invalid memory address or nil pointer dereference Apr 25 12:45:58 volumio go-librespot[28883]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x158 pc=0x806931] Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 60 [running]: Apr 25 12:45:58 volumio go-librespot[28883]: panic({0x9857a0, 0xe4c480}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/panic.go:987 +0x3bb fp=0xc0000b9d60 sp=0xc0000b9ca0 pc=0x43a6db Apr 25 12:45:58 volumio go-librespot[28883]: runtime.panicmem(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/panic.go:260 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.sigpanic() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/signal_unix.go:841 +0x37d fp=0xc0000b9dc0 sp=0xc0000b9d60 pc=0x450f5d Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.(*Conn).writeClose(0x0, 0x3f4, {0x0, 0x0}) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/close_notjs.go:54 +0x51 fp=0xc0000b9e88 sp=0xc0000b9dc0 pc=0x806931 Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.(*Conn).closeHandshake(0xc0000b6000?, 0xc000000002?, {0x0?, 0x33?}) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/close_notjs.go:37 +0x7a fp=0xc0000b9f18 sp=0xc0000b9e88 pc=0x8066fa Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.(*Conn).Close(...) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/close_notjs.go:31 Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/dealer.(*Dealer).pingTicker(0xc000372000) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:114 +0x19f fp=0xc0000b9fc8 sp=0xc0000b9f18 pc=0x84467f Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/dealer.NewDealer.func1() Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:57 +0x26 fp=0xc0000b9fe0 sp=0xc0000b9fc8 pc=0x843f66 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0000b9fe8 sp=0xc0000b9fe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by go-librespot/dealer.NewDealer Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:57 +0x15a Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 1 [select, 2 minutes]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0xc00050f528?, 0x6?, 0x40?, 0xe1?, 0xc00050f3d4?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc00050f070 sp=0xc00050f050 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.selectgo(0xc00050f528, 0xc00050f3c8, 0xed?, 0x0, 0x0?, 0x1) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/select.go:327 +0x7be fp=0xc00050f1b0 sp=0xc00050f070 pc=0x44d45e Apr 25 12:45:58 volumio go-librespot[28883]: main.(*AppPlayer).Run(0xc000092460, 0xc0000943c0) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/player.go:361 +0x2af fp=0xc00050fd78 sp=0xc00050f1b0 pc=0x90ad4f Apr 25 12:45:58 volumio go-librespot[28883]: main.(*App).withReusableCredentials(0xc00008ee40, {0x9ae820?, 0xc0000e05c0?}) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:218 +0x5d5 fp=0xc00050fea8 sp=0xc00050fd78 pc=0x907735 Apr 25 12:45:58 volumio go-librespot[28883]: main.(*App).SpotifyToken(...) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:159 Apr 25 12:45:58 volumio go-librespot[28883]: main.main() Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:331 +0x5bc fp=0xc00050ff80 sp=0xc00050fea8 pc=0x9080dc Apr 25 12:45:58 volumio go-librespot[28883]: runtime.main() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:250 +0x207 fp=0xc00050ffe0 sp=0xc00050ff80 pc=0x43d447 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc00050ffe8 sp=0xc00050ffe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 2 [force gc (idle), 2 minutes]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0x13d24868b874?, 0x0?, 0x0?, 0x0?, 0x0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc000056fb0 sp=0xc000056f90 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goparkunlock(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:387 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.forcegchelper() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:305 +0xb0 fp=0xc000056fe0 sp=0xc000056fb0 pc=0x43d6b0 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc000056fe8 sp=0xc000056fe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by runtime.init.6 Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:293 +0x25 Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 18 [GC sweep wait]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0x1?, 0x0?, 0x0?, 0x0?, 0x0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc000052780 sp=0xc000052760 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goparkunlock(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:387 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.bgsweep(0x0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgcsweep.go:319 +0xde fp=0xc0000527c8 sp=0xc000052780 pc=0x429a1e Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gcenable.func1() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:178 +0x26 fp=0xc0000527e0 sp=0xc0000527c8 pc=0x41ec86 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0000527e8 sp=0xc0000527e0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by runtime.gcenable Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:178 +0x6b Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 19 [GC scavenge wait]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0x13d24aaaae98?, 0x3b9c28f1?, 0x0?, 0x0?, 0x0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc000052f70 sp=0xc000052f50 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goparkunlock(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:387 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.(*scavengerState).park(0xea16e0) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgcscavenge.go:400 +0x53 fp=0xc000052fa0 sp=0xc000052f70 pc=0x4278f3 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.bgscavenge(0x0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgcscavenge.go:633 +0x65 fp=0xc000052fc8 sp=0xc000052fa0 pc=0x427ee5 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gcenable.func2() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:179 +0x26 fp=0xc000052fe0 sp=0xc000052fc8 pc=0x41ec26 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc000052fe8 sp=0xc000052fe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by runtime.gcenable Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:179 +0xaa Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 20 [finalizer wait]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0x0?, 0xc000012120?, 0x40?, 0x60?, 0x1000000010?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc000056628 sp=0xc000056608 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.runfinq() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mfinal.go:193 +0x107 fp=0xc0000567e0 sp=0xc000056628 pc=0x41dcc7 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0000567e8 sp=0xc0000567e0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by runtime.createfing Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mfinal.go:163 +0x45 Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 21 [IO wait, 2 minutes]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0x0?, 0x0?, 0x0?, 0x0?, 0x0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc000069be8 sp=0xc000069bc8 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.netpollblock(0x7f6946159f08?, 0x40922f?, 0x0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/netpoll.go:527 +0xf7 fp=0xc000069c20 sp=0xc000069be8 pc=0x436117 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.runtime_pollWait(0x7f6946161eb8, 0x72) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/netpoll.go:306 +0x89 fp=0xc000069c40 sp=0xc000069c20 pc=0x4673a9 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.(*pollDesc).wait(0xc0000b6900?, 0x4?, 0x0) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_poll_runtime.go:84 +0x32 fp=0xc000069c68 sp=0xc000069c40 pc=0x4da132 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.(*pollDesc).waitRead(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_poll_runtime.go:89 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.(*FD).Accept(0xc0000b6900) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_unix.go:614 +0x2bd fp=0xc000069d10 sp=0xc000069c68 pc=0x4dfa3d Apr 25 12:45:58 volumio go-librespot[28883]: net.(*netFD).accept(0xc0000b6900) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/fd_unix.go:172 +0x35 fp=0xc000069dc8 sp=0xc000069d10 pc=0x658695 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*TCPListener).accept(0xc0000b0420) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/tcpsock_posix.go:148 +0x25 fp=0xc000069df0 sp=0xc000069dc8 pc=0x66f785 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*TCPListener).Accept(0xc0000b0420) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/tcpsock.go:297 +0x3d fp=0xc000069e20 sp=0xc000069df0 pc=0x66e87d Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*onceCloseListener).Accept(0xc000171e60?) Apr 25 12:45:58 volumio go-librespot[28883]: :1 +0x2a fp=0xc000069e38 sp=0xc000069e20 pc=0x7f30ca Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*Server).Serve(0xc000204000, {0xafda70, 0xc0000b0420}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/server.go:3059 +0x385 fp=0xc000069f68 sp=0xc000069e38 pc=0x7ce825 Apr 25 12:45:58 volumio go-librespot[28883]: net/http.Serve(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/server.go:2581 Apr 25 12:45:58 volumio go-librespot[28883]: main.(*ApiServer).serve(0xc000092370) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:438 +0x545 fp=0xc000069fc8 sp=0xc000069f68 pc=0x901a85 Apr 25 12:45:58 volumio go-librespot[28883]: main.NewApiServer.func1() Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:237 +0x26 fp=0xc000069fe0 sp=0xc000069fc8 pc=0x9011a6 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc000069fe8 sp=0xc000069fe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by main.NewApiServer Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:237 +0x176 Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 13 [select, 2 minutes]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0xc0001f9f98?, 0x2?, 0x8e?, 0xa7?, 0xc0001f9f7c?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc0001f9e00 sp=0xc0001f9de0 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.selectgo(0xc0001f9f98, 0xc0001f9f78, 0xea1660?, 0x0, 0x1?, 0x1) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/select.go:327 +0x7be fp=0xc0001f9f40 sp=0xc0001f9e00 pc=0x44d45e Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/ap.(*Accesspoint).pongAckTicker(0xc000206680) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:301 +0x7e fp=0xc0001f9fc8 sp=0xc0001f9f40 pc=0x82171e Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/ap.NewAccesspoint.func1() Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:66 +0x26 fp=0xc0001f9fe0 sp=0xc0001f9fc8 pc=0x81fbc6 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0001f9fe8 sp=0xc0001f9fe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by go-librespot/ap.NewAccesspoint Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:66 +0x176 Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 102 [select]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0xc0000bb4e8?, 0x2?, 0x60?, 0x0?, 0xc0000bb42c?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc0000bb268 sp=0xc0000bb248 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.selectgo(0xc0000bb4e8, 0xc0000bb428, 0x1b?, 0x0, 0x1701?, 0x1) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/select.go:327 +0x7be fp=0xc0000bb3a8 sp=0xc0000bb268 pc=0x44d45e Apr 25 12:45:58 volumio go-librespot[28883]: net.(*Resolver).lookupIPAddr(0xea0ce0, {0xafdf90?, 0xc000312150}, {0xa3419a, 0x3}, {0xc0003bc020, 0x17}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/lookup.go:334 +0x505 fp=0xc0000bb590 sp=0xc0000bb3a8 pc=0x664f45 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*Resolver).internetAddrList(0xafdf90?, {0xafdf90?, 0xc000312150?}, {0xa3419a, 0x3}, {0xc0003bc020?, 0xea1660?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/ipsock.go:288 +0x519 fp=0xc0000bb6b0 sp=0xc0000bb590 pc=0x662cf9 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*Resolver).resolveAddrList(0xed0760?, {0xafdf90, 0xc000312150}, {0xa34554, 0x4}, {0xa3419a?, 0xc0001f58a8?}, {0xc0003bc020, 0x1b}, {0x0, ...}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/dial.go:234 +0x41b fp=0xc0000bb7b0 sp=0xc0000bb6b0 pc=0x64bd1b Apr 25 12:45:58 volumio go-librespot[28883]: net.(*Dialer).DialContext(0xc0000ca700, {0xafdf90, 0xc000312150}, {0xa3419a, 0x3}, {0xc0003bc020, 0x1b}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/dial.go:422 +0x448 fp=0xc0000bb8e8 sp=0xc0000bb7b0 pc=0x64cc08 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*Dialer).DialContext-fm({0xafdf90?, 0xc000312150?}, {0xa3419a?, 0xafdf58?}, {0xc0003bc020?, 0x985680?}) Apr 25 12:45:58 volumio go-librespot[28883]: :1 +0x5b fp=0xc0000bb930 sp=0xc0000bb8e8 pc=0x7f45fb Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*Transport).dial(0xc00008dd40?, {0xafdf90?, 0xc000312150?}, {0xa3419a?, 0x47ee67?}, {0xc0003bc020?, 0xc0001f5a28?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/transport.go:1176 +0xe7 fp=0xc0000bb988 sp=0xc0000bb930 pc=0x7dd507 Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*Transport).dialConn(0xe570c0, {0xafdf90, 0xc000312150}, {{}, 0x0, {0xc0003568c0, 0x5}, {0xc0003bc020, 0x1b}, 0x1}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/transport.go:1614 +0x82c fp=0xc0000bbed8 sp=0xc0000bb988 pc=0x7e042c Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*Transport).dialConnFor(0xc000037180?, 0xc0004888f0) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/transport.go:1456 +0xb0 fp=0xc0000bbfc0 sp=0xc0000bbed8 pc=0x7dee70 Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*Transport).queueForDial.func1() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/transport.go:1425 +0x2a fp=0xc0000bbfe0 sp=0xc0000bbfc0 pc=0x7ded8a Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0000bbfe8 sp=0xc0000bbfe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by net/http.(*Transport).queueForDial Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/transport.go:1425 +0x3ea Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 6 [GC worker (idle)]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0x13d248883a37?, 0xc000091440?, 0x0?, 0x0?, 0x2?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc000053f50 sp=0xc000053f30 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gcBgMarkWorker() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:1275 +0xf1 fp=0xc000053fe0 sp=0xc000053f50 pc=0x4209f1 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc000053fe8 sp=0xc000053fe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by runtime.gcBgMarkStartWorkers Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:1199 +0x25 Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 25 [IO wait, 2 minutes]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0xc0000bf2b8?, 0xb?, 0x0?, 0x0?, 0x8?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc0000bf2c8 sp=0xc0000bf2a8 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.netpollblock(0x47d145?, 0x40922f?, 0x0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/netpoll.go:527 +0xf7 fp=0xc0000bf300 sp=0xc0000bf2c8 pc=0x436117 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.runtime_pollWait(0x7f6946161dc8, 0x72) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/netpoll.go:306 +0x89 fp=0xc0000bf320 sp=0xc0000bf300 pc=0x4673a9 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.(*pollDesc).wait(0xc0000b7300?, 0xc0001e0000?, 0x0) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_poll_runtime.go:84 +0x32 fp=0xc0000bf348 sp=0xc0000bf320 pc=0x4da132 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.(*pollDesc).waitRead(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_poll_runtime.go:89 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.(*FD).Read(0xc0000b7300, {0xc0001e0000, 0x1000, 0x1000}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_unix.go:167 +0x299 fp=0xc0000bf3e0 sp=0xc0000bf348 pc=0x4db519 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*netFD).Read(0xc0000b7300, {0xc0001e0000?, 0xc0000bf440?, 0x43d960?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/fd_posix.go:55 +0x29 fp=0xc0000bf428 sp=0xc0000bf3e0 pc=0x656509 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*conn).Read(0xc0000b2200, {0xc0001e0000?, 0xc0001de340?, 0xc0000bf5c8?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/net.go:183 +0x45 fp=0xc0000bf470 sp=0xc0000bf428 pc=0x666825 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*TCPConn).Read(0xc000091680?, {0xc0001e0000?, 0xc0000bf590?, 0x2?}) Apr 25 12:45:58 volumio go-librespot[28883]: :1 +0x29 fp=0xc0000bf4a0 sp=0xc0000bf470 pc=0x6793e9 Apr 25 12:45:58 volumio go-librespot[28883]: io.(*multiReader).Read(0xc000012018, {0xc0001e0000, 0x1000, 0x1000}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/io/multi.go:26 +0x9b fp=0xc0000bf4e8 sp=0xc0000bf4a0 pc=0x4d56db Apr 25 12:45:58 volumio go-librespot[28883]: bufio.(*Reader).fill(0xc000091560) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/bufio/bufio.go:106 +0xff fp=0xc0000bf520 sp=0xc0000bf4e8 pc=0x5257ff Apr 25 12:45:58 volumio go-librespot[28883]: bufio.(*Reader).ReadByte(0xc000091560) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/bufio/bufio.go:265 +0x2c fp=0xc0000bf540 sp=0xc0000bf520 pc=0x525fcc Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.readFrameHeader(0x48?, {0xc000007580, 0x8, 0x8}) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/frame.go:54 +0xa5 fp=0xc0000bf5d8 sp=0xc0000bf540 pc=0x80bde5 Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.(*Conn).readFrameHeader(0xc000007520, {0xafdf58, 0xc0000a6010}) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:188 +0xe9 fp=0xc0000bf718 sp=0xc0000bf5d8 pc=0x80d869 Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.(*Conn).readLoop(0xc000007520, {0xafdf58, 0xc0000a6010}) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:146 +0x6c fp=0xc0000bf870 sp=0xc0000bf718 pc=0x80d0ec Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.(*Conn).reader(0xc000007520, {0xafdf58, 0xc0000a6010}) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:315 +0x130 fp=0xc0000bf970 sp=0xc0000bf870 pc=0x80e8d0 Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.(*Conn).Reader(...) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:30 Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.(*Conn).Read(0xc0000b6000?, {0xafdf58?, 0xc0000a6010?}) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/read.go:36 +0x25 fp=0xc0000bf9a0 sp=0xc0000bf970 pc=0x80c9e5 Apr 25 12:45:58 volumio go-librespot[28883]: main.(*ApiServer).serve.func13({0xafdc80, 0xc0001260e0}, 0x0?) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:418 +0x1e5 fp=0xc0000bfa58 sp=0xc0000bf9a0 pc=0x901e05 Apr 25 12:45:58 volumio go-librespot[28883]: net/http.HandlerFunc.ServeHTTP(0xc0000b7300?, {0xafdc80?, 0xc0001260e0?}, 0x4132ca?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/server.go:2122 +0x2f fp=0xc0000bfa80 sp=0xc0000bfa58 pc=0x7cb16f Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*ServeMux).ServeHTTP(0x0?, {0xafdc80, 0xc0001260e0}, 0xc0000c5100) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/server.go:2500 +0x149 fp=0xc0000bfad0 sp=0xc0000bfa80 pc=0x7ccb09 Apr 25 12:45:58 volumio go-librespot[28883]: net/http.serverHandler.ServeHTTP({0xc0001bab70?}, {0xafdc80, 0xc0001260e0}, 0xc0000c5100) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/server.go:2936 +0x316 fp=0xc0000bfb80 sp=0xc0000bfad0 pc=0x7ce2b6 Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*conn).serve(0xc000171cb0, {0xafdfc8, 0xc000200120}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/server.go:1995 +0x612 fp=0xc0000bffb8 sp=0xc0000bfb80 pc=0x7c9c92 Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*Server).Serve.func3() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/server.go:3089 +0x2e fp=0xc0000bffe0 sp=0xc0000bffb8 pc=0x7cec0e Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0000bffe8 sp=0xc0000bffe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by net/http.(*Server).Serve Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/server.go:3089 +0x5ed Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 3 [select, 2 minutes]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0xc000054768?, 0x5?, 0x0?, 0x0?, 0xc0000546f6?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc000054568 sp=0xc000054548 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.selectgo(0xc000054768, 0xc0000546ec, 0xc000054700?, 0x0, 0x43d927?, 0x1) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/select.go:327 +0x7be fp=0xc0000546a8 sp=0xc000054568 pc=0x44d45e Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.(*Conn).timeoutLoop(0xc000007520) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:153 +0x15e fp=0xc0000547c8 sp=0xc0000546a8 pc=0x808bde Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.newConn.func2() Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:114 +0x26 fp=0xc0000547e0 sp=0xc0000547c8 pc=0x808726 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0000547e8 sp=0xc0000547e0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by nhooyr.io/websocket.newConn Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:114 +0x565 Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 7 [GC worker (idle)]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0x13d2488cc08c?, 0x0?, 0x0?, 0x0?, 0x0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc000057750 sp=0xc000057730 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gcBgMarkWorker() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:1275 +0xf1 fp=0xc0000577e0 sp=0xc000057750 pc=0x4209f1 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0000577e8 sp=0xc0000577e0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by runtime.gcBgMarkStartWorkers Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:1199 +0x25 Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 103 [select]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0xc0001f5b58?, 0x2?, 0xca?, 0x32?, 0xc0001f5b3c?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc0001f59c8 sp=0xc0001f59a8 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.selectgo(0xc0001f5b58, 0xc0001f5b38, 0xc000037180?, 0x0, 0xc00018f2c0?, 0x1) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/select.go:327 +0x7be fp=0xc0001f5b08 sp=0xc0001f59c8 pc=0x44d45e Apr 25 12:45:58 volumio go-librespot[28883]: net.cgoLookupIP({0xafdf20, 0xc000036190}, {0xa3419a, 0x3}, {0xc0003bc020, 0x17}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/cgo_unix.go:221 +0x1aa fp=0xc0001f5bf8 sp=0xc0001f5b08 pc=0x64980a Apr 25 12:45:58 volumio go-librespot[28883]: net.(*Resolver).lookupIP(0xea0ce0, {0xafdf20, 0xc000036190}, {0xa3419a, 0x3}, {0xc0003bc020, 0x17}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/lookup_unix.go:74 +0x130 fp=0xc0001f5e58 sp=0xc0001f5bf8 pc=0x6662b0 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*Resolver).lookupIP-fm({0xafdf20?, 0xc000036190?}, {0xa3419a?, 0xc00005ac00?}, {0xc0003bc020?, 0xc0001f5fb0?}) Apr 25 12:45:58 volumio go-librespot[28883]: :1 +0x5b fp=0xc0001f5ea0 sp=0xc0001f5e58 pc=0x67b71b Apr 25 12:45:58 volumio go-librespot[28883]: net.glob..func1({0xafdf20?, 0xc000036190?}, 0x0?, {0xa3419a?, 0x5?}, {0xc0003bc020?, 0x1b?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/hook.go:23 +0x3d fp=0xc0001f5ee0 sp=0xc0001f5ea0 pc=0x658bdd Apr 25 12:45:58 volumio go-librespot[28883]: net.(*Resolver).lookupIPAddr.func1() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/lookup.go:326 +0x3d fp=0xc0001f5f38 sp=0xc0001f5ee0 pc=0x66581d Apr 25 12:45:58 volumio go-librespot[28883]: internal/singleflight.(*Group).doCall(0xea0cf0, 0xc000036230, {0xc0003bc040, 0x1b}, 0xc0004888f0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/singleflight/singleflight.go:93 +0x3b fp=0xc0001f5fa8 sp=0xc0001f5f38 pc=0x64681b Apr 25 12:45:58 volumio go-librespot[28883]: internal/singleflight.(*Group).DoChan.func1() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/singleflight/singleflight.go:86 +0x36 fp=0xc0001f5fe0 sp=0xc0001f5fa8 pc=0x6467b6 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0001f5fe8 sp=0xc0001f5fe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by internal/singleflight.(*Group).DoChan Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/singleflight/singleflight.go:86 +0x30a Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 104 [syscall]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.cgocall(0x90cf60, 0xc00051fd58) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/cgocall.go:157 +0x5c fp=0xc00051fd30 sp=0xc00051fcf8 pc=0x409b9c Apr 25 12:45:58 volumio go-librespot[28883]: net._C2func_getaddrinfo(0xc0003e0108, 0x0, 0xc000312330, 0xc0000140e0) Apr 25 12:45:58 volumio go-librespot[28883]: _cgo_gotypes.go:99 +0x56 fp=0xc00051fd58 sp=0xc00051fd30 pc=0x676616 Apr 25 12:45:58 volumio go-librespot[28883]: net._C_getaddrinfo.func1(0x4136a7?, 0x8?, 0x946780?, 0xc0003e0101?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/cgo_unix_cgo.go:74 +0x85 fp=0xc00051fdc0 sp=0xc00051fd58 pc=0x676a05 Apr 25 12:45:58 volumio go-librespot[28883]: net._C_getaddrinfo(0x0?, 0x0?, 0x0?, 0xc0003bc020?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/cgo_unix_cgo.go:74 +0x19 fp=0xc00051fdf0 sp=0xc00051fdc0 pc=0x676939 Apr 25 12:45:58 volumio go-librespot[28883]: net.cgoLookupIPCNAME({0xa3419a, 0x3}, {0xc0003bc020, 0x17}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/cgo_unix.go:153 +0x175 fp=0xc00051ff38 sp=0xc00051fdf0 pc=0x648ef5 Apr 25 12:45:58 volumio go-librespot[28883]: net.cgoIPLookup(0x0?, {0xa3419a?, 0x0?}, {0xc0003bc020?, 0x0?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/cgo_unix.go:210 +0x3b fp=0xc00051ffa8 sp=0xc00051ff38 pc=0x6495bb Apr 25 12:45:58 volumio go-librespot[28883]: net.cgoLookupIP.func1() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/cgo_unix.go:220 +0x36 fp=0xc00051ffe0 sp=0xc00051ffa8 pc=0x6499f6 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc00051ffe8 sp=0xc00051ffe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by net.cgoLookupIP Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/cgo_unix.go:220 +0x12a Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 90 [IO wait, 2 minutes]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0xd9e17b800a0a4fc?, 0xb?, 0x0?, 0x0?, 0x9?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc0001f6608 sp=0xc0001f65e8 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.netpollblock(0x47d145?, 0x40922f?, 0x0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/netpoll.go:527 +0xf7 fp=0xc0001f6640 sp=0xc0001f6608 pc=0x436117 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.runtime_pollWait(0x7f6946161cd8, 0x72) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/netpoll.go:306 +0x89 fp=0xc0001f6660 sp=0xc0001f6640 pc=0x4673a9 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.(*pollDesc).wait(0xc0003b0880?, 0xc0004f5000?, 0x0) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_poll_runtime.go:84 +0x32 fp=0xc0001f6688 sp=0xc0001f6660 pc=0x4da132 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.(*pollDesc).waitRead(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_poll_runtime.go:89 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.(*FD).Read(0xc0003b0880, {0xc0004f5000, 0x1000, 0x1000}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_unix.go:167 +0x299 fp=0xc0001f6720 sp=0xc0001f6688 pc=0x4db519 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*netFD).Read(0xc0003b0880, {0xc0004f5000?, 0xc0004f565f?, 0x27?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/fd_posix.go:55 +0x29 fp=0xc0001f6768 sp=0xc0001f6720 pc=0x656509 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*conn).Read(0xc000014280, {0xc0004f5000?, 0x4457b1?, 0x25095dfc43711c05?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/net.go:183 +0x45 fp=0xc0001f67b0 sp=0xc0001f6768 pc=0x666825 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*TCPConn).Read(0xc0001f6848?, {0xc0004f5000?, 0xc0001fda40?, 0x18?}) Apr 25 12:45:58 volumio go-librespot[28883]: :1 +0x29 fp=0xc0001f67e0 sp=0xc0001f67b0 pc=0x6793e9 Apr 25 12:45:58 volumio go-librespot[28883]: crypto/tls.(*atLeastReader).Read(0xc0001fda40, {0xc0004f5000?, 0xc0001fda40?, 0x0?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/crypto/tls/conn.go:788 +0x3d fp=0xc0001f6828 sp=0xc0001f67e0 pc=0x729dbd Apr 25 12:45:58 volumio go-librespot[28883]: bytes.(*Buffer).ReadFrom(0xc0004ee610, {0xaf8ac0, 0xc0001fda40}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/bytes/buffer.go:202 +0x98 fp=0xc0001f6880 sp=0xc0001f6828 pc=0x506af8 Apr 25 12:45:58 volumio go-librespot[28883]: crypto/tls.(*Conn).readFromUntil(0xc0004ee380, {0xafaa40?, 0xc000014280}, 0xc0001f68f0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/crypto/tls/conn.go:810 +0xe5 fp=0xc0001f68c0 sp=0xc0001f6880 pc=0x729fa5 Apr 25 12:45:58 volumio go-librespot[28883]: crypto/tls.(*Conn).readRecordOrCCS(0xc0004ee380, 0x0) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/crypto/tls/conn.go:617 +0x116 fp=0xc0001f6c20 sp=0xc0001f68c0 pc=0x727496 Apr 25 12:45:58 volumio go-librespot[28883]: crypto/tls.(*Conn).readRecord(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/crypto/tls/conn.go:583 Apr 25 12:45:58 volumio go-librespot[28883]: crypto/tls.(*Conn).Read(0xc0004ee380, {0xc00018b000, 0x1000, 0x11?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/crypto/tls/conn.go:1316 +0x16f fp=0xc0001f6c90 sp=0xc0001f6c20 pc=0x72d38f Apr 25 12:45:58 volumio go-librespot[28883]: bufio.(*Reader).Read(0xc0003e30e0, {0xc0002fc2e0, 0x9, 0xc0001f6d28?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/bufio/bufio.go:237 +0x1bb fp=0xc0001f6cc8 sp=0xc0001f6c90 pc=0x525ddb Apr 25 12:45:58 volumio go-librespot[28883]: io.ReadAtLeast({0xaf8900, 0xc0003e30e0}, {0xc0002fc2e0, 0x9, 0x9}, 0x9) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/io/io.go:332 +0x9a fp=0xc0001f6d10 sp=0xc0001f6cc8 pc=0x4d47fa Apr 25 12:45:58 volumio go-librespot[28883]: io.ReadFull(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/io/io.go:351 Apr 25 12:45:58 volumio go-librespot[28883]: net/http.http2readFrameHeader({0xc0002fc2e0?, 0x9?, 0xc0001f6e00?}, {0xaf8900?, 0xc0003e30e0?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/h2_bundle.go:1567 +0x6e fp=0xc0001f6d60 sp=0xc0001f6d10 pc=0x78d34e Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*http2Framer).ReadFrame(0xc0002fc2a0) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/h2_bundle.go:1831 +0x95 fp=0xc0001f6e10 sp=0xc0001f6d60 pc=0x78db95 Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*http2clientConnReadLoop).run(0xc0001f6f98) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/h2_bundle.go:9187 +0x12e fp=0xc0001f6f60 sp=0xc0001f6e10 pc=0x7b118e Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*http2ClientConn).readLoop(0xc000003080) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/h2_bundle.go:9082 +0x6f fp=0xc0001f6fc8 sp=0xc0001f6f60 pc=0x7b06af Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*http2Transport).newClientConn.func1() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/h2_bundle.go:7779 +0x26 fp=0xc0001f6fe0 sp=0xc0001f6fc8 pc=0x7a92a6 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0001f6fe8 sp=0xc0001f6fe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by net/http.(*http2Transport).newClientConn Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/h2_bundle.go:7779 +0xc3c Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 61 [select, 2 minutes]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0xc000055f78?, 0x2?, 0x0?, 0x0?, 0xc000055f1c?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc000055d78 sp=0xc000055d58 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.selectgo(0xc000055f78, 0xc000055f18, 0x0?, 0x0, 0x0?, 0x1) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/select.go:327 +0x7be fp=0xc000055eb8 sp=0xc000055d78 pc=0x44d45e Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/player.(*Player).manageLoop(0xc0005007e0) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/player/player.go:102 +0x108 fp=0xc000055fc8 sp=0xc000055eb8 pc=0x836268 Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/player.NewPlayer.func2() Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/player/player.go:86 +0x26 fp=0xc000055fe0 sp=0xc000055fc8 pc=0x836066 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc000055fe8 sp=0xc000055fe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by go-librespot/player.NewPlayer Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/player/player.go:86 +0x1d6 Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 62 [IO wait, 2 minutes]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0xc0004ceb60?, 0xb?, 0x0?, 0x0?, 0xb?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc000519b70 sp=0xc000519b50 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.netpollblock(0x47d145?, 0x40922f?, 0x0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/netpoll.go:527 +0xf7 fp=0xc000519ba8 sp=0xc000519b70 pc=0x436117 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.runtime_pollWait(0x7f6946161a08, 0x72) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/netpoll.go:306 +0x89 fp=0xc000519bc8 sp=0xc000519ba8 pc=0x4673a9 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.(*pollDesc).wait(0xc0000b6580?, 0xc0003a79c8?, 0x0) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_poll_runtime.go:84 +0x32 fp=0xc000519bf0 sp=0xc000519bc8 pc=0x4da132 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.(*pollDesc).waitRead(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_poll_runtime.go:89 Apr 25 12:45:58 volumio go-librespot[28883]: internal/poll.(*FD).Read(0xc0000b6580, {0xc0003a79c8, 0x3, 0x3}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_unix.go:167 +0x299 fp=0xc000519c88 sp=0xc000519bf0 pc=0x4db519 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*netFD).Read(0xc0000b6580, {0xc0003a79c8?, 0x1?, 0xf?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/fd_posix.go:55 +0x29 fp=0xc000519cd0 sp=0xc000519c88 pc=0x656509 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*conn).Read(0xc0000b2388, {0xc0003a79c8?, 0xc00032f500?, 0x7f696ecf15b8?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/net.go:183 +0x45 fp=0xc000519d18 sp=0xc000519cd0 pc=0x666825 Apr 25 12:45:58 volumio go-librespot[28883]: net.(*TCPConn).Read(0xc0000bdd80?, {0xc0003a79c8?, 0xc0000bdd80?, 0x411096?}) Apr 25 12:45:58 volumio go-librespot[28883]: :1 +0x29 fp=0xc000519d48 sp=0xc000519d18 pc=0x6793e9 Apr 25 12:45:58 volumio go-librespot[28883]: io.ReadAtLeast({0xafaa40, 0xc0000b2388}, {0xc0003a79c8, 0x3, 0x3}, 0x3) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/io/io.go:332 +0x9a fp=0xc000519d90 sp=0xc000519d48 pc=0x4d47fa Apr 25 12:45:58 volumio go-librespot[28883]: io.ReadFull(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/io/io.go:351 Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/ap.(*shannonConn).receivePacket(0xc00007ef40) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/ap/shannon.go:80 +0x132 fp=0xc000519e68 sp=0xc000519d90 pc=0x823e72 Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/ap.(*Accesspoint).recvLoop(0xc000206680) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:239 +0x6e fp=0xc000519fc8 sp=0xc000519e68 pc=0x8210ae Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/ap.(*Accesspoint).startReceiving.func1.1() Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:228 +0x26 fp=0xc000519fe0 sp=0xc000519fc8 pc=0x821006 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc000519fe8 sp=0xc000519fe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by go-librespot/ap.(*Accesspoint).startReceiving.func1 Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:228 +0x5a Apr 25 12:45:58 volumio go-librespot[28883]: goroutine 63 [select]: Apr 25 12:45:58 volumio go-librespot[28883]: runtime.gopark(0xc0004ed148?, 0x4?, 0x3?, 0x68?, 0xc0004ecff0?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0xd6 fp=0xc0004ece48 sp=0xc0004ece28 pc=0x43d876 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.selectgo(0xc0004ed148, 0xc0004ecfe8, 0xc00048e210?, 0x0, 0x0?, 0x1) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/select.go:327 +0x7be fp=0xc0004ecf88 sp=0xc0004ece48 pc=0x44d45e Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*Transport).getConn(0xe570c0, 0xc0004e4000, {{}, 0x0, {0xc0003568c0, 0x5}, {0xc0003bc020, 0x1b}, 0x1}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/transport.go:1382 +0x5c6 fp=0xc0004ed1a0 sp=0xc0004ecf88 pc=0x7de1e6 Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*Transport).roundTrip(0xe570c0, 0xc0004a6800) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/transport.go:590 +0x79e fp=0xc0004ed3c8 sp=0xc0004ed1a0 pc=0x7da0de Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*Transport).RoundTrip(0x400000?, 0xafab20?) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/roundtrip.go:17 +0x19 fp=0xc0004ed3e8 sp=0xc0004ed3c8 pc=0x7c22d9 Apr 25 12:45:58 volumio go-librespot[28883]: net/http.send(0xc0004a6800, {0xafab20, 0xe570c0}, {0x8?, 0xa1fb00?, 0x0?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/client.go:252 +0x5f7 fp=0xc0004ed5e0 sp=0xc0004ed3e8 pc=0x782dd7 Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*Client).send(0xc000312180, 0xc0004a6800, {0xc0003568e3?, 0x1?, 0x0?}) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/client.go:176 +0x9b fp=0xc0004ed658 sp=0xc0004ed5e0 pc=0x78265b Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*Client).do(0xc000312180, 0xc0004a6800) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/client.go:716 +0x8fb fp=0xc0004ed860 sp=0xc0004ed658 pc=0x78495b Apr 25 12:45:58 volumio go-librespot[28883]: net/http.(*Client).Do(...) Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/client.go:582 Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.handshakeRequest({0xafdf90, 0xc000312150}, {0xc000356700?, 0xc0004eda58?}, 0xc0004edc80, 0xc0000a608e, {0xc0003e0078, 0x18}) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/dial.go:173 +0x6fd fp=0xc0004ed9e8 sp=0xc0004ed860 pc=0x80ac5d Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.dial({0xafdf58?, 0xc0000a6010?}, {0xc000356700, 0x1aa}, 0x2?, {0x0, 0x0}) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/dial.go:101 +0x465 fp=0xc0004edbc8 sp=0xc0004ed9e8 pc=0x809b25 Apr 25 12:45:58 volumio go-librespot[28883]: nhooyr.io/websocket.Dial(...) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/dial.go:63 Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/dealer.(*Dealer).connect(0xc000372000) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:69 +0x255 fp=0xc0004edcc8 sp=0xc0004edbc8 pc=0x8441f5 Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/dealer.(*Dealer).reconnect(0xc000372000) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:236 +0x25 fp=0xc0004edd10 sp=0xc0004edcc8 pc=0x845105 Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/dealer.(*Dealer).reconnect-fm() Apr 25 12:45:58 volumio go-librespot[28883]: :1 +0x26 fp=0xc0004edd28 sp=0xc0004edd10 pc=0x846b06 Apr 25 12:45:58 volumio go-librespot[28883]: github.com/cenkalti/backoff/v4.RetryNotifyWithTimer.func1() Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:18 +0x1b fp=0xc0004edd38 sp=0xc0004edd28 pc=0x81cd9b Apr 25 12:45:58 volumio go-librespot[28883]: github.com/cenkalti/backoff/v4.doRetryNotify[...](0xc0004ede60?, {0xafc3e8, 0xc00038c5a0}, 0x0, {0x0, 0x0?}) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:88 +0x152 fp=0xc0004ede28 sp=0xc0004edd38 pc=0x81d172 Apr 25 12:45:58 volumio go-librespot[28883]: github.com/cenkalti/backoff/v4.RetryNotifyWithTimer(0xc000441f80?, {0xafc3e8?, 0xc00038c5a0?}, 0x989080?, {0x0?, 0x0?}) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:61 +0x65 fp=0xc0004ede80 sp=0xc0004ede28 pc=0x81cd25 Apr 25 12:45:58 volumio go-librespot[28883]: github.com/cenkalti/backoff/v4.RetryNotify(...) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:49 Apr 25 12:45:58 volumio go-librespot[28883]: github.com/cenkalti/backoff/v4.Retry(...) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:38 Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/dealer.(*Dealer).recvLoop(0xc000372000) Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:191 +0x48c fp=0xc0004edfc8 sp=0xc0004ede80 pc=0x844ccc Apr 25 12:45:58 volumio go-librespot[28883]: go-librespot/dealer.(*Dealer).startReceiving.func1.1() Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:97 +0x26 fp=0xc0004edfe0 sp=0xc0004edfc8 pc=0x8444a6 Apr 25 12:45:58 volumio go-librespot[28883]: runtime.goexit() Apr 25 12:45:58 volumio go-librespot[28883]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc0004edfe8 sp=0xc0004edfe0 pc=0x46c961 Apr 25 12:45:58 volumio go-librespot[28883]: created by go-librespot/dealer.(*Dealer).startReceiving.func1 Apr 25 12:45:58 volumio go-librespot[28883]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:97 +0x5a Apr 25 12:45:58 volumio go-librespot[28883]: Aborted Apr 25 12:45:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Apr 25 12:45:58 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 12:45:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 12:46:01 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:46:01 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 12:46:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 12:46:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 203. Apr 25 12:46:01 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 12:46:01 volumio systemd[1]: Started go-librespot Daemon. Apr 25 12:46:01 volumio go-librespot[29085]: Librespot-go daemon starting... Apr 25 12:46:01 volumio go-librespot[29085]: time="2024-04-25T12:46:01-05:00" level=info msg="generated new device id: febb3109e90db357a14039dd4bec3ce88f3bf68a" Apr 25 12:46:01 volumio go-librespot[29085]: time="2024-04-25T12:46:01-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:46:04 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:46:04 volumio go-librespot[29085]: time="2024-04-25T12:46:04-05:00" level=debug msg="new websocket client" Apr 25 12:46:04 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 12:46:07 volumio volumio[832]: info: Getting Spotify volume Apr 25 12:46:07 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 12:46:07 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 12:46:07 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 12:46:07 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 12:46:31 volumio go-librespot[29085]: time="2024-04-25T12:46:31-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp 35.186.224.25:443: i/o timeout" Apr 25 12:46:31 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 12:46:31 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 12:46:31 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 12:46:31 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 12:46:31 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 12:46:31 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 12:46:31 volumio volumio[832]: (node:832) 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: 199) Apr 25 12:46:31 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 12:46:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 12:46:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 12:46:34 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:46:34 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 12:46:35 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 12:46:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 204. Apr 25 12:46:35 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 12:46:35 volumio systemd[1]: Started go-librespot Daemon. Apr 25 12:46:35 volumio go-librespot[29095]: Librespot-go daemon starting... Apr 25 12:46:35 volumio go-librespot[29095]: time="2024-04-25T12:46:35-05:00" level=info msg="generated new device id: bc5862a3a6b827f0d4c2a0545b22d275a148c065" Apr 25 12:46:35 volumio go-librespot[29095]: time="2024-04-25T12:46:35-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:46:36 volumio ntpd[28880]: Soliciting pool server 192.36.143.130 Apr 25 12:46:37 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:46:37 volumio go-librespot[29095]: time="2024-04-25T12:46:37-05:00" level=debug msg="new websocket client" Apr 25 12:46:37 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 12:46:39 volumio ntpd[28880]: Soliciting pool server 132.248.3.29 Apr 25 12:46:40 volumio volumio[832]: info: Getting Spotify volume Apr 25 12:46:40 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 12:46:40 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 12:46:40 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 12:46:40 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 12:46:53 volumio go-librespot[29095]: time="2024-04-25T12:46:53-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp 35.186.224.25:443: connect: no route to host" Apr 25 12:46:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 12:46:53 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 12:46:53 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 12:46:53 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 12:46:53 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 12:46:53 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 12:46:53 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 12:46:53 volumio volumio[832]: (node:832) 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: 200) Apr 25 12:46:53 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 12:46:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 12:46:56 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:46:56 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 12:46:56 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 12:46:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 205. Apr 25 12:46:56 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 12:46:56 volumio systemd[1]: Started go-librespot Daemon. Apr 25 12:46:56 volumio go-librespot[29159]: Librespot-go daemon starting... Apr 25 12:46:56 volumio go-librespot[29159]: time="2024-04-25T12:46:56-05:00" level=info msg="generated new device id: c632a2c13fe9787b13213a32f14f590a6af2b898" Apr 25 12:46:56 volumio go-librespot[29159]: time="2024-04-25T12:46:56-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:46:59 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:46:59 volumio go-librespot[29159]: time="2024-04-25T12:46:59-05:00" level=debug msg="new websocket client" Apr 25 12:46:59 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 12:47:02 volumio volumio[832]: info: Getting Spotify volume Apr 25 12:47:02 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 12:47:02 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 12:47:02 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 12:47:02 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 12:47:12 volumio ntpd[28880]: Soliciting pool server 45.231.168.6 Apr 25 12:47:15 volumio go-librespot[29159]: time="2024-04-25T12:47:15-05:00" level=debug msg="obtained new client token: AADYDLG8QYo/KiYA7VV4roZp9/fnZbkwnU1MAA7WiS8ARmATY28yZMm3ZWJ6oKnBz60ALQMe/niWdr3Od+7vT7mnsx3BVkShqKuqxHUqK/94fi/jwHRaTCXwA+QHTXxibRs75q/aLS4NUvghYz46ughgZ3w5EeXR0BOaP8HnTZDSwjvSbUlh/zN54tbKjL2P0LYXnmRIvkpkWdau7Glxt0d4tSTUZ7oyYNigXExCO8aWU44I4u+lUq/FPWiOFkw7mg==" Apr 25 12:47:43 volumio go-librespot[29159]: time="2024-04-25T12:47:43-05:00" level=fatal msg="failed running with username and spotify token" error="failed getting accesspoint from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Apr 25 12:47:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 12:47:43 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 12:47:43 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 12:47:43 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 12:47:43 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 12:47:43 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 12:47:43 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 12:47:43 volumio volumio[832]: (node:832) 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: 201) Apr 25 12:47:43 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 12:47:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 12:47:46 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:47:46 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 12:47:46 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 12:47:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 206. Apr 25 12:47:46 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 12:47:46 volumio systemd[1]: Started go-librespot Daemon. Apr 25 12:47:46 volumio go-librespot[29226]: Librespot-go daemon starting... Apr 25 12:47:46 volumio go-librespot[29226]: time="2024-04-25T12:47:46-05:00" level=info msg="generated new device id: 17e45e49c6ba478d583b1db64b51cc9575a6d98a" Apr 25 12:47:46 volumio go-librespot[29226]: time="2024-04-25T12:47:46-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:47:49 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:47:49 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 12:47:49 volumio go-librespot[29226]: time="2024-04-25T12:47:49-05:00" level=debug msg="new websocket client" Apr 25 12:47:52 volumio volumio[832]: info: Getting Spotify volume Apr 25 12:47:52 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 12:47:52 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 12:47:52 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 12:47:52 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 12:47:52 volumio ntpd[28880]: Soliciting pool server 192.36.143.130 Apr 25 12:48:09 volumio ntpd[28880]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Apr 25 12:48:11 volumio go-librespot[29226]: time="2024-04-25T12:48:11-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": net/http: TLS handshake timeout" Apr 25 12:48:11 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 12:48:11 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 12:48:11 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 12:48:11 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 12:48:11 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 12:48:11 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 12:48:11 volumio volumio[832]: (node:832) 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: 202) Apr 25 12:48:11 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 12:48:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 12:48:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 12:48:14 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:48:14 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 12:48:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 12:48:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 207. Apr 25 12:48:14 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 12:48:14 volumio systemd[1]: Started go-librespot Daemon. Apr 25 12:48:14 volumio go-librespot[29236]: Librespot-go daemon starting... Apr 25 12:48:14 volumio go-librespot[29236]: time="2024-04-25T12:48:14-05:00" level=info msg="generated new device id: 8a002532a34dc7f8256cded1bca8297eeeeff928" Apr 25 12:48:14 volumio go-librespot[29236]: time="2024-04-25T12:48:14-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:48:17 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:48:17 volumio go-librespot[29236]: time="2024-04-25T12:48:17-05:00" level=debug msg="new websocket client" Apr 25 12:48:17 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 12:48:20 volumio volumio[832]: info: Getting Spotify volume Apr 25 12:48:20 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 12:48:20 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 12:48:20 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 12:48:20 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 12:48:25 volumio go-librespot[29236]: time="2024-04-25T12:48:25-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp 35.186.224.25:443: connect: no route to host" Apr 25 12:48:25 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 12:48:25 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 12:48:25 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 12:48:25 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 12:48:25 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 12:48:25 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 12:48:25 volumio volumio[832]: (node:832) 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: 203) Apr 25 12:48:25 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 12:48:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 12:48:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 12:48:26 volumio ntpd[28880]: Soliciting pool server 192.36.143.130 Apr 25 12:48:28 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:48:28 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 12:48:28 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 12:48:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 208. Apr 25 12:48:28 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 12:48:28 volumio systemd[1]: Started go-librespot Daemon. Apr 25 12:48:28 volumio go-librespot[29244]: Librespot-go daemon starting... Apr 25 12:48:28 volumio go-librespot[29244]: time="2024-04-25T12:48:28-05:00" level=info msg="generated new device id: 3296e94c3a55150a71e2c2219e87adbfe960e5be" Apr 25 12:48:28 volumio go-librespot[29244]: time="2024-04-25T12:48:28-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:48:31 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:48:31 volumio go-librespot[29244]: time="2024-04-25T12:48:31-05:00" level=debug msg="new websocket client" Apr 25 12:48:31 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 12:48:34 volumio volumio[832]: info: Getting Spotify volume Apr 25 12:48:34 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 12:48:34 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 12:48:34 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 12:48:34 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 12:48:34 volumio ntpd[28880]: Soliciting pool server 45.231.168.6 Apr 25 12:48:37 volumio go-librespot[29244]: time="2024-04-25T12:48:37-05:00" level=debug msg="obtained new client token: AABXdTXJpWo9fLm3GYYMzFVx9zoHOi1uQK71xolmLHO3vQ2PLmLM5xJDfFXtyZVQtIpzXF2zJrS3dhF1GkMMLn1I8aeYrf3JD0u6Io40Iqsc3Msf1SZ/5BAeotYN6mNwNY57LQbhOw5oa68TcCmZXXhN4QP7xUiJ9BHXt4l/knFalIEELTskoH3VsRH2yTjOWWOf1hW1gF4u2Gsfll1Dw37lMftxDAEaYdHNNuc3cjfc0xZgMomXIkvQRcFsYIP2TQ==" Apr 25 12:48:46 volumio ntpd[28880]: Soliciting pool server 193.182.111.13 Apr 25 12:48:55 volumio ntpd[28880]: Soliciting pool server 192.36.143.130 Apr 25 12:49:01 volumio ntpd[28880]: Soliciting pool server 193.182.111.13 Apr 25 12:49:02 volumio ntpd[28880]: Soliciting pool server 216.238.85.87 Apr 25 12:49:11 volumio go-librespot[29244]: time="2024-04-25T12:49:11-05:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 25 12:49:16 volumio ntpd[28880]: Soliciting pool server 192.36.143.130 Apr 25 12:49:53 volumio ntpd[28880]: Soliciting pool server 45.231.168.6 Apr 25 12:49:54 volumio ntpd[28880]: Soliciting pool server 45.231.168.6 Apr 25 12:50:03 volumio ntpd[28880]: Soliciting pool server 45.183.178.195 Apr 25 12:50:09 volumio ntpd[28880]: Soliciting pool server 45.231.168.6 Apr 25 12:51:00 volumio ntpd[28880]: Soliciting pool server 192.36.143.130 Apr 25 12:51:46 volumio ntpd[28880]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Apr 25 12:51:49 volumio go-librespot[29244]: time="2024-04-25T12:51:49-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.1.244:55542->104.154.127.126:4070: read: connection timed out" Apr 25 12:51:49 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 12:51:49 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 12:51:49 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 12:51:49 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 12:51:49 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 12:51:49 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 12:51:49 volumio volumio[832]: (node:832) 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: 204) Apr 25 12:51:49 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 12:51:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 12:51:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 12:51:52 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:51:52 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 12:51:52 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 12:51:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 209. Apr 25 12:51:52 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 12:51:52 volumio systemd[1]: Started go-librespot Daemon. Apr 25 12:51:52 volumio go-librespot[29508]: Librespot-go daemon starting... Apr 25 12:51:52 volumio go-librespot[29508]: time="2024-04-25T12:51:52-05:00" level=info msg="generated new device id: 3e6452d2d0fe77984d28c856af79a1ab12c986c2" Apr 25 12:51:52 volumio go-librespot[29508]: time="2024-04-25T12:51:52-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 12:51:54 volumio go-librespot[29508]: time="2024-04-25T12:51:54-05:00" level=debug msg="obtained new client token: AACtti8E0DZkMTNilAm3rNM9kCANQiNkX2/sJefzWxgUjIXmfxIuh6gblCKXeYekZxagqBTuqjTi8RXlR65CpVBYC//ksZpvbGtgNO0tB8UbkLqhqYPvckgProkWk/L9rGjmB1nArBScYaW5d8tKXbm/J5Hq/BZGeMI5dyFeA7osDrhCf8iPtiCLuhYbEqppt7yNJd/LW08g5Rh5bLoFMQC8ZJzQAOYFpFz6dg5Y2/73QxOUoNSY1oo/0PQteDPW9g==" Apr 25 12:51:55 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 12:51:55 volumio go-librespot[29508]: time="2024-04-25T12:51:55-05:00" level=debug msg="new websocket client" Apr 25 12:51:55 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 12:51:58 volumio volumio[832]: info: Getting Spotify volume Apr 25 12:51:58 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 12:51:58 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 12:51:58 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 12:51:58 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 12:52:25 volumio ntpd[28880]: Soliciting pool server 192.36.143.130 Apr 25 12:52:26 volumio ntpd[28880]: Soliciting pool server 45.231.168.6 Apr 25 12:52:59 volumio ntpd[28880]: Soliciting pool server 216.238.85.87 Apr 25 12:53:13 volumio ntpd[28880]: Soliciting pool server 216.238.85.87 Apr 25 12:53:28 volumio ntpd[28880]: Soliciting pool server 216.238.85.87 Apr 25 12:55:11 volumio ntpd[28880]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Apr 25 12:55:33 volumio ntpd[28880]: Soliciting pool server 45.183.178.195 Apr 25 12:55:58 volumio ntpd[28880]: Soliciting pool server 132.248.3.29 Apr 25 12:58:19 volumio ntpd[28880]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Apr 25 12:58:50 volumio ntpd[28880]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Apr 25 12:59:23 volumio ntpd[28880]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Apr 25 12:59:51 volumio ntpd[28880]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Apr 25 12:59:52 volumio ntpd[28880]: Soliciting pool server 2a03:8600::ee Apr 25 12:59:56 volumio ntpd[28880]: Soliciting pool server 2a03:8600::cc Apr 25 13:00:31 volumio ntpd[28880]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Apr 25 13:00:45 volumio ntpd[28880]: Soliciting pool server 45.183.178.195 Apr 25 13:01:02 volumio ntpd[28880]: Soliciting pool server 2a03:8600::aa Apr 25 13:01:13 volumio ntpd[28880]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Apr 25 13:01:46 volumio ntpd[28880]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Apr 25 13:02:08 volumio ntpd[28880]: Soliciting pool server 2a03:8600::bb Apr 25 13:03:33 volumio ntpd[28880]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Apr 25 13:03:38 volumio ntpd[28880]: Soliciting pool server 2a03:8600::aa Apr 25 13:04:17 volumio ntpd[28880]: Soliciting pool server 132.248.3.29 Apr 25 13:04:24 volumio ntpd[28880]: Soliciting pool server 2a03:8600::dd Apr 25 13:05:33 volumio ntpd[28880]: Soliciting pool server 2a03:8600::bb Apr 25 13:05:59 volumio ntpd[28880]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Apr 25 13:06:39 volumio ntpd[28880]: Soliciting pool server 2a03:8600::ee Apr 25 13:07:02 volumio ntpd[28880]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Apr 25 13:09:11 volumio go-librespot[29508]: time="2024-04-25T13:09:11-05:00" level=fatal msg="failed running with username and spotify token" error="failed getting accesspoint from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint\": read tcp 192.168.1.244:60182->35.186.224.25:443: read: no route to host" Apr 25 13:09:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 13:09:11 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 13:09:11 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 13:09:11 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 13:09:11 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 13:09:11 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 13:09:11 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 13:09:11 volumio volumio[832]: (node:832) 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: 205) Apr 25 13:09:11 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 13:09:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 13:09:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 13:09:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 210. Apr 25 13:09:14 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 13:09:14 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 13:09:14 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 13:09:14 volumio systemd[1]: Started go-librespot Daemon. Apr 25 13:09:14 volumio go-librespot[30556]: Librespot-go daemon starting... Apr 25 13:09:14 volumio go-librespot[30556]: time="2024-04-25T13:09:14-05:00" level=info msg="generated new device id: c03c46d4852c541620b3c812898b8c64b3925c34" Apr 25 13:09:14 volumio go-librespot[30556]: time="2024-04-25T13:09:14-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 13:09:17 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 13:09:17 volumio go-librespot[30556]: time="2024-04-25T13:09:17-05:00" level=debug msg="new websocket client" Apr 25 13:09:17 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 13:09:20 volumio volumio[832]: info: Getting Spotify volume Apr 25 13:09:20 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 13:09:20 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:09:20 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:09:20 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:09:25 volumio go-librespot[30556]: time="2024-04-25T13:09:25-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": net/http: TLS handshake timeout" Apr 25 13:09:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 13:09:25 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 13:09:25 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 13:09:25 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 13:09:25 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 13:09:25 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 13:09:25 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 13:09:25 volumio volumio[832]: (node:832) 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: 206) Apr 25 13:09:25 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 13:09:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 13:09:28 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 13:09:28 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 13:09:28 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 13:09:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 211. Apr 25 13:09:28 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 13:09:28 volumio systemd[1]: Started go-librespot Daemon. Apr 25 13:09:28 volumio go-librespot[30565]: Librespot-go daemon starting... Apr 25 13:09:28 volumio go-librespot[30565]: time="2024-04-25T13:09:28-05:00" level=info msg="generated new device id: 42a5035360cb36cdb4aed20639757580d7416526" Apr 25 13:09:28 volumio go-librespot[30565]: time="2024-04-25T13:09:28-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 13:09:31 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 13:09:31 volumio go-librespot[30565]: time="2024-04-25T13:09:31-05:00" level=debug msg="new websocket client" Apr 25 13:09:31 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 13:09:34 volumio volumio[832]: info: Getting Spotify volume Apr 25 13:09:34 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 13:09:34 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:09:34 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:09:34 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:09:40 volumio go-librespot[30565]: time="2024-04-25T13:09:40-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": net/http: TLS handshake timeout" Apr 25 13:09:40 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 13:09:40 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 13:09:40 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 13:09:40 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 13:09:40 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 13:09:40 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 13:09:40 volumio volumio[832]: (node:832) 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: 207) Apr 25 13:09:40 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 13:09:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 13:09:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 13:09:43 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 13:09:43 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 13:09:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 13:09:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 212. Apr 25 13:09:43 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 13:09:43 volumio systemd[1]: Started go-librespot Daemon. Apr 25 13:09:43 volumio go-librespot[30573]: Librespot-go daemon starting... Apr 25 13:09:43 volumio go-librespot[30573]: time="2024-04-25T13:09:43-05:00" level=info msg="generated new device id: 8c929f84da705efaf3467c6bd19d90ed292a886f" Apr 25 13:09:43 volumio go-librespot[30573]: time="2024-04-25T13:09:43-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 13:09:46 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 13:09:46 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 13:09:46 volumio go-librespot[30573]: time="2024-04-25T13:09:46-05:00" level=debug msg="new websocket client" Apr 25 13:09:49 volumio volumio[832]: info: Getting Spotify volume Apr 25 13:09:49 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 13:09:49 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:09:49 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:09:49 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:10:13 volumio go-librespot[30573]: time="2024-04-25T13:10:13-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp 35.186.224.25:443: i/o timeout" Apr 25 13:10:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 13:10:13 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 13:10:13 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 13:10:13 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 13:10:13 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 13:10:13 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 13:10:13 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 13:10:13 volumio volumio[832]: (node:832) 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: 208) Apr 25 13:10:13 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 13:10:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 13:10:16 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 13:10:16 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 13:10:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 13:10:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 213. Apr 25 13:10:17 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 13:10:17 volumio systemd[1]: Started go-librespot Daemon. Apr 25 13:10:17 volumio go-librespot[30638]: Librespot-go daemon starting... Apr 25 13:10:17 volumio go-librespot[30638]: time="2024-04-25T13:10:17-05:00" level=info msg="generated new device id: 0aeaedd00e3fba9f6d0782eea5d73bdc4af3e6fe" Apr 25 13:10:17 volumio go-librespot[30638]: time="2024-04-25T13:10:17-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 13:10:19 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 13:10:19 volumio go-librespot[30638]: time="2024-04-25T13:10:19-05:00" level=debug msg="new websocket client" Apr 25 13:10:19 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 13:10:22 volumio volumio[832]: info: Getting Spotify volume Apr 25 13:10:22 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 13:10:22 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:10:22 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:10:22 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:10:34 volumio ntpd[28880]: 45.183.178.195 local addr 192.168.1.244 -> Apr 25 13:11:32 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 25 13:11:32 volumio volumio[832]: info: Received Get System Info Apr 25 13:11:32 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 25 13:11:32 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 25 13:11:32 volumio volumio[832]: info: Discovery: Getting this device information Apr 25 13:11:32 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:11:32 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:11:32 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 25 13:13:29 volumio go-librespot[30638]: time="2024-04-25T13:13:29-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": read tcp 192.168.1.244:48622->35.186.224.25:443: read: connection reset by peer" Apr 25 13:13:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 25 13:13:29 volumio volumio[832]: (node:832) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 25 13:13:29 volumio volumio[832]: at connResetException (internal/errors.js:639:14) Apr 25 13:13:29 volumio volumio[832]: at Socket.socketOnEnd (_http_client.js:499:23) Apr 25 13:13:29 volumio volumio[832]: at Socket.emit (events.js:412:35) Apr 25 13:13:29 volumio volumio[832]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 25 13:13:29 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 25 13:13:29 volumio volumio[832]: (node:832) 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: 209) Apr 25 13:13:29 volumio volumio[832]: info: Connection to go-librespot Websocket closed Apr 25 13:13:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 25 13:13:32 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 13:13:32 volumio volumio[832]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 25 13:13:32 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 25 13:13:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 214. Apr 25 13:13:32 volumio systemd[1]: Stopped go-librespot Daemon. Apr 25 13:13:32 volumio systemd[1]: Started go-librespot Daemon. Apr 25 13:13:32 volumio go-librespot[30836]: Librespot-go daemon starting... Apr 25 13:13:32 volumio go-librespot[30836]: time="2024-04-25T13:13:32-05:00" level=info msg="generated new device id: eb73fbcca8723c522449cf028cef6517cf2649a2" Apr 25 13:13:32 volumio go-librespot[30836]: time="2024-04-25T13:13:32-05:00" level=debug msg="stored credentials found for txqeumjpo0e2sqzbg8ea9kho7" Apr 25 13:13:33 volumio go-librespot[30836]: time="2024-04-25T13:13:33-05:00" level=debug msg="obtained new client token: AAAqligf33txXCHfXvsa+wzkuKsTHLY1CqTXh+Swi91jy2p/BTFg0Ejd7TdZOKJvqOl/rV2vGSg62KvaigZdXm3UgvuRnRe7zMMY20VCKZ+4T5YUYNrak5gBqy9OoAl/wkybCNSJhSnXVnpLBJUMJb9Mr65uxxCXLH7v9Xnxp3JkGKLFoX/wCtVGvV78AtrxgKHHyii782xgYV3fRuktdElrjchcy2xKwQz53v4NA2WmMidIWBzkTrizv7u+dTc=" Apr 25 13:13:33 volumio go-librespot[30836]: time="2024-04-25T13:13:33-05:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 25 13:13:33 volumio go-librespot[30836]: time="2024-04-25T13:13:33-05:00" level=debug msg="completed keyexchange" Apr 25 13:13:34 volumio go-librespot[30836]: time="2024-04-25T13:13:34-05:00" level=debug msg="completed challenge" Apr 25 13:13:34 volumio go-librespot[30836]: time="2024-04-25T13:13:34-05:00" level=debug msg="authenticated as txqeumjpo0e2sqzbg8ea9kho7" Apr 25 13:13:34 volumio go-librespot[30836]: time="2024-04-25T13:13:34-05:00" level=debug msg="authenticated as txqeumjpo0e2sqzbg8ea9kho7" Apr 25 13:13:34 volumio go-librespot[30836]: time="2024-04-25T13:13:34-05:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 25 13:13:34 volumio go-librespot[30836]: time="2024-04-25T13:13:34-05:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 25 13:13:34 volumio go-librespot[30836]: time="2024-04-25T13:13:34-05:00" level=debug msg="dealer connection opened" Apr 25 13:13:34 volumio go-librespot[30836]: time="2024-04-25T13:13:34-05:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 25 13:13:34 volumio go-librespot[30836]: time="2024-04-25T13:13:34-05:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 25 13:13:34 volumio go-librespot[30836]: time="2024-04-25T13:13:34-05:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 25 13:13:34 volumio go-librespot[30836]: time="2024-04-25T13:13:34-05:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 25 13:13:34 volumio go-librespot[30836]: time="2024-04-25T13:13:34-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" Apr 25 13:13:34 volumio go-librespot[30836]: time="2024-04-25T13:13:34-05:00" level=debug msg="received connection id: ZTFkY2NiMDYtYzZkZi00MmJiLWI4ZTgtODY4OTM4MjFhZmI1K2RlYWxlcit0Y3A6Ly9ndWMzLWRlYWxlci1hLWxoZDkuZ3VjMy5zcG90aWZ5Lm5ldDo1NzAwKzQzNzVFRTIwOTcxMTcwN0NCRjk5MkNGRTg1MDhFQzY2ODFCRjkwMEYxOTIyOTc3RUVFMjQ5MzAzRTZFNDZDNTc=" Apr 25 13:13:35 volumio go-librespot[30836]: time="2024-04-25T13:13:35-05:00" level=debug msg="put connect state because NEW_DEVICE" Apr 25 13:13:35 volumio volumio[832]: info: Initializing connection to go-librespot Websocket Apr 25 13:13:35 volumio go-librespot[30836]: time="2024-04-25T13:13:35-05:00" level=debug msg="new websocket client" Apr 25 13:13:35 volumio volumio[832]: info: Connection to go-librespot Websocket established Apr 25 13:13:38 volumio volumio[832]: info: Getting Spotify volume Apr 25 13:13:38 volumio volumio[832]: info: Spotify volume: 100 Apr 25 13:13:38 volumio volumio[832]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 25 13:13:38 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:13:38 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:13:38 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:23:07 volumio sudo[31444]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 25 13:23:07 volumio sudo[31444]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:23:07 volumio sudo[31444]: pam_unix(sudo:session): session closed for user root Apr 25 13:23:07 volumio sudo[31447]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 25 13:23:07 volumio sudo[31447]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:23:07 volumio sudo[31447]: pam_unix(sudo:session): session closed for user root Apr 25 13:23:08 volumio sudo[31450]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 25 13:23:08 volumio sudo[31450]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:23:08 volumio sudo[31450]: pam_unix(sudo:session): session closed for user root Apr 25 13:23:08 volumio sudo[31453]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 25 13:23:08 volumio sudo[31453]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:23:08 volumio sudo[31453]: pam_unix(sudo:session): session closed for user root Apr 25 13:23:08 volumio volumio[832]: verbose: New Socket.io Connection to 192.168.1.244 from 192.168.1.121 UA: Mozilla/5.0 (X11; Linux x86_64; rv:125.0) Gecko/20100101 Firefox/125.0 Total Clients: 6 Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::volumioGetVisibleSources Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:23:08 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 25 13:23:08 volumio volumio[832]: info: Received Get System Info Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 25 13:23:08 volumio volumio[832]: info: Discovery: Getting this device information Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:23:08 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:23:08 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:08 volumio volumio[832]: info: Listing playlists Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 25 13:23:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 25 13:23:09 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:23:09 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:10 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 25 13:23:10 volumio volumio[832]: info: Received Get System Info Apr 25 13:23:10 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 25 13:23:10 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 25 13:23:10 volumio volumio[832]: info: Discovery: Getting this device information Apr 25 13:23:10 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:23:10 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:10 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 25 13:23:11 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 25 13:23:11 volumio volumio[832]: info: Received Get System Info Apr 25 13:23:11 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 25 13:23:11 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 25 13:23:11 volumio volumio[832]: info: Discovery: Getting this device information Apr 25 13:23:11 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:23:11 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:11 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::volumioPlay Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::play index undefined Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::startPlaybackTimer Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::clearAddPlayTracks USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 01 - Querida.flac Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand stop Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand stop took 3 milliseconds Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand clear Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand clear took 0 milliseconds Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand add "USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 01 - Querida.flac" Apr 25 13:23:14 volumio volumio[832]: info: Apr 25 13:23:14 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:23:14 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:23:14 volumio volumio[832]: info: Apr 25 13:23:14 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:23:14 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand add "USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 01 - Querida.flac" took 5 milliseconds Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand play Apr 25 13:23:14 volumio volumio[832]: info: Apr 25 13:23:14 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:23:14 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:23:14 volumio volumio[832]: info: Apr 25 13:23:14 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:23:14 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:23:14 volumio volumio[832]: error: Upnp client error: Error: This socket has been ended by the other party Apr 25 13:23:14 volumio volumio[832]: info: Apr 25 13:23:14 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:23:14 volumio volumio[832]: info: ------------------------------ 16ms Apr 25 13:23:14 volumio volumio[832]: info: ------------------------------ 16ms Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand play took 18 milliseconds Apr 25 13:23:14 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:23:14 volumio volumio[832]: info: ------------------------------ 19ms Apr 25 13:23:14 volumio volumio[832]: info: ------------------------------ 18ms Apr 25 13:23:14 volumio volumio[832]: info: Apr 25 13:23:14 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:23:14 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:23:14 volumio volumio[832]: info: Apr 25 13:23:14 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:23:14 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:23:14 volumio volumio[832]: info: Apr 25 13:23:14 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:23:14 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:23:14 volumio volumio[832]: info: Apr 25 13:23:14 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:23:14 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand status took 27 milliseconds Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:23:14 volumio volumio[832]: info: Apr 25 13:23:14 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:23:14 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:23:14 volumio volumio[832]: info: Apr 25 13:23:14 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:23:14 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:23:14 volumio volumio[832]: info: Apr 25 13:23:14 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:23:14 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:23:14 volumio volumio[832]: info: ------------------------------ 36ms Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand status took 36 milliseconds Apr 25 13:23:14 volumio volumio[832]: info: ------------------------------ 35ms Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand status took 35 milliseconds Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand playlistinfo took 9 milliseconds Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:23:14 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":295,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Querida","artist":"Juan Gabriel con Juanes","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 01 - Querida.flac","trackType":"flac"} Apr 25 13:23:14 volumio volumio[832]: verbose: CURRENT POSITION 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus stop Apr 25 13:23:14 volumio volumio[832]: info: ------------------------------ 52ms Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand status took 11 milliseconds Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand status took 9 milliseconds Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand status took 8 milliseconds Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand playlistinfo took 5 milliseconds Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:23:14 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":22,"duration":295,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Querida","artist":"Juan Gabriel con Juanes","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 01 - Querida.flac","trackType":"flac"} Apr 25 13:23:14 volumio volumio[832]: verbose: CURRENT POSITION 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:23:14 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:23:14 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":91,"duration":295,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Querida","artist":"Juan Gabriel con Juanes","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 01 - Querida.flac","trackType":"flac"} Apr 25 13:23:14 volumio volumio[832]: verbose: CURRENT POSITION 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:23:14 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:23:14 volumio volumio[832]: info: ------------------------------ 61ms Apr 25 13:23:14 volumio volumio[832]: info: ------------------------------ 64ms Apr 25 13:23:14 volumio volumio[832]: info: sendMpdCommand playlistinfo took 22 milliseconds Apr 25 13:23:14 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:23:14 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":842,"duration":295,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"723 Kbps","isStreaming":false,"title":"Querida","artist":"Juan Gabriel con Juanes","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 01 - Querida.flac","trackType":"flac"} Apr 25 13:23:14 volumio volumio[832]: verbose: CURRENT POSITION 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:23:14 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:23:14 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":842,"duration":295,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"723 Kbps","isStreaming":false,"title":"Querida","artist":"Juan Gabriel con Juanes","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 01 - Querida.flac","trackType":"flac"} Apr 25 13:23:14 volumio volumio[832]: verbose: CURRENT POSITION 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:23:14 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:23:14 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":842,"duration":295,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"723 Kbps","isStreaming":false,"title":"Querida","artist":"Juan Gabriel con Juanes","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 01 - Querida.flac","trackType":"flac"} Apr 25 13:23:14 volumio volumio[832]: verbose: CURRENT POSITION 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:23:14 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:23:14 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:23:14 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:14 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:23:14 volumio volumio[832]: info: ------------------------------ 54ms Apr 25 13:23:14 volumio volumio[832]: info: ------------------------------ 53ms Apr 25 13:23:14 volumio volumio[832]: info: ------------------------------ 52ms Apr 25 13:23:14 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:23:14 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:23:14 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:23:14 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:23:14 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:23:14 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:23:14 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:23:14 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:23:14 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:23:14 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:23:27 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 25 13:23:27 volumio volumio[832]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Apr 25 13:23:27 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Apr 25 13:23:27 volumio volumio[832]: info: Received Get System Version Apr 25 13:23:27 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 25 13:23:27 volumio volumio[832]: info: Received Get System Info Apr 25 13:23:27 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 25 13:23:27 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 25 13:23:27 volumio volumio[832]: info: Discovery: Getting this device information Apr 25 13:23:27 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:23:27 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:23:27 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 25 13:23:35 volumio volumio[832]: info: CoreCommandRouter::volumioGetQueue Apr 25 13:23:35 volumio volumio[832]: info: CoreStateMachine::getQueue Apr 25 13:23:35 volumio volumio[832]: info: CorePlayQueue::getQueue Apr 25 13:28:03 volumio volumio[832]: info: CorePlayQueue::getTrack 0 Apr 25 13:28:03 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:28:03 volumio volumio[832]: info: Prefetching next song Apr 25 13:28:03 volumio volumio[832]: info: DOING PREFETCH IN MPD Apr 25 13:28:03 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand add "USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 02 - Se me olvidó otra vez.flac" Apr 25 13:28:03 volumio volumio[832]: info: sendMpdCommand add "USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 02 - Se me olvidó otra vez.flac" took 2 milliseconds Apr 25 13:28:03 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand consume 1 Apr 25 13:28:03 volumio volumio[832]: info: Apr 25 13:28:03 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:28:03 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:28:03 volumio volumio[832]: info: Apr 25 13:28:03 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:28:03 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:28:03 volumio volumio[832]: info: Apr 25 13:28:03 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:28:03 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:28:03 volumio volumio[832]: info: sendMpdCommand consume 1 took 4 milliseconds Apr 25 13:28:03 volumio volumio[832]: info: ------------------------------ 4ms Apr 25 13:28:03 volumio volumio[832]: info: ------------------------------ 3ms Apr 25 13:28:03 volumio volumio[832]: info: ------------------------------ 4ms Apr 25 13:28:07 volumio volumio[832]: info: CoreStateMachine::startPlaybackTimer Apr 25 13:28:07 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:28:08 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:28:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 25 13:28:08 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:28:08 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:28:08 volumio volumio[832]: info: Apr 25 13:28:08 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:28:08 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:28:08 volumio volumio[832]: info: Apr 25 13:28:08 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:28:08 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:28:08 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:28:08 volumio volumio[832]: info: Apr 25 13:28:08 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:28:08 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:28:08 volumio volumio[832]: info: Apr 25 13:28:08 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:28:08 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:28:08 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:28:08 volumio volumio[832]: info: Apr 25 13:28:08 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:28:08 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:28:08 volumio volumio[832]: info: Apr 25 13:28:08 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:28:08 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:28:08 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:28:08 volumio volumio[832]: info: ------------------------------ 9ms Apr 25 13:28:08 volumio volumio[832]: info: sendMpdCommand status took 9 milliseconds Apr 25 13:28:08 volumio volumio[832]: info: ------------------------------ 8ms Apr 25 13:28:08 volumio volumio[832]: info: sendMpdCommand status took 8 milliseconds Apr 25 13:28:08 volumio volumio[832]: info: ------------------------------ 7ms Apr 25 13:28:08 volumio volumio[832]: info: sendMpdCommand status took 4 milliseconds Apr 25 13:28:08 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:28:08 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:28:08 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:28:08 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:28:08 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:28:08 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:28:08 volumio volumio[832]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 25 13:28:08 volumio volumio[832]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 25 13:28:08 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:28:08 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:28:08 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:28:08 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:28:08 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:28:08 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:28:08 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":91,"duration":197,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"586 Kbps","isStreaming":false,"title":"Se me olvidó otra vez","artist":"Juan Gabriel con Marco Antonio Solís","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 02 - Se me olvidó otra vez.flac","trackType":"flac"} Apr 25 13:28:08 volumio volumio[832]: verbose: CURRENT POSITION 1 Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:28:08 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:28:08 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:28:08 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 25 13:28:08 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:28:08 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:28:08 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:28:08 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:28:08 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:28:08 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:28:08 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":91,"duration":197,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"586 Kbps","isStreaming":false,"title":"Se me olvidó otra vez","artist":"Juan Gabriel con Marco Antonio Solís","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 02 - Se me olvidó otra vez.flac","trackType":"flac"} Apr 25 13:28:08 volumio volumio[832]: verbose: CURRENT POSITION 1 Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:28:08 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:28:08 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:28:08 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:28:08 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:28:08 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:28:08 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:28:08 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:28:08 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:28:08 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":91,"duration":197,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"586 Kbps","isStreaming":false,"title":"Se me olvidó otra vez","artist":"Juan Gabriel con Marco Antonio Solís","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 02 - Se me olvidó otra vez.flac","trackType":"flac"} Apr 25 13:28:08 volumio volumio[832]: verbose: CURRENT POSITION 1 Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:28:08 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:28:08 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:28:08 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:28:08 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:28:08 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:28:08 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:28:08 volumio volumio[832]: info: ------------------------------ 61ms Apr 25 13:28:08 volumio volumio[832]: info: ------------------------------ 70ms Apr 25 13:28:08 volumio volumio[832]: info: ------------------------------ 67ms Apr 25 13:28:08 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:28:08 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:28:56 volumio go-librespot[30836]: time="2024-04-25T13:28:56-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:28:56 volumio go-librespot[30836]: time="2024-04-25T13:28:56-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:31:20 volumio volumio[832]: info: CorePlayQueue::getTrack 1 Apr 25 13:31:20 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:31:20 volumio volumio[832]: info: Prefetching next song Apr 25 13:31:20 volumio volumio[832]: info: DOING PREFETCH IN MPD Apr 25 13:31:20 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand add "USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 03 - Hasta que te conocí.flac" Apr 25 13:31:20 volumio volumio[832]: info: Apr 25 13:31:20 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:31:20 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:31:20 volumio volumio[832]: info: sendMpdCommand add "USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 03 - Hasta que te conocí.flac" took 4 milliseconds Apr 25 13:31:20 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand consume 1 Apr 25 13:31:20 volumio volumio[832]: info: Apr 25 13:31:20 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:31:20 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:31:20 volumio volumio[832]: info: Apr 25 13:31:20 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:31:20 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:31:20 volumio volumio[832]: info: ------------------------------ 3ms Apr 25 13:31:20 volumio volumio[832]: info: sendMpdCommand consume 1 took 2 milliseconds Apr 25 13:31:20 volumio volumio[832]: info: ------------------------------ 1ms Apr 25 13:31:20 volumio volumio[832]: info: ------------------------------ 1ms Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::startPlaybackTimer Apr 25 13:31:25 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:31:25 volumio volumio[832]: info: Apr 25 13:31:25 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:31:25 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:31:25 volumio volumio[832]: info: Apr 25 13:31:25 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:31:25 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:31:25 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:31:25 volumio volumio[832]: info: Apr 25 13:31:25 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:31:25 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:31:25 volumio volumio[832]: info: Apr 25 13:31:25 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:31:25 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:31:25 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:31:25 volumio volumio[832]: info: Apr 25 13:31:25 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:31:25 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:31:25 volumio volumio[832]: info: Apr 25 13:31:25 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:31:25 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:31:25 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:31:25 volumio volumio[832]: info: ------------------------------ 5ms Apr 25 13:31:25 volumio volumio[832]: info: sendMpdCommand status took 5 milliseconds Apr 25 13:31:25 volumio volumio[832]: info: ------------------------------ 5ms Apr 25 13:31:25 volumio volumio[832]: info: sendMpdCommand status took 4 milliseconds Apr 25 13:31:25 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:31:25 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:31:25 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:31:25 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:31:25 volumio volumio[832]: info: ------------------------------ 5ms Apr 25 13:31:25 volumio volumio[832]: info: sendMpdCommand status took 3 milliseconds Apr 25 13:31:25 volumio volumio[832]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 25 13:31:25 volumio volumio[832]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 25 13:31:25 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:31:25 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:31:25 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:31:25 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:31:25 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:31:25 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:31:25 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:31:25 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":528,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"696 Kbps","isStreaming":false,"title":"Hasta que te conocí","artist":"Juan Gabriel con Joy","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 03 - Hasta que te conocí.flac","trackType":"flac"} Apr 25 13:31:25 volumio volumio[832]: verbose: CURRENT POSITION 2 Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:31:25 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:31:25 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:31:25 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 25 13:31:25 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:31:25 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:31:25 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:31:25 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:31:25 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:31:25 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:31:25 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":528,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"696 Kbps","isStreaming":false,"title":"Hasta que te conocí","artist":"Juan Gabriel con Joy","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 03 - Hasta que te conocí.flac","trackType":"flac"} Apr 25 13:31:25 volumio volumio[832]: verbose: CURRENT POSITION 2 Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:31:25 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:31:25 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:31:25 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:31:25 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:31:25 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:31:25 volumio volumio[832]: info: ------------------------------ 19ms Apr 25 13:31:25 volumio volumio[832]: info: ------------------------------ 19ms Apr 25 13:31:25 volumio volumio[832]: info: sendMpdCommand playlistinfo took 12 milliseconds Apr 25 13:31:25 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:31:25 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:31:25 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:31:25 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:31:25 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":68,"duration":528,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"696 Kbps","isStreaming":false,"title":"Hasta que te conocí","artist":"Juan Gabriel con Joy","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 03 - Hasta que te conocí.flac","trackType":"flac"} Apr 25 13:31:25 volumio volumio[832]: verbose: CURRENT POSITION 2 Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:31:25 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:31:25 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:31:25 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:31:25 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:31:25 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:31:25 volumio volumio[832]: info: ------------------------------ 25ms Apr 25 13:31:25 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:31:25 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:31:25 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:31:25 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:31:25 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 25 13:31:25 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:31:25 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:31:51 volumio go-librespot[30836]: time="2024-04-25T13:31:51-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:31:51 volumio go-librespot[30836]: time="2024-04-25T13:31:51-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:33:22 volumio go-librespot[30836]: time="2024-04-25T13:33:22-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:33:22 volumio go-librespot[30836]: time="2024-04-25T13:33:22-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:35:44 volumio go-librespot[30836]: time="2024-04-25T13:35:44-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:35:44 volumio go-librespot[30836]: time="2024-04-25T13:35:44-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:36:35 volumio go-librespot[30836]: time="2024-04-25T13:36:35-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:36:35 volumio go-librespot[30836]: time="2024-04-25T13:36:35-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:36:50 volumio go-librespot[30836]: time="2024-04-25T13:36:50-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:36:50 volumio go-librespot[30836]: time="2024-04-25T13:36:50-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:37:24 volumio go-librespot[30836]: time="2024-04-25T13:37:24-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:37:25 volumio go-librespot[30836]: time="2024-04-25T13:37:25-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:37:53 volumio go-librespot[30836]: time="2024-04-25T13:37:53-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:37:53 volumio go-librespot[30836]: time="2024-04-25T13:37:53-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:38:06 volumio go-librespot[30836]: time="2024-04-25T13:38:06-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:38:06 volumio go-librespot[30836]: time="2024-04-25T13:38:06-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:39:01 volumio go-librespot[30836]: time="2024-04-25T13:39:01-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:39:02 volumio go-librespot[30836]: time="2024-04-25T13:39:02-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:39:10 volumio go-librespot[30836]: time="2024-04-25T13:39:10-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:39:10 volumio go-librespot[30836]: time="2024-04-25T13:39:10-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:39:22 volumio go-librespot[30836]: time="2024-04-25T13:39:22-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:39:22 volumio go-librespot[30836]: time="2024-04-25T13:39:22-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:39:30 volumio go-librespot[30836]: time="2024-04-25T13:39:30-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:39:30 volumio go-librespot[30836]: time="2024-04-25T13:39:30-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:40:06 volumio go-librespot[30836]: time="2024-04-25T13:40:06-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:40:06 volumio go-librespot[30836]: time="2024-04-25T13:40:06-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:40:08 volumio volumio[832]: info: CorePlayQueue::getTrack 2 Apr 25 13:40:08 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:40:08 volumio volumio[832]: info: Prefetching next song Apr 25 13:40:08 volumio volumio[832]: info: DOING PREFETCH IN MPD Apr 25 13:40:08 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand add "USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 04 - La diferencia.flac" Apr 25 13:40:08 volumio volumio[832]: info: Apr 25 13:40:08 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:40:08 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:40:08 volumio volumio[832]: info: sendMpdCommand add "USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 04 - La diferencia.flac" took 1 milliseconds Apr 25 13:40:08 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand consume 1 Apr 25 13:40:08 volumio volumio[832]: info: Apr 25 13:40:08 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:40:08 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:40:08 volumio volumio[832]: info: Apr 25 13:40:08 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:40:08 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:40:08 volumio volumio[832]: info: ------------------------------ 3ms Apr 25 13:40:08 volumio volumio[832]: info: sendMpdCommand consume 1 took 2 milliseconds Apr 25 13:40:08 volumio volumio[832]: info: ------------------------------ 2ms Apr 25 13:40:08 volumio volumio[832]: info: ------------------------------ 1ms Apr 25 13:40:12 volumio volumio[832]: info: CoreStateMachine::startPlaybackTimer Apr 25 13:40:12 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:40:13 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:40:13 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 25 13:40:13 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:40:13 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:40:13 volumio volumio[832]: info: Apr 25 13:40:13 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:40:13 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:40:13 volumio volumio[832]: info: Apr 25 13:40:13 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:40:13 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:40:13 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:40:13 volumio volumio[832]: info: Apr 25 13:40:13 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:40:13 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:40:13 volumio volumio[832]: info: Apr 25 13:40:13 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:40:13 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:40:13 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:40:13 volumio volumio[832]: info: Apr 25 13:40:13 volumio volumio[832]: ---------------------------- MPD announces system playlist update Apr 25 13:40:13 volumio volumio[832]: info: Ignoring MPD Status Update Apr 25 13:40:13 volumio volumio[832]: info: Apr 25 13:40:13 volumio volumio[832]: ---------------------------- MPD announces state update: player Apr 25 13:40:13 volumio volumio[832]: info: ControllerMpd::getState Apr 25 13:40:13 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand status Apr 25 13:40:13 volumio volumio[832]: info: ------------------------------ 4ms Apr 25 13:40:13 volumio volumio[832]: info: sendMpdCommand status took 3 milliseconds Apr 25 13:40:13 volumio volumio[832]: info: ------------------------------ 3ms Apr 25 13:40:13 volumio volumio[832]: info: sendMpdCommand status took 2 milliseconds Apr 25 13:40:13 volumio volumio[832]: info: ------------------------------ 2ms Apr 25 13:40:13 volumio volumio[832]: info: sendMpdCommand status took 2 milliseconds Apr 25 13:40:13 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:40:13 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:40:13 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:40:13 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:40:13 volumio volumio[832]: verbose: ControllerMpd::parseState Apr 25 13:40:13 volumio volumio[832]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 25 13:40:13 volumio volumio[832]: info: sendMpdCommand playlistinfo took 1 milliseconds Apr 25 13:40:13 volumio volumio[832]: info: sendMpdCommand playlistinfo took 1 milliseconds Apr 25 13:40:13 volumio volumio[832]: info: sendMpdCommand playlistinfo took 1 milliseconds Apr 25 13:40:13 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:40:13 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:40:13 volumio volumio[832]: verbose: ControllerMpd::parseTrackInfo Apr 25 13:40:13 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:40:13 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:40:13 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:40:13 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":212,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"606 Kbps","isStreaming":false,"title":"La diferencia","artist":"Juan Gabriel con Vicente Fernández","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 04 - La diferencia.flac","trackType":"flac"} Apr 25 13:40:13 volumio volumio[832]: verbose: CURRENT POSITION 3 Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:40:13 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:40:13 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:40:13 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 25 13:40:13 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:40:13 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:40:13 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:40:13 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:40:13 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:40:13 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:40:13 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":212,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"606 Kbps","isStreaming":false,"title":"La diferencia","artist":"Juan Gabriel con Vicente Fernández","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 04 - La diferencia.flac","trackType":"flac"} Apr 25 13:40:13 volumio volumio[832]: verbose: CURRENT POSITION 3 Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:40:13 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:40:13 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:40:13 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:40:13 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:40:13 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:40:13 volumio volumio[832]: info: ControllerMpd::pushState Apr 25 13:40:13 volumio volumio[832]: info: CoreCommandRouter::servicePushState Apr 25 13:40:13 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:40:13 volumio volumio[832]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":212,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"606 Kbps","isStreaming":false,"title":"La diferencia","artist":"Juan Gabriel con Vicente Fernández","album":"Los dúo","uri":"USB/Toshiba_2TB/Juan Gabriel/Juan Gabriel - Los dúo (disco 1 y 2)/Disc 1 - 04 - La diferencia.flac","trackType":"flac"} Apr 25 13:40:13 volumio volumio[832]: verbose: CURRENT POSITION 3 Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::syncState stateService play Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::syncState currentStatus play Apr 25 13:40:13 volumio volumio[832]: info: Received an update from plugin. extracting info from payload Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:40:13 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:40:13 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:40:13 volumio volumio[832]: info: CoreStateMachine::pushState Apr 25 13:40:13 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:40:13 volumio volumio[832]: info: CoreCommandRouter::volumioPushState Apr 25 13:40:13 volumio volumio[832]: info: ------------------------------ 19ms Apr 25 13:40:13 volumio volumio[832]: info: ------------------------------ 19ms Apr 25 13:40:13 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:40:13 volumio volumio[832]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 25 13:40:22 volumio go-librespot[30836]: time="2024-04-25T13:40:22-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:40:22 volumio go-librespot[30836]: time="2024-04-25T13:40:22-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:40:34 volumio go-librespot[30836]: time="2024-04-25T13:40:34-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:40:34 volumio go-librespot[30836]: time="2024-04-25T13:40:34-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:41:14 volumio go-librespot[30836]: time="2024-04-25T13:41:14-05:00" level=debug msg="skipping dealer message" uri="hm://playlist/v2/playlist/1KFtGEe6T00sn4BtSFNKOg" Apr 25 13:41:14 volumio go-librespot[30836]: time="2024-04-25T13:41:14-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 252" Apr 25 13:41:16 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: youtube2 , handleBrowseUri Apr 25 13:41:16 volumio volumio[832]: info: [youtube2-browse] browseUri: youtube2 Apr 25 13:41:16 volumio volumio[832]: info: [youtube2] InnertubeLoader: creating Innertube instance... Apr 25 13:41:17 volumio volumio[832]: info: [youtube2] InnertubeLoader: creating Auth instance... Apr 25 13:41:17 volumio volumio[832]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 25 13:41:26 volumio volumio[832]: info: CoreCommandRouter::volumioGetState Apr 25 13:41:26 volumio volumio[832]: info: CorePlayQueue::getTrack 3 Apr 25 13:41:28 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 25 13:41:28 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 25 13:41:33 volumio volumio[832]: info: Enabling plugin fusiondsp Apr 25 13:41:33 volumio volumio[832]: info: Loading plugin "fusiondsp"... Apr 25 13:41:34 volumio volumio[832]: info: Preparing to generate the ALSA configuration file Apr 25 13:41:34 volumio volumio[832]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Apr 25 13:41:34 volumio volumio[832]: info: Reading ALSA contributions from plugins. Apr 25 13:41:34 volumio volumio[832]: info: Asound.conf file written Apr 25 13:41:34 volumio sudo[2444]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Apr 25 13:41:34 volumio sudo[2444]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:41:34 volumio sudo[2444]: pam_unix(sudo:session): session closed for user root Apr 25 13:41:34 volumio volumio[832]: info: Output device has changed, restarting MPD Apr 25 13:41:34 volumio sudo[2449]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 25 13:41:34 volumio sudo[2449]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:41:34 volumio sudo[2449]: pam_unix(sudo:session): session closed for user root Apr 25 13:41:34 volumio volumio[832]: info: Output device has changed, restarting Shairport Sync Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 25 13:41:34 volumio sudo[2453]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 25 13:41:34 volumio sudo[2453]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:41:34 volumio systemd[1]: Stopping Music Player Daemon... Apr 25 13:41:34 volumio volumio[832]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 25 13:41:34 volumio volumio[832]: info: PLUGIN START: fusiondsp Apr 25 13:41:34 volumio volumio[832]: info: Loading i18n strings for locale es Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: FusionDsp - mixtype--------------------- Hardware Apr 25 13:41:34 volumio volumio[832]: info: Preparing to generate the ALSA configuration file Apr 25 13:41:34 volumio volumio[832]: info: Done. Apr 25 13:41:34 volumio volumio[832]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Apr 25 13:41:34 volumio volumio[832]: info: Reading ALSA contributions from plugins. Apr 25 13:41:34 volumio volumio[832]: info: MPD Permissions set Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: Asound.conf file unchanged, so no further update is needed Apr 25 13:41:34 volumio volumio[832]: info: Output device has changed, restarting MPD Apr 25 13:41:34 volumio sudo[2465]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 25 13:41:34 volumio sudo[2465]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:41:34 volumio sudo[2465]: pam_unix(sudo:session): session closed for user root Apr 25 13:41:34 volumio volumio[832]: info: Output device has changed, restarting Shairport Sync Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 25 13:41:34 volumio sudo[2468]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 25 13:41:34 volumio sudo[2468]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:41:34 volumio volumio[832]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 25 13:41:34 volumio volumio[832]: info: MPD Permissions set Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 25 13:41:34 volumio volumio[832]: info: Starting Shairport Sync Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio sudo[2474]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 25 13:41:34 volumio sudo[2474]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:41:34 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Apr 25 13:41:34 volumio systemd[1]: shairport-sync.service: Succeeded. Apr 25 13:41:34 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 25 13:41:34 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:34 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 25 13:41:34 volumio volumio[832]: info: Starting Shairport Sync Apr 25 13:41:34 volumio sudo[2474]: pam_unix(sudo:session): session closed for user root Apr 25 13:41:34 volumio sudo[2484]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 25 13:41:34 volumio sudo[2484]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:41:34 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 25 13:41:34 volumio systemd[1]: shairport-sync.service: Succeeded. Apr 25 13:41:34 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 25 13:41:34 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 25 13:41:34 volumio sudo[2484]: pam_unix(sudo:session): session closed for user root Apr 25 13:41:34 volumio systemd[1]: mpd.service: Succeeded. Apr 25 13:41:34 volumio systemd[1]: Stopped Music Player Daemon. Apr 25 13:41:34 volumio systemd[1]: Starting Music Player Daemon... Apr 25 13:41:34 volumio volumio[832]: info: Shairport-Sync Started Apr 25 13:41:34 volumio volumio[832]: info: Shairport-Sync Started Apr 25 13:41:35 volumio volumio[832]: error: Upnp client error: Error: This socket has been ended by the other party Apr 25 13:41:35 volumio volumio[832]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 25 13:41:35 volumio mpd[2489]: Apr 25 13:41 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 25 13:41:36 volumio systemd[1]: Started Music Player Daemon. Apr 25 13:41:36 volumio sudo[2468]: pam_unix(sudo:session): session closed for user root Apr 25 13:41:36 volumio sudo[2453]: pam_unix(sudo:session): session closed for user root Apr 25 13:41:36 volumio volumio[832]: error: MPD error: The expression evaluated to a falsy value: Apr 25 13:41:36 volumio volumio[832]: assert.ok(self.idling) Apr 25 13:41:36 volumio volumio[832]: error: The expression evaluated to a falsy value: Apr 25 13:41:36 volumio volumio[832]: assert.ok(self.idling) Apr 25 13:41:36 volumio volumio[832]: error: updateQueue error: null Apr 25 13:41:36 volumio volumio[832]: info: camilladsp spawned new process with pid undefined, instance 1, run: true Apr 25 13:41:36 volumio volumio[832]: info: camilladsp service started and running in background, instance 1 Apr 25 13:41:36 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:41:36 volumio volumio[832]: info: FusionDsp - AAAAAAAAAAAAAA-> 44100 48000 88200 96000 <-AAAAAAAAAAAAA Apr 25 13:41:36 volumio volumio[832]: info: FusionDsp loaded Apr 25 13:41:36 volumio volumio[832]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 25 13:41:36 volumio sudo[2504]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Apr 25 13:41:36 volumio sudo[2504]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:41:36 volumio volumio[832]: info: FusionDsp - Reporting Fusion DSP Enabled Apr 25 13:41:36 volumio volumio[832]: info: Adding Signal Path Element [object Object] Apr 25 13:41:36 volumio volumio[832]: info: Adding fusiondspeq DSP Signal Path Element Apr 25 13:41:36 volumio volumio[832]: info: FusionDsp - ---- installed callbackRead Apr 25 13:41:36 volumio volumio[832]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 25 13:41:36 volumio systemd[1]: Started FusionDsp Daemon. Apr 25 13:41:36 volumio volumio[832]: Error: spawn /data/plugins/audio_interface/fusiondsp/camilladsp ENOENT Apr 25 13:41:36 volumio volumio[832]: at Process.ChildProcess._handle.onexit (internal/child_process.js:277:19) Apr 25 13:41:36 volumio volumio[832]: at onErrorNT (internal/child_process.js:472:16) Apr 25 13:41:36 volumio volumio[832]: at processTicksAndRejections (internal/process/task_queues.js:82:21) { Apr 25 13:41:36 volumio volumio[832]: errno: -2, Apr 25 13:41:36 volumio volumio[832]: code: 'ENOENT', Apr 25 13:41:36 volumio volumio[832]: syscall: 'spawn /data/plugins/audio_interface/fusiondsp/camilladsp', Apr 25 13:41:36 volumio volumio[832]: path: '/data/plugins/audio_interface/fusiondsp/camilladsp', Apr 25 13:41:36 volumio volumio[832]: spawnargs: [ Apr 25 13:41:36 volumio volumio[832]: '-p', Apr 25 13:41:36 volumio volumio[832]: 9876, Apr 25 13:41:36 volumio volumio[832]: '-o', Apr 25 13:41:36 volumio volumio[832]: '/tmp/camilladsp.log', Apr 25 13:41:36 volumio volumio[832]: '-l', Apr 25 13:41:36 volumio volumio[832]: 'warn', Apr 25 13:41:36 volumio volumio[832]: '/data/configuration/audio_interface/fusiondsp/camilladsp.yml' Apr 25 13:41:36 volumio volumio[832]: ] Apr 25 13:41:36 volumio volumio[832]: } Apr 25 13:41:36 volumio volumio[832]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 25 13:41:36 volumio sudo[2504]: pam_unix(sudo:session): session closed for user root Apr 25 13:41:36 volumio volumio[2506]: /usr/bin/python3: can't open file '/data/plugins/audio_interface/fusiondsp/cgui/main.py': [Errno 2] No such file or directory Apr 25 13:41:36 volumio systemd[1]: fusiondsp.service: Main process exited, code=exited, status=2/INVALIDARGUMENT Apr 25 13:41:36 volumio systemd[1]: fusiondsp.service: Failed with result 'exit-code'. Apr 25 13:41:37 volumio sudo[2516]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-25 12:40 Apr 25 13:41:37 volumio sudo[2516]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="7b9cb4a8b52fb7148a38d6ac651c1c29e09bb92c" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="b1dcc17f6d31bf91f0abd3c3fa57506d1e0d2b6b" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 01 Mar 2024 08:52:33 PM CET" VOLUMIO_VERSION="3.634" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="93edfc70711724967af109c0a39fa069"