-- Logs begin at Thu 2019-02-14 05:12:00 EST, end at Thu 2024-10-24 19:06:33 EDT. -- Oct 24 19:05:01 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 24 19:05:01 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 24 19:05:01 volumio volumio[803]: info: Discovery: Getting this device information Oct 24 19:05:01 volumio volumio[803]: info: CoreCommandRouter::volumioGetState Oct 24 19:05:01 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 24 19:05:08 volumio volumio[803]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 24 19:05:12 volumio nmbd[741]: [2024/10/24 19:05:12.887756, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Oct 24 19:05:12 volumio nmbd[741]: query_name_response: Multiple (2) responses received for a query on subnet 10.0.0.77 for name WORKGROUP<1d>. Oct 24 19:05:12 volumio nmbd[741]: This response was from IP 10.0.0.218, reporting an IP address of 10.0.0.218. Oct 24 19:05:16 volumio volumio[803]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Oct 24 19:05:16 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Oct 24 19:05:16 volumio volumio[803]: info: Creating Spotify config file Oct 24 19:05:16 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 19:05:16 volumio volumio[803]: info: Spotify config file written Oct 24 19:05:16 volumio sudo[2308]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 24 19:05:16 volumio sudo[2308]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:05:16 volumio systemd[1]: Stopping go-librespot Daemon... Oct 24 19:05:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 24 19:05:16 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 24 19:05:16 volumio systemd[1]: Stopped go-librespot Daemon. Oct 24 19:05:16 volumio volumio[803]: info: Connection to go-librespot Websocket closed Oct 24 19:05:16 volumio systemd[1]: Started go-librespot Daemon. Oct 24 19:05:16 volumio go-librespot[2310]: Librespot-go daemon starting... Oct 24 19:05:16 volumio sudo[2308]: pam_unix(sudo:session): session closed for user root Oct 24 19:05:16 volumio go-librespot[2310]: time="2024-10-24T19:05:16-04:00" level=info msg="generated new device id: bd563538eb9a090de014f1ed322c4252cf102638" Oct 24 19:05:16 volumio go-librespot[2310]: time="2024-10-24T19:05:16-04:00" level=debug msg="stored credentials found for xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:16 volumio go-librespot[2310]: time="2024-10-24T19:05:16-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Oct 24 19:05:16 volumio go-librespot[2310]: time="2024-10-24T19:05:16-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 24 19:05:16 volumio go-librespot[2310]: time="2024-10-24T19:05:16-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 24 19:05:16 volumio go-librespot[2310]: time="2024-10-24T19:05:16-04:00" level=debug msg="zeroconf server listening on port 41153" Oct 24 19:05:16 volumio go-librespot[2310]: time="2024-10-24T19:05:16-04:00" level=debug msg="obtained new client token: AAB16BrOQ2gvM2Epz2YijE0yy/r5xdm+qkza3sobPvbVTSEmjNkcRS2tXL+4wyuV/sepIF9DSpBrvnbuX0w4uvqZ2jHjUZ9Wz9s4FAGmbfEDI+Zdixh80FMq14Sj2QvppZDrHPyePdAORcck1+dfTf9jltf2t/wuFE749SajP28jlL2zxQTbDwsZOpsdAFuLtiXOLSyhO0aGA/4QiGzLRL690qaQf5IoGOy2uWuvA8bK9rLIVBo7KR8XKpu8" Oct 24 19:05:16 volumio go-librespot[2310]: time="2024-10-24T19:05:16-04:00" level=info msg="connected to ap-gue1.spotify.com:4070" Oct 24 19:05:16 volumio go-librespot[2310]: time="2024-10-24T19:05:16-04:00" level=debug msg="completed keyexchange" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="completed challenge" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="authenticated as xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="authenticated as xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="dealer connection opened" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="initializing zeroconf session, username: xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 495" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="autoplay enabled: false" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="received connection id: NjFmNTJmZjgtMDAwOC00ZjZhLWJlMmItZWNlNGEzYmNmNTQ0K2RlYWxlcit0Y3A6Ly8wYWNiZjk3ZC5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArREQ5MDA1MDIwOTRDRDcwM0Y1MkYwQzg3NDNGMDVEMUJCQTU0N0NENDQ5RDZFRTcwQTc1MzIxRTNCODVEMEZENQ==" Oct 24 19:05:17 volumio go-librespot[2310]: time="2024-10-24T19:05:17-04:00" level=debug msg="put connect state because NEW_DEVICE" Oct 24 19:05:17 volumio volumio[803]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Oct 24 19:05:17 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Oct 24 19:05:17 volumio volumio[803]: info: Creating Spotify config file Oct 24 19:05:17 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 19:05:17 volumio volumio[803]: info: Spotify config file written Oct 24 19:05:18 volumio sudo[2320]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 24 19:05:18 volumio sudo[2320]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:05:18 volumio systemd[1]: Stopping go-librespot Daemon... Oct 24 19:05:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 24 19:05:18 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 24 19:05:18 volumio systemd[1]: Stopped go-librespot Daemon. Oct 24 19:05:18 volumio systemd[1]: Started go-librespot Daemon. Oct 24 19:05:18 volumio go-librespot[2322]: Librespot-go daemon starting... Oct 24 19:05:18 volumio sudo[2320]: pam_unix(sudo:session): session closed for user root Oct 24 19:05:18 volumio go-librespot[2322]: time="2024-10-24T19:05:18-04:00" level=info msg="generated new device id: 49fe503ad4182359d3d4cc3682669fe83f664eaf" Oct 24 19:05:18 volumio go-librespot[2322]: time="2024-10-24T19:05:18-04:00" level=debug msg="stored credentials found for xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:18 volumio go-librespot[2322]: time="2024-10-24T19:05:18-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 24 19:05:18 volumio go-librespot[2322]: time="2024-10-24T19:05:18-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 24 19:05:18 volumio go-librespot[2322]: time="2024-10-24T19:05:18-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 24 19:05:18 volumio go-librespot[2322]: time="2024-10-24T19:05:18-04:00" level=debug msg="zeroconf server listening on port 43657" Oct 24 19:05:18 volumio go-librespot[2322]: time="2024-10-24T19:05:18-04:00" level=debug msg="obtained new client token: AAC1xOGElC7yRVt9t4cHLu2mOmLXx5nkPtUrizJkb9EZBZpn23FX9D7FLo3wEL27YQRQpyJdtw2Lcz4D7zBXGN4AmRY621GAWVQyV1MSdEPpdDP7A775PZOqOUm60xd9P27bHpN3ilogewoP6IrulgE9QbMis85EGtEmCTEUWVyAaKhZOvGsIA4pRhadJyhLWtD0A9GXEjr8yx9+3LX0cQSOyfcnkYOwFTtWWumEhO6QeRtSqza57feAcjAs" Oct 24 19:05:18 volumio go-librespot[2322]: time="2024-10-24T19:05:18-04:00" level=info msg="connected to ap-gue1.spotify.com:4070" Oct 24 19:05:18 volumio go-librespot[2322]: time="2024-10-24T19:05:18-04:00" level=debug msg="completed keyexchange" Oct 24 19:05:18 volumio volumio[803]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Oct 24 19:05:18 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Oct 24 19:05:18 volumio volumio[803]: info: Creating Spotify config file Oct 24 19:05:18 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 19:05:18 volumio volumio[803]: info: Spotify config file written Oct 24 19:05:18 volumio sudo[2331]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 24 19:05:18 volumio sudo[2331]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:05:18 volumio systemd[1]: Stopping go-librespot Daemon... Oct 24 19:05:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 24 19:05:18 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 24 19:05:18 volumio systemd[1]: Stopped go-librespot Daemon. Oct 24 19:05:18 volumio systemd[1]: Started go-librespot Daemon. Oct 24 19:05:18 volumio go-librespot[2333]: Librespot-go daemon starting... Oct 24 19:05:18 volumio sudo[2331]: pam_unix(sudo:session): session closed for user root Oct 24 19:05:18 volumio go-librespot[2333]: time="2024-10-24T19:05:18-04:00" level=info msg="generated new device id: 855ce92ee3a73a46b9d7bd4129ae9dc1d97ba6f4" Oct 24 19:05:18 volumio go-librespot[2333]: time="2024-10-24T19:05:18-04:00" level=debug msg="stored credentials found for xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:19 volumio go-librespot[2333]: time="2024-10-24T19:05:19-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 24 19:05:19 volumio go-librespot[2333]: time="2024-10-24T19:05:19-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 24 19:05:19 volumio go-librespot[2333]: time="2024-10-24T19:05:19-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 24 19:05:19 volumio go-librespot[2333]: time="2024-10-24T19:05:19-04:00" level=debug msg="zeroconf server listening on port 45099" Oct 24 19:05:19 volumio go-librespot[2333]: time="2024-10-24T19:05:19-04:00" level=debug msg="obtained new client token: AABhHBhYclPoQAX+RbDm/eYXfU9BS1D5qunVmy0N7D+uRHtRkBpaMHr2MzF5lZ/MIuEMlBW007MZeAIG4Z4K2JPTIJjbgTZ0C7aoyZMSSfqvkbats1A3vzc2hCehEW90T74wU5oe7poK18MssxvUSbN83eACWatX/Q/S6l9BOHoVvkMMhUc2byZDIhdBCiBqemDIBkbaFP5Ff8bN05Dyf/5LOzc8kPeOHwqSuFBfAvsLiRtq5KF+i3UuLA==" Oct 24 19:05:19 volumio go-librespot[2333]: time="2024-10-24T19:05:19-04:00" level=info msg="connected to ap-gue1.spotify.com:4070" Oct 24 19:05:19 volumio go-librespot[2333]: time="2024-10-24T19:05:19-04:00" level=debug msg="completed keyexchange" Oct 24 19:05:19 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:19 volumio go-librespot[2333]: time="2024-10-24T19:05:19-04:00" level=debug msg="new websocket client" Oct 24 19:05:19 volumio volumio[803]: info: Connection to go-librespot Websocket established Oct 24 19:05:19 volumio volumio[803]: info: go-librespot daemon successfully initialized Oct 24 19:05:19 volumio go-librespot[2333]: time="2024-10-24T19:05:19-04:00" level=debug msg="completed challenge" Oct 24 19:05:19 volumio go-librespot[2333]: time="2024-10-24T19:05:19-04:00" level=debug msg="authenticated as xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:19 volumio volumio[803]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Oct 24 19:05:19 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Oct 24 19:05:19 volumio volumio[803]: info: Creating Spotify config file Oct 24 19:05:19 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 19:05:19 volumio volumio[803]: info: Spotify config file written Oct 24 19:05:19 volumio sudo[2342]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 24 19:05:19 volumio sudo[2342]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:05:19 volumio systemd[1]: Stopping go-librespot Daemon... Oct 24 19:05:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 24 19:05:19 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 24 19:05:19 volumio systemd[1]: Stopped go-librespot Daemon. Oct 24 19:05:19 volumio volumio[803]: info: Connection to go-librespot Websocket closed Oct 24 19:05:19 volumio systemd[1]: Started go-librespot Daemon. Oct 24 19:05:19 volumio go-librespot[2344]: Librespot-go daemon starting... Oct 24 19:05:19 volumio sudo[2342]: pam_unix(sudo:session): session closed for user root Oct 24 19:05:19 volumio go-librespot[2344]: time="2024-10-24T19:05:19-04:00" level=info msg="generated new device id: 8656f78fdbdab6c7271b8c6a167c2fb0350094aa" Oct 24 19:05:19 volumio go-librespot[2344]: time="2024-10-24T19:05:19-04:00" level=debug msg="stored credentials found for xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:20 volumio volumio[803]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Oct 24 19:05:20 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Oct 24 19:05:20 volumio volumio[803]: info: Creating Spotify config file Oct 24 19:05:20 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 19:05:20 volumio volumio[803]: info: Spotify config file written Oct 24 19:05:20 volumio sudo[2353]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 24 19:05:20 volumio sudo[2353]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:05:20 volumio systemd[1]: Stopping go-librespot Daemon... Oct 24 19:05:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 24 19:05:20 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 24 19:05:20 volumio systemd[1]: Stopped go-librespot Daemon. Oct 24 19:05:20 volumio systemd[1]: Started go-librespot Daemon. Oct 24 19:05:20 volumio go-librespot[2355]: Librespot-go daemon starting... Oct 24 19:05:20 volumio sudo[2353]: pam_unix(sudo:session): session closed for user root Oct 24 19:05:20 volumio go-librespot[2355]: time="2024-10-24T19:05:20-04:00" level=info msg="generated new device id: 96afc68da21508c59e376276c677b6df7db987d7" Oct 24 19:05:20 volumio go-librespot[2355]: time="2024-10-24T19:05:20-04:00" level=debug msg="stored credentials found for xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:20 volumio volumio[803]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Oct 24 19:05:20 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Oct 24 19:05:20 volumio volumio[803]: info: Creating Spotify config file Oct 24 19:05:20 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 19:05:20 volumio volumio[803]: info: Spotify config file written Oct 24 19:05:20 volumio sudo[2363]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 24 19:05:20 volumio sudo[2363]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:05:20 volumio systemd[1]: Stopping go-librespot Daemon... Oct 24 19:05:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 24 19:05:20 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 24 19:05:20 volumio systemd[1]: Stopped go-librespot Daemon. Oct 24 19:05:20 volumio systemd[1]: go-librespot-daemon.service: Start request repeated too quickly. Oct 24 19:05:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'start-limit-hit'. Oct 24 19:05:20 volumio systemd[1]: Failed to start go-librespot Daemon. Oct 24 19:05:20 volumio sudo[2363]: pam_unix(sudo:session): session closed for user root Oct 24 19:05:20 volumio volumio[803]: error: Cannot start Go-librespot Daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Oct 24 19:05:20 volumio volumio[803]: Job for go-librespot-daemon.service failed. Oct 24 19:05:20 volumio volumio[803]: See "systemctl status go-librespot-daemon.service" and "journalctl -xe" for details. Oct 24 19:05:20 volumio volumio[803]: error: Error initializing go-librespot daemon: Error: Command failed: /usr/bin/sudo systemctl restart go-librespot-daemon.service Oct 24 19:05:20 volumio volumio[803]: Job for go-librespot-daemon.service failed. Oct 24 19:05:20 volumio volumio[803]: See "systemctl status go-librespot-daemon.service" and "journalctl -xe" for details. Oct 24 19:05:21 volumio volumio[803]: info: go-librespot daemon successfully initialized Oct 24 19:05:21 volumio volumio[803]: info: go-librespot daemon successfully initialized Oct 24 19:05:22 volumio volumio[803]: info: Getting Spotify volume Oct 24 19:05:22 volumio volumio[803]: (node:803) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:22 volumio volumio[803]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Oct 24 19:05:22 volumio volumio[803]: (node:803) 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: 3) Oct 24 19:05:22 volumio volumio[803]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Oct 24 19:05:22 volumio volumio[803]: info: CoreCommandRouter::volumioGetState Oct 24 19:05:22 volumio volumio[803]: SPOTIFY: RECEIVED VOLUMIO VOLUME 45 Oct 24 19:05:22 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:22 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:22 volumio volumio[803]: info: go-librespot daemon successfully initialized Oct 24 19:05:23 volumio volumio[803]: info: go-librespot daemon successfully initialized Oct 24 19:05:24 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:24 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:24 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:24 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:25 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:25 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:26 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:26 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:29 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:29 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:31 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 24 19:05:31 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 24 19:05:31 volumio volumio[803]: info: Discovery: Getting this device information Oct 24 19:05:31 volumio volumio[803]: info: CoreCommandRouter::volumioGetState Oct 24 19:05:31 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 24 19:05:31 volumio volumio[803]: info: CorePlayQueue::getTrack 1 Oct 24 19:05:31 volumio volumio[803]: info: CorePlayQueue::getTrack 2 Oct 24 19:05:31 volumio volumio[803]: info: Prefetching next song Oct 24 19:05:31 volumio volumio[803]: info: [1729811131854] ControllerSpotify::prefetch Oct 24 19:05:31 volumio volumio[803]: info: Sending Spotify command with payload to local API: /player/add_to_queue Oct 24 19:05:31 volumio volumio[803]: error: Failed to send command to Spotify local API: /player/add_to_queue: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:32 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:32 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:35 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:35 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:36 volumio volumio[803]: info: CoreStateMachine::startPlaybackTimer Oct 24 19:05:36 volumio volumio[803]: info: CorePlayQueue::getTrack 2 Oct 24 19:05:36 volumio volumio[803]: info: CoreStateMachine::pushState Oct 24 19:05:36 volumio volumio[803]: info: CoreCommandRouter::volumioPushState Oct 24 19:05:36 volumio volumio[803]: info: PeppySpectrum ---peppyspectrum status pause Oct 24 19:05:36 volumio volumio[803]: SPOTIFY: RECEIVED VOLUMIO VOLUME 45 Oct 24 19:05:36 volumio sudo[2368]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Oct 24 19:05:36 volumio sudo[2368]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:05:36 volumio sudo[2368]: pam_unix(sudo:session): session closed for user root Oct 24 19:05:36 volumio volumio[803]: info: peppyspectrum Daemon Stop Oct 24 19:05:38 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:38 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:39 volumio volumio[803]: info: VolumeController::SetAlsaVolume+ Oct 24 19:05:39 volumio volumio[803]: info: CoreStateMachine::pushState Oct 24 19:05:39 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 24 19:05:39 volumio volumio[803]: info: CoreCommandRouter::volumioPushState Oct 24 19:05:39 volumio volumio[803]: info: PeppySpectrum ---peppyspectrum status pause Oct 24 19:05:39 volumio volumio[803]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Oct 24 19:05:39 volumio volumio[803]: SPOTIFY: SPOTIFY VOLUME 45 Oct 24 19:05:39 volumio volumio[803]: SPOTIFY: VOLUMIO VOLUME 46 Oct 24 19:05:39 volumio volumio[803]: SPOTIFY: DELTA VOLUME ENOUGH: false Oct 24 19:05:39 volumio sudo[2374]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Oct 24 19:05:39 volumio sudo[2374]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:05:39 volumio sudo[2374]: pam_unix(sudo:session): session closed for user root Oct 24 19:05:39 volumio volumio[803]: info: peppyspectrum Daemon Stop Oct 24 19:05:41 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:41 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:43 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 24 19:05:43 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 24 19:05:44 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:44 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:47 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:47 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:47 volumio volumio[803]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Oct 24 19:05:47 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 19:05:47 volumio sudo[2378]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service Oct 24 19:05:47 volumio sudo[2378]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:05:47 volumio volumio[803]: info: Disabling plugin spop Oct 24 19:05:47 volumio volumio[803]: info: Done. Oct 24 19:05:47 volumio sudo[2378]: pam_unix(sudo:session): session closed for user root Oct 24 19:05:50 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:50 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:05:52 volumio volumio[803]: info: Enabling plugin spop Oct 24 19:05:52 volumio volumio[803]: info: Loading plugin "spop"... Oct 24 19:05:52 volumio volumio[803]: info: PLUGIN START: spop Oct 24 19:05:52 volumio volumio[803]: info: Creating Spotify config file Oct 24 19:05:52 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 19:05:52 volumio volumio[803]: info: Done. Oct 24 19:05:52 volumio volumio[803]: info: Spotify config file written Oct 24 19:05:52 volumio volumio[803]: info: No need to fix Spotify hosts Oct 24 19:05:52 volumio sudo[2381]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 24 19:05:52 volumio sudo[2381]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:05:52 volumio systemd[1]: Started go-librespot Daemon. Oct 24 19:05:52 volumio go-librespot[2383]: Librespot-go daemon starting... Oct 24 19:05:52 volumio sudo[2381]: pam_unix(sudo:session): session closed for user root Oct 24 19:05:52 volumio go-librespot[2383]: time="2024-10-24T19:05:52-04:00" level=info msg="generated new device id: a18cb4f6f55ba0ae33c2c6a3b500ea4053c160c3" Oct 24 19:05:52 volumio go-librespot[2383]: time="2024-10-24T19:05:52-04:00" level=debug msg="stored credentials found for xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:53 volumio go-librespot[2383]: time="2024-10-24T19:05:53-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 24 19:05:53 volumio go-librespot[2383]: time="2024-10-24T19:05:53-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 24 19:05:53 volumio go-librespot[2383]: time="2024-10-24T19:05:53-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 24 19:05:53 volumio go-librespot[2383]: time="2024-10-24T19:05:53-04:00" level=debug msg="zeroconf server listening on port 41573" Oct 24 19:05:53 volumio volumio[803]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 24 19:05:53 volumio volumio[803]: SPOTIFY: BQBTa_zedlTVjIUjBWWUzwJIfKyvfYL5EJzjANHdTEV9bAYaIAUjOjEA63wHf9dBFnotF-A2r9gl2pJXpSk2ofl2Gq3h_tE7rluznxy4aRkV-ca2pb0ILPf_ldyuM-N4nUbqXGSGeeXFOa43yJIykIH0uIEF4Ibr53hikUiPHGX90an-oC1yyqN3gFXGzGISHgqENFcseISMsZplpqWmgC4rTn_ANyw0hliAR-hRkdGsoVA9ngttLcYfKh5JW0vFePs2pijInd9CMyU Oct 24 19:05:53 volumio volumio[803]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 24 19:05:53 volumio volumio[803]: info: New Spotify access token = BQBTa_zedlTVjIUjBWWUzwJIfKyvfYL5EJzjANHdTEV9bAYaIAUjOjEA63wHf9dBFnotF-A2r9gl2pJXpSk2ofl2Gq3h_tE7rluznxy4aRkV-ca2pb0ILPf_ldyuM-N4nUbqXGSGeeXFOa43yJIykIH0uIEF4Ibr53hikUiPHGX90an-oC1yyqN3gFXGzGISHgqENFcseISMsZplpqWmgC4rTn_ANyw0hliAR-hRkdGsoVA9ngttLcYfKh5JW0vFePs2pijInd9CMyU Oct 24 19:05:53 volumio volumio[803]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 24 19:05:53 volumio go-librespot[2383]: time="2024-10-24T19:05:53-04:00" level=debug msg="obtained new client token: AAC7T3XXoyblSOPPfNhaH0rQEWXUFQ+3W93jRwO3jt92OZ60mhQG/P4/5unrOjiCd3FL55/ex3g83dUEWFkQgZJkYpgzlMOUF2GVlaQQoGhHkywp56Nw1W9o0SunT1/kh16Srg3Dy3TjydZHY+hQmfzRmdhI2G+wTwoIe4CZ+2fpxeQgmFuI0KYEJ9L0yYqhQlYvOt6FR/pUi5nx6o3rcpnwqqiu5aEPR93u2Vlnghg5W7moLu5xM4UBVQ==" Oct 24 19:05:53 volumio go-librespot[2383]: time="2024-10-24T19:05:53-04:00" level=info msg="connected to ap-gue1.spotify.com:4070" Oct 24 19:05:53 volumio volumio[803]: SPOTIFY: User informations: {"country":"US","display_name":"Hasan","email":"hasan.friends@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/xh3k15zazrk4e1q9ohcfs13oj"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/xh3k15zazrk4e1q9ohcfs13oj","id":"xh3k15zazrk4e1q9ohcfs13oj","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee8591985af56a1aa5ff24672d98","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b8291985af56a1aa5ff24672d98","width":64}],"product":"premium","type":"user","uri":"spotify:user:xh3k15zazrk4e1q9ohcfs13oj"} Oct 24 19:05:53 volumio volumio[803]: info: Spotify Successfully logged in Oct 24 19:05:53 volumio volumio[803]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 24 19:05:53 volumio volumio[803]: info: [1729811153217] CoreMusicLibrary::Adding element Spotify Oct 24 19:05:53 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 19:05:53 volumio volumio[803]: Cannot find translation for source Spotify Oct 24 19:05:53 volumio go-librespot[2383]: time="2024-10-24T19:05:53-04:00" level=debug msg="completed keyexchange" Oct 24 19:05:53 volumio go-librespot[2383]: time="2024-10-24T19:05:53-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed solving challenge: failed login: BadCredentials" Oct 24 19:05:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 24 19:05:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 19:05:54 volumio volumio[803]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 24 19:05:55 volumio volumio[803]: info: go-librespot daemon successfully initialized Oct 24 19:05:56 volumio volumio[803]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Oct 24 19:05:56 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Oct 24 19:05:56 volumio volumio[803]: info: Creating Spotify config file Oct 24 19:05:56 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 24 19:05:56 volumio volumio[803]: info: Spotify config file written Oct 24 19:05:56 volumio sudo[2393]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 24 19:05:56 volumio sudo[2393]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:05:56 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 24 19:05:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Oct 24 19:05:56 volumio systemd[1]: Stopped go-librespot Daemon. Oct 24 19:05:56 volumio systemd[1]: Started go-librespot Daemon. Oct 24 19:05:56 volumio go-librespot[2395]: Librespot-go daemon starting... Oct 24 19:05:56 volumio systemd[1]: Stopping go-librespot Daemon... Oct 24 19:05:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 24 19:05:56 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 24 19:05:56 volumio systemd[1]: Stopped go-librespot Daemon. Oct 24 19:05:56 volumio systemd[1]: Started go-librespot Daemon. Oct 24 19:05:56 volumio sudo[2393]: pam_unix(sudo:session): session closed for user root Oct 24 19:05:56 volumio go-librespot[2397]: Librespot-go daemon starting... Oct 24 19:05:56 volumio go-librespot[2397]: time="2024-10-24T19:05:56-04:00" level=info msg="generated new device id: 288e93d9ca99a1f1e3fc33cd067bf306ba7568c2" Oct 24 19:05:56 volumio go-librespot[2397]: time="2024-10-24T19:05:56-04:00" level=debug msg="stored credentials found for xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:56 volumio go-librespot[2397]: time="2024-10-24T19:05:56-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 24 19:05:56 volumio go-librespot[2397]: time="2024-10-24T19:05:56-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 24 19:05:56 volumio go-librespot[2397]: time="2024-10-24T19:05:56-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 24 19:05:56 volumio go-librespot[2397]: time="2024-10-24T19:05:56-04:00" level=debug msg="zeroconf server listening on port 39067" Oct 24 19:05:56 volumio go-librespot[2397]: time="2024-10-24T19:05:56-04:00" level=debug msg="obtained new client token: AACRIlo0eFDvWFaVQf5byTCL9E5kDa7DxvPQ5hpGdM2a9mM8PnbCkKZ8hxOr6UbnOv3DTg96IV9m+sFpi8QE/c5HbBMaLIK4O0jG6ZTtDuUZ7UeFEQ9g+NuwzEr3PqJSU/aUiapXS9n4Z38IG/LF4xt9HOx1DaNO6xQq1Lj3QG4mANH1iG+3+ky0aGFD8YjDdUFMbWa7Y3czav8ecm3hhsHhvrRoYgZkM2gHip0D0dlBA5KA8gp9+USSNtws" Oct 24 19:05:56 volumio go-librespot[2397]: time="2024-10-24T19:05:56-04:00" level=info msg="connected to ap-gue1.spotify.com:4070" Oct 24 19:05:56 volumio go-librespot[2397]: time="2024-10-24T19:05:56-04:00" level=debug msg="completed keyexchange" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="completed challenge" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="authenticated as xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="authenticated as xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="dealer connection opened" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="initializing zeroconf session, username: xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="autoplay enabled: false" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="received connection id: MDhlNjQzNWYtYzZjOS00NzlhLWIwMzktMWYwOTQ4ZTNhMzliK2RlYWxlcit0Y3A6Ly8wYWNiZmEwOC5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArN0VCM0MyNDgzOERGMDVBRTZGNzUyQzRCNTNFNDA4Q0Q5OEEwMjM5NjhBQTIxMzFERENDQzM5RDNEOUE4NDRGRQ==" Oct 24 19:05:57 volumio go-librespot[2397]: time="2024-10-24T19:05:57-04:00" level=debug msg="put connect state because NEW_DEVICE" Oct 24 19:05:58 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:05:58 volumio go-librespot[2397]: time="2024-10-24T19:05:58-04:00" level=debug msg="new websocket client" Oct 24 19:05:58 volumio volumio[803]: info: Connection to go-librespot Websocket established Oct 24 19:05:59 volumio volumio[803]: info: go-librespot daemon successfully initialized Oct 24 19:06:01 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 24 19:06:01 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 24 19:06:01 volumio volumio[803]: info: Discovery: Getting this device information Oct 24 19:06:01 volumio volumio[803]: info: CoreCommandRouter::volumioGetState Oct 24 19:06:01 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 24 19:06:01 volumio volumio[803]: info: Getting Spotify volume Oct 24 19:06:01 volumio volumio[803]: info: Spotify volume: 100 Oct 24 19:06:01 volumio volumio[803]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Oct 24 19:06:01 volumio volumio[803]: info: CoreCommandRouter::volumioGetState Oct 24 19:06:01 volumio volumio[803]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Oct 24 19:06:01 volumio volumio[803]: SPOTIFY: SPOTIFY VOLUME 100 Oct 24 19:06:01 volumio volumio[803]: SPOTIFY: VOLUMIO VOLUME 46 Oct 24 19:06:01 volumio volumio[803]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 24 19:06:01 volumio volumio[803]: info: Setting Spotify Volume from Volumio: 46 Oct 24 19:06:02 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:06:02 volumio go-librespot[2397]: time="2024-10-24T19:06:02-04:00" level=debug msg="new websocket client" Oct 24 19:06:02 volumio volumio[803]: info: Connection to go-librespot Websocket established Oct 24 19:06:03 volumio volumio[803]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Oct 24 19:06:03 volumio volumio[803]: info: Sending Spotify command with payload to local API: /player/volume Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=debug msg="update volume to 30146/65535" Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=trace msg="emitting websocket event: volume" Oct 24 19:06:03 volumio volumio[803]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Oct 24 19:06:03 volumio volumio[803]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Oct 24 19:06:03 volumio volumio[803]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Oct 24 19:06:03 volumio volumio[803]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=debug msg="handling transfer player command from 7c2590f96fd722c80df21e74ce8f99d2612fc4b2" Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=debug msg="resolved context of track" uri="spotify:album:1W9cr6LNkNTfX5YKBOGFMu" Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=trace msg="fetched new page 0 with 28 items (list: 28)" uri="spotify:album:1W9cr6LNkNTfX5YKBOGFMu" Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=warning msg="failed seeking to track in context spotify:album:1W9cr6LNkNTfX5YKBOGFMu" error="could not find track" Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=debug msg="loading track (paused: true, position: 81949ms)" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=trace msg="emitting websocket event: will_play" Oct 24 19:06:03 volumio volumio[803]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6D9LXRMhyLUPIhveoDONSS","play_origin":"playlist"}} Oct 24 19:06:03 volumio volumio[803]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6D9LXRMhyLUPIhveoDONSS","play_origin":"playlist"}} Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=debug msg="selected format OGG_VORBIS_320 (64238db92eccf20d0f5e778893b16f4d51fc30ea)" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:03 volumio go-librespot[2397]: time="2024-10-24T19:06:03-04:00" level=debug msg="requested aes key for file 64238db92eccf20d0f5e778893b16f4d51fc30ea, gid: 6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1708" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1308" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="fetched first chunk of 27, total size is 13858520 bytes" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="fetched chunk 1/26, size: 524288" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="fetched chunk 2/26, size: 524288" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="fetched chunk 3/26, size: 524288" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="fetched chunk 7/26, size: 524288" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=trace msg="seek to 81949ms (diff: 180ms, samples: 3613950, bytes: 3935480)" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="fetched chunk 8/26, size: 524288" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="created new output device" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="fetched chunk 10/26, size: 524288" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=info msg="loaded track \"Us Raah Per\" (paused: true, position: 81949ms, duration: 262986ms, prefetched: false)" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="fetched chunk 9/26, size: 524288" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=trace msg="emitting websocket event: metadata" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=trace msg="emitting websocket event: active" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="sending successful reply for dealer request" Oct 24 19:06:04 volumio volumio[803]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6D9LXRMhyLUPIhveoDONSS","name":"Us Raah Per","artist_names":["Junaid Jamshed"],"album_name":"Us Raah Per","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b099679fcc0dc74dd766f911","position":81949,"duration":262986,"release_date":"year:1999","track_number":2,"disc_number":1}} Oct 24 19:06:04 volumio volumio[803]: SPOTIFY: received: {"type":"active","data":null} Oct 24 19:06:04 volumio volumio[803]: info: Aligning Spotify Volume to Volumio Volume Oct 24 19:06:04 volumio volumio[803]: info: CoreCommandRouter::volumioGetState Oct 24 19:06:04 volumio volumio[803]: info: Setting Spotify Volume from Volumio: 46 Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 24 19:06:04 volumio volumio[803]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6D9LXRMhyLUPIhveoDONSS","name":"Us Raah Per","artist_names":["Junaid Jamshed"],"album_name":"Us Raah Per","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b099679fcc0dc74dd766f911","position":81949,"duration":262986,"release_date":"year:1999","track_number":2,"disc_number":1}} Oct 24 19:06:04 volumio volumio[803]: SPOTIFY: received: {"type":"active","data":null} Oct 24 19:06:04 volumio volumio[803]: info: Aligning Spotify Volume to Volumio Volume Oct 24 19:06:04 volumio volumio[803]: info: CoreCommandRouter::volumioGetState Oct 24 19:06:04 volumio volumio[803]: info: Setting Spotify Volume from Volumio: 46 Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 24 19:06:04 volumio go-librespot[2397]: time="2024-10-24T19:06:04-04:00" level=trace msg="emitting websocket event: paused" Oct 24 19:06:04 volumio volumio[803]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6D9LXRMhyLUPIhveoDONSS","play_origin":"playlist"}} Oct 24 19:06:04 volumio volumio[803]: SPOTIFY: PUSH STATE SPOTIFY Oct 24 19:06:04 volumio volumio[803]: SPOTIFY: {"status":"pause","service":"spop","title":"Us Raah Per","artist":"Junaid Jamshed","album":"Us Raah Per","albumart":"https://i.scdn.co/image/ab67616d00001e02b099679fcc0dc74dd766f911","uri":"spotify:track:6D9LXRMhyLUPIhveoDONSS","trackType":"spotify","seek":81949,"duration":262,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 24 19:06:04 volumio volumio[803]: info: CoreCommandRouter::servicePushState Oct 24 19:06:04 volumio volumio[803]: info: CoreStateMachine::pushState Oct 24 19:06:04 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 24 19:06:04 volumio volumio[803]: info: CoreCommandRouter::volumioPushState Oct 24 19:06:04 volumio volumio[803]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6D9LXRMhyLUPIhveoDONSS","play_origin":"playlist"}} Oct 24 19:06:04 volumio volumio[803]: SPOTIFY: PUSH STATE SPOTIFY Oct 24 19:06:04 volumio volumio[803]: SPOTIFY: {"status":"pause","service":"spop","title":"Us Raah Per","artist":"Junaid Jamshed","album":"Us Raah Per","albumart":"https://i.scdn.co/image/ab67616d00001e02b099679fcc0dc74dd766f911","uri":"spotify:track:6D9LXRMhyLUPIhveoDONSS","trackType":"spotify","seek":81949,"duration":262,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 24 19:06:04 volumio volumio[803]: info: CoreCommandRouter::servicePushState Oct 24 19:06:04 volumio volumio[803]: info: CoreStateMachine::pushState Oct 24 19:06:04 volumio volumio[803]: info: CoreCommandRouter::volumioPushState Oct 24 19:06:04 volumio volumio[803]: info: PeppySpectrum ---peppyspectrum status pause Oct 24 19:06:04 volumio volumio[803]: info: PeppySpectrum ---peppyspectrum status pause Oct 24 19:06:04 volumio sudo[2409]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Oct 24 19:06:04 volumio sudo[2409]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:06:04 volumio volumio[803]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Oct 24 19:06:04 volumio volumio[803]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Oct 24 19:06:04 volumio sudo[2412]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Oct 24 19:06:04 volumio sudo[2409]: pam_unix(sudo:session): session closed for user root Oct 24 19:06:04 volumio sudo[2412]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:06:04 volumio volumio[803]: info: peppyspectrum Daemon Stop Oct 24 19:06:04 volumio sudo[2412]: pam_unix(sudo:session): session closed for user root Oct 24 19:06:04 volumio volumio[803]: info: peppyspectrum Daemon Stop Oct 24 19:06:05 volumio volumio[803]: info: Getting Spotify volume Oct 24 19:06:05 volumio volumio[803]: info: Spotify volume: 46 Oct 24 19:06:05 volumio volumio[803]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Oct 24 19:06:05 volumio volumio[803]: info: CoreCommandRouter::volumioGetState Oct 24 19:06:05 volumio volumio[803]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Oct 24 19:06:06 volumio volumio[803]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Oct 24 19:06:06 volumio volumio[803]: info: Sending Spotify command with payload to local API: /player/volume Oct 24 19:06:09 volumio go-librespot[2397]: time="2024-10-24T19:06:09-04:00" level=debug msg="handling resume player command from 7c2590f96fd722c80df21e74ce8f99d2612fc4b2" Oct 24 19:06:09 volumio go-librespot[2397]: time="2024-10-24T19:06:09-04:00" level=trace msg="seek to 81949ms (diff: 180ms, samples: 3613950, bytes: 3935480)" uri="spotify:track:6D9LXRMhyLUPIhveoDONSS" Oct 24 19:06:09 volumio go-librespot[2397]: time="2024-10-24T19:06:09-04:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Oct 24 19:06:09 volumio go-librespot[2397]: time="2024-10-24T19:06:09-04:00" level=debug msg="resume track at 81769ms" Oct 24 19:06:09 volumio go-librespot[2397]: go-librespot: pcm_meter.c:1216: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Oct 24 19:06:09 volumio go-librespot[2397]: Aborted Oct 24 19:06:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Oct 24 19:06:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 24 19:06:09 volumio volumio[803]: info: Connection to go-librespot Websocket closed Oct 24 19:06:09 volumio volumio[803]: info: Connection to go-librespot Websocket closed Oct 24 19:06:12 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:06:12 volumio volumio[803]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 24 19:06:12 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 24 19:06:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Oct 24 19:06:12 volumio systemd[1]: Stopped go-librespot Daemon. Oct 24 19:06:12 volumio systemd[1]: Started go-librespot Daemon. Oct 24 19:06:12 volumio go-librespot[2456]: Librespot-go daemon starting... Oct 24 19:06:12 volumio go-librespot[2456]: time="2024-10-24T19:06:12-04:00" level=info msg="generated new device id: bc640b18a4e852ed30a0bff0aa8039360d005a23" Oct 24 19:06:12 volumio go-librespot[2456]: time="2024-10-24T19:06:12-04:00" level=debug msg="stored credentials found for xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:06:12 volumio go-librespot[2456]: time="2024-10-24T19:06:12-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Oct 24 19:06:12 volumio go-librespot[2456]: time="2024-10-24T19:06:12-04:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 24 19:06:12 volumio go-librespot[2456]: time="2024-10-24T19:06:12-04:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 24 19:06:12 volumio go-librespot[2456]: time="2024-10-24T19:06:12-04:00" level=debug msg="zeroconf server listening on port 37729" Oct 24 19:06:12 volumio go-librespot[2456]: time="2024-10-24T19:06:12-04:00" level=debug msg="obtained new client token: AADKZa6toDNiy17mU5zIVI33O7jTA7BP6Tc9pJBhA7obYi+CmX2qdBFPvy/CWHx23e+gI15Fahj9Cqua/xxDpP/9ze47VWtV+SFVtSxfhfEEyZLkDbhVii4YHDFAZhMKXZ/m6/3Yt2MmR/Kmm1AiO+BKWiTzdYpr3KUZq/wAtj4AQvU7kPZjEFCuQZRNrS7OQz+NTgHB/Z5W4fKyX2kQAdo0wWMZ4z/aS3P5Hof9tfjO8wwm0MYwpIBElCI7" Oct 24 19:06:12 volumio go-librespot[2456]: time="2024-10-24T19:06:12-04:00" level=info msg="connected to ap-gue1.spotify.com:4070" Oct 24 19:06:12 volumio go-librespot[2456]: time="2024-10-24T19:06:12-04:00" level=debug msg="completed keyexchange" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="completed challenge" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="authenticated as xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="authenticated as xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="dealer connection opened" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="initializing zeroconf session, username: xh3k15zazrk4e1q9ohcfs13oj" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 495" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="autoplay enabled: false" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="received connection id: NjBiZTRjOGUtMWJjMC00MWQwLWIwZmMtZWJhN2U4YmExZjRmK2RlYWxlcit0Y3A6Ly8wYWNiZmEzNS5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArNzQyNTkxRDJFMkVCNUE0NzkxQjZBNDI3MUQwODA5NTY1RUEyODIxOUUwRTVEQkUzREIwM0FCQjk5MjlEQzQ2MQ==" Oct 24 19:06:13 volumio go-librespot[2456]: time="2024-10-24T19:06:13-04:00" level=debug msg="put connect state because NEW_DEVICE" Oct 24 19:06:15 volumio volumio[803]: info: Initializing connection to go-librespot Websocket Oct 24 19:06:15 volumio go-librespot[2456]: time="2024-10-24T19:06:15-04:00" level=debug msg="new websocket client" Oct 24 19:06:15 volumio volumio[803]: info: Connection to go-librespot Websocket established Oct 24 19:06:16 volumio go-librespot[2456]: time="2024-10-24T19:06:16-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 24 19:06:16 volumio go-librespot[2456]: time="2024-10-24T19:06:16-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 340" Oct 24 19:06:16 volumio go-librespot[2456]: time="2024-10-24T19:06:16-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 24 19:06:16 volumio go-librespot[2456]: time="2024-10-24T19:06:16-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1748" Oct 24 19:06:17 volumio go-librespot[2456]: time="2024-10-24T19:06:17-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 24 19:06:17 volumio go-librespot[2456]: time="2024-10-24T19:06:17-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 340" Oct 24 19:06:18 volumio volumio[803]: info: Getting Spotify volume Oct 24 19:06:18 volumio volumio[803]: info: Spotify volume: 100 Oct 24 19:06:18 volumio volumio[803]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Oct 24 19:06:18 volumio volumio[803]: info: CoreCommandRouter::volumioGetState Oct 24 19:06:18 volumio volumio[803]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Oct 24 19:06:18 volumio volumio[803]: SPOTIFY: SPOTIFY VOLUME 100 Oct 24 19:06:18 volumio volumio[803]: SPOTIFY: VOLUMIO VOLUME 46 Oct 24 19:06:18 volumio volumio[803]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 24 19:06:18 volumio volumio[803]: info: Setting Spotify Volume from Volumio: 46 Oct 24 19:06:18 volumio go-librespot[2456]: time="2024-10-24T19:06:18-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 24 19:06:18 volumio go-librespot[2456]: time="2024-10-24T19:06:18-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 341" Oct 24 19:06:19 volumio volumio[803]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Oct 24 19:06:19 volumio volumio[803]: info: Sending Spotify command with payload to local API: /player/volume Oct 24 19:06:19 volumio go-librespot[2456]: time="2024-10-24T19:06:19-04:00" level=debug msg="update volume to 30146/65535" Oct 24 19:06:19 volumio go-librespot[2456]: time="2024-10-24T19:06:19-04:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 24 19:06:19 volumio go-librespot[2456]: time="2024-10-24T19:06:19-04:00" level=trace msg="emitting websocket event: volume" Oct 24 19:06:19 volumio volumio[803]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Oct 24 19:06:19 volumio volumio[803]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Oct 24 19:06:23 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 24 19:06:23 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 24 19:06:27 volumio volumio[803]: info: Starting Uninstall of plugin music_service - spop Oct 24 19:06:27 volumio volumio[803]: info: Uninstalling plugin spop Oct 24 19:06:27 volumio go-librespot[2456]: time="2024-10-24T19:06:27-04:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Oct 24 19:06:27 volumio volumio[803]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Oct 24 19:06:27 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 24 19:06:27 volumio sudo[2468]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service Oct 24 19:06:27 volumio sudo[2468]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:06:27 volumio volumio[803]: info: Disabling plugin spop Oct 24 19:06:27 volumio systemd[1]: Stopping go-librespot Daemon... Oct 24 19:06:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 24 19:06:27 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 24 19:06:27 volumio systemd[1]: Stopped go-librespot Daemon. Oct 24 19:06:27 volumio volumio[803]: info: Checking if uninstall.sh is present Oct 24 19:06:27 volumio volumio[803]: info: Connection to go-librespot Websocket closed Oct 24 19:06:27 volumio volumio[803]: info: Executing uninstall.sh Oct 24 19:06:27 volumio sudo[2468]: pam_unix(sudo:session): session closed for user root Oct 24 19:06:27 volumio sudo[2473]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/music_service/spop/uninstall.sh Oct 24 19:06:27 volumio sudo[2473]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 24 19:06:27 volumio sudo[2473]: pam_unix(sudo:session): session closed for user root Oct 24 19:06:27 volumio volumio[803]: info: Uninstall script completed Oct 24 19:06:27 volumio volumio[803]: info: Removing plugin spop from configuration Oct 24 19:06:27 volumio volumio[803]: info: Successfully removed spop configuration files Oct 24 19:06:27 volumio volumio[803]: info: Plugin folders cleanup Oct 24 19:06:27 volumio volumio[803]: info: Scanning into folder /volumio/app/plugins/ Oct 24 19:06:27 volumio volumio[803]: info: Scanning category audio_interface Oct 24 19:06:27 volumio volumio[803]: info: Scanning category miscellanea Oct 24 19:06:27 volumio volumio[803]: info: Scanning category music_service Oct 24 19:06:27 volumio volumio[803]: info: Scanning category plugins.json Oct 24 19:06:27 volumio volumio[803]: info: Scanning category system_controller Oct 24 19:06:27 volumio volumio[803]: info: Scanning category user_interface Oct 24 19:06:27 volumio volumio[803]: info: Scanning into folder /data/plugins/ Oct 24 19:06:27 volumio volumio[803]: info: Scanning category music_service Oct 24 19:06:27 volumio volumio[803]: info: Cleaning folder for spop Oct 24 19:06:28 volumio volumio[803]: info: Scanning category system_controller Oct 24 19:06:28 volumio volumio[803]: info: Scanning category user_interface Oct 24 19:06:28 volumio volumio[803]: info: Plugin folders cleanup completed Oct 24 19:06:28 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 24 19:06:28 volumio volumio[803]: info: [{"prettyName":"Backup & Restore Data","name":"backup_restore","category":"system_controller","version":"0.7.4","icon":"fa-floppy-o","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Peppy-spectrum","name":"peppyspectrum","category":"user_interface","version":"0.0.35","icon":"fa-bar-chart","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Touch Display","name":"touch_display","category":"user_interface","version":"3.5.0","icon":"fa-hand-pointer-o","isManuallyInstalled":false,"enabled":true,"active":true}] Oct 24 19:06:28 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 24 19:06:31 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 24 19:06:31 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 24 19:06:31 volumio volumio[803]: info: Discovery: Getting this device information Oct 24 19:06:31 volumio volumio[803]: info: CoreCommandRouter::volumioGetState Oct 24 19:06:31 volumio volumio[803]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 24 19:06:33 volumio volumio[803]: info: Starting Uninstall of plugin user_interface - peppyspectrum Oct 24 19:06:33 volumio volumio[803]: info: Uninstalling plugin peppyspectrum Oct 24 19:06:33 volumio volumio[803]: info: Stopping peppyspectrum service Oct 24 19:06:33 volumio volumio[803]: info: CoreStateMachine::stop Oct 24 19:06:33 volumio volumio[803]: info: CoreStateMachine::serviceStop Oct 24 19:06:33 volumio volumio[803]: info: CoreCommandRouter::serviceStop Oct 24 19:06:33 volumio volumio[803]: error: WARNING: No stop method for service spop Oct 24 19:06:33 volumio volumio[803]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 24 19:06:33 volumio volumio[803]: TypeError: Cannot read property 'then' of undefined Oct 24 19:06:33 volumio volumio[803]: at peppyspectrum.onStop (/data/plugins/user_interface/peppyspectrum/index.js:60:43) Oct 24 19:06:33 volumio volumio[803]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) Oct 24 19:06:33 volumio volumio[803]: at PluginManager.unInstallPlugin (/volumio/app/pluginmanager.js:1449:10) Oct 24 19:06:33 volumio volumio[803]: at CoreCommandRouter.unInstallPlugin (/volumio/app/index.js:1465:22) Oct 24 19:06:33 volumio volumio[803]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1246:45) Oct 24 19:06:33 volumio volumio[803]: at Socket.emit (events.js:315:20) Oct 24 19:06:33 volumio volumio[803]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Oct 24 19:06:33 volumio volumio[803]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Oct 24 19:06:33 volumio volumio[803]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 24 19:06:33 volumio sudo[2491]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-24 19:05 Oct 24 19:06:33 volumio sudo[2491]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:01:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e0a6dc7e914e3fb93cbf2123f2f73eac"