-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Thu 2024-07-11 22:46:49 UTC. -- Jul 11 22:46:44 volumio ntpd[619]: receive: Unexpected origin timestamp 0xe7dab878.616a0e30 does not match aorg 0000000000.00000000 from server@162.252.172.49 xmt 0xea3adf54.dba33723 Jul 11 22:46:44 volumio ntpd[619]: receive: Unexpected origin timestamp 0xe7dab878.6163ec66 does not match aorg 0000000000.00000000 from server@129.250.35.250 xmt 0xea3adf54.db591219 Jul 11 22:46:44 volumio systemd[1]: Starting Daily apt download activities... Jul 11 22:46:44 volumio ntpd[619]: receive: Unexpected origin timestamp 0xe7dab878.616b6607 does not match aorg 0000000000.00000000 from server@69.164.213.136 xmt 0xea3adf54.db020348 Jul 11 22:46:44 volumio ntpd[619]: receive: Unexpected origin timestamp 0xe7dab878.61689d1d does not match aorg 0000000000.00000000 from server@99.119.214.210 xmt 0xea3adf54.ddd4d0e8 Jul 11 22:46:44 volumio ntpd[619]: receive: Unexpected origin timestamp 0xe7dab878.6165a8a5 does not match aorg 0000000000.00000000 from server@45.79.1.70 xmt 0xea3adf54.df771c3e Jul 11 22:46:44 volumio ntpd[619]: receive: Unexpected origin timestamp 0xe7dab878.61672c39 does not match aorg 0000000000.00000000 from server@129.146.193.200 xmt 0xea3adf54.e29178c2 Jul 11 22:46:44 volumio ntpd[619]: receive: Unexpected origin timestamp 0xe7dab878.615fbb65 does not match aorg 0000000000.00000000 from server@204.17.205.27 xmt 0xea3adf54.e1f2d733 Jul 11 22:46:45 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 11 22:46:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jul 11 22:46:45 volumio systemd[1]: Stopped go-librespot Daemon. Jul 11 22:46:45 volumio systemd[1]: Started go-librespot Daemon. Jul 11 22:46:45 volumio go-librespot[1295]: Librespot-go daemon starting... Jul 11 22:46:45 volumio go-librespot[1295]: time="2024-07-11T22:46:45Z" level=info msg="generated new device id: 49b3aea621528ea86e3e8d77ce0eb51e652b7a42" Jul 11 22:46:45 volumio go-librespot[1295]: time="2024-07-11T22:46:45Z" level=debug msg="stored credentials found for 31ziiaa4ktzdw7qarz25tiesao5q" Jul 11 22:46:45 volumio go-librespot[1295]: time="2024-07-11T22:46:45Z" level=debug msg="obtained new client token: AADWhaCplbEfOm2w5fTt7N+PeZueHX7t/WoVbtCHD3TYNg+w2qsAfOWQZLE3/21nokrPH0aw+5PIWDq53OKl4dEbAoBpZGUq4JU5CNPtsNoir6B7ilLcV+BavmsfNj4rMaKugEyDb94jAqlusdIu7IWnCDtKSpa0f03GvbhbSEdUrUo2If5A5CzuD9aPdRo2qLVDSysAB6T471VVh93YEJrzOGZUfimGOE98MTa3z/adcL4jM3M7XnZKtJExy88=" Jul 11 22:46:45 volumio go-librespot[1295]: time="2024-07-11T22:46:45Z" 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]" Jul 11 22:46:45 volumio go-librespot[1295]: time="2024-07-11T22:46:45Z" level=debug msg="completed keyexchange" Jul 11 22:46:46 volumio go-librespot[1295]: time="2024-07-11T22:46:46Z" level=debug msg="completed challenge" Jul 11 22:46:46 volumio go-librespot[1295]: time="2024-07-11T22:46:46Z" level=debug msg="authenticated as 31ziiaa4ktzdw7qarz25tiesao5q" Jul 11 22:46:46 volumio go-librespot[1295]: time="2024-07-11T22:46:46Z" level=debug msg="authenticated as 31ziiaa4ktzdw7qarz25tiesao5q" Jul 11 22:46:46 volumio go-librespot[1295]: time="2024-07-11T22:46:46Z" 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]" Jul 11 22:46:46 volumio go-librespot[1295]: time="2024-07-11T22:46:46Z" 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]" Jul 11 22:46:46 volumio systemd[1]: apt-daily.service: Succeeded. Jul 11 22:46:46 volumio go-librespot[1295]: time="2024-07-11T22:46:46Z" level=debug msg="dealer connection opened" Jul 11 22:46:46 volumio go-librespot[1295]: time="2024-07-11T22:46:46Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 11 22:46:46 volumio go-librespot[1295]: time="2024-07-11T22:46:46Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 11 22:46:46 volumio systemd[1]: Started Daily apt download activities. Jul 11 22:46:46 volumio go-librespot[1295]: time="2024-07-11T22:46:46Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 11 22:46:46 volumio go-librespot[1295]: time="2024-07-11T22:46:46Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 11 22:46:46 volumio go-librespot[1295]: time="2024-07-11T22:46:46Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" Jul 11 22:46:46 volumio go-librespot[1295]: time="2024-07-11T22:46:46Z" level=debug msg="received connection id: M2FjOTAyODAtNTVjNS00MzdiLTk5ZjUtZTAwOGZmZDYwNTAxK2RlYWxlcit0Y3A6Ly9ndWUxLWRlYWxlci1hLWhoODguZ3VlMS5zcG90aWZ5Lm5ldDo1NzAwK0ZBNzcxOTNCM0MzNzU4NTlENjU4QkUxRjZENzQyNkM0QjhGNDREOTMzQ0VCMUE5NzdFMTBCQzM2NTM1MEJBQjI=" Jul 11 22:46:46 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Jul 11 22:46:47 volumio go-librespot[1295]: time="2024-07-11T22:46:47Z" level=debug msg="new websocket client" Jul 11 22:46:47 volumio go-librespot[1295]: time="2024-07-11T22:46:47Z" level=debug msg="put connect state because NEW_DEVICE" Jul 11 22:46:48 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Jul 11 22:46:48 volumio systemd[1]: Started Daily apt upgrade and clean activities. Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=debug msg="handling transfer player command from cc1494728a4a01820ecf698ad283a43dde6e72e7" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=trace msg="fetched new page 0 with 50 items (list: 50)" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=debug msg="shuffled context with seed 2529936742671142212 (len: 50, keep: 48)" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=debug msg="loading track spotify:track:3OBzTMqncLaFNjLQQfXOpe (paused: true, position: 6895ms)" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=trace msg="emitting websocket event: will_play" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:3OBzTMqncLaFNjLQQfXOpe" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=debug msg="requested aes key for file b952e7eb5c3834d4ffe0fa94b3c33fc8b41389cc, gid: 3OBzTMqncLaFNjLQQfXOpe" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1627" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1388" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=debug msg="fetched first chunk of 24, total size is 12133928 bytes" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=trace msg="seek to 6895ms (diff: 105ms, samples: 304069, bytes: 293750)" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=info msg="loaded track \"Guitars and Tiki Bars\" (uri: spotify:track:3OBzTMqncLaFNjLQQfXOpe, paused: true, position: 6895ms, duration: 276400ms)" Jul 11 22:46:48 volumio go-librespot[1295]: time="2024-07-11T22:46:48Z" level=debug msg="fetched chunk 1/23, size: 524288" Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=trace msg="emitting websocket event: metadata" Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=trace msg="emitting websocket event: active" Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=debug msg="sending successful reply for delaer request" Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=debug msg="fetched chunk 2/23, size: 524288" Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=debug msg="fetched chunk 3/23, size: 524288" Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=trace msg="emitting websocket event: paused" Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=debug msg="handling resume player command from cc1494728a4a01820ecf698ad283a43dde6e72e7" Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=trace msg="seek to 6895ms (diff: 105ms, samples: 304069, bytes: 293750)" Jul 11 22:46:49 volumio go-librespot[1295]: time="2024-07-11T22:46:49Z" level=debug msg="resume track at 6419ms" 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="c87c6e2b1ae33dc5801986cbcbe970898b92e7b4" VOLUMIO_FE_VERSION="c433755e569617abac52264d17ad61be303ef463" VOLUMIO_FE3_VERSION="2419ddd8e895c5bdc456962163c9dc7c0f187aa7" VOLUMIO_BE_VERSION="b949d6001d7e656b4668f31c119d2247cdf45158" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 30 Mar 2023 05:45:03 PM CEST" VOLUMIO_VERSION="3.449" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="6428d8e2c06e98483f5c5d77e8f01989"