-- Logs begin at Thu 2019-02-14 18:11:59 CST, end at Sat 2024-10-05 08:56:22 CST. -- Oct 05 08:56:13 volumio ntpd[615]: receive: Unexpected origin timestamp 0xe9421ed8.9d4395ed does not match aorg 0000000000.00000000 from server@122.117.253.246 xmt 0xeaab0d2d.2832057a Oct 05 08:56:13 volumio systemd[1]: Starting Daily apt download activities... Oct 05 08:56:15 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 05 08:56:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Oct 05 08:56:15 volumio systemd[1]: Stopped go-librespot Daemon. Oct 05 08:56:15 volumio systemd[1]: Started go-librespot Daemon. Oct 05 08:56:15 volumio go-librespot[1305]: Librespot-go daemon starting... Oct 05 08:56:15 volumio go-librespot[1305]: time="2024-10-05T08:56:15+08:00" level=info msg="generated new device id: fb1b05a8e09c03ffc255c0e6f5ca27398204f344" Oct 05 08:56:15 volumio go-librespot[1305]: time="2024-10-05T08:56:15+08:00" level=debug msg="new websocket client" Oct 05 08:56:15 volumio go-librespot[1305]: time="2024-10-05T08:56:15+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 05 08:56:15 volumio go-librespot[1305]: time="2024-10-05T08:56:15+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 05 08:56:15 volumio go-librespot[1305]: time="2024-10-05T08:56:15+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 05 08:56:15 volumio go-librespot[1305]: time="2024-10-05T08:56:15+08:00" level=debug msg="zeroconf server listening on port 45469" Oct 05 08:56:16 volumio systemd[1]: apt-daily.service: Succeeded. Oct 05 08:56:16 volumio systemd[1]: Started Daily apt download activities. Oct 05 08:56:16 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Oct 05 08:56:17 volumio volumio[1103]: ..............................................................................................................................................................................................................................................................................................................................................................++++ Oct 05 08:56:18 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Oct 05 08:56:18 volumio systemd[1]: Started Daily apt upgrade and clean activities. Oct 05 08:56:18 volumio nmbd[602]: [2024/10/05 08:56:18.129167, 0] ../source3/libsmb/nmblib.c:917(send_udp) Oct 05 08:56:18 volumio nmbd[602]: Packet send failed to 169.254.255.255(138) ERRNO=Network is unreachable Oct 05 08:56:18 volumio nmbd[602]: [2024/10/05 08:56:18.129644, 0] ../source3/libsmb/nmblib.c:917(send_udp) Oct 05 08:56:18 volumio nmbd[602]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Oct 05 08:56:18 volumio nmbd[602]: [2024/10/05 08:56:18.129772, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Oct 05 08:56:18 volumio nmbd[602]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Oct 05 08:56:18 volumio nmbd[602]: [2024/10/05 08:56:18.129894, 0] ../source3/libsmb/nmblib.c:917(send_udp) Oct 05 08:56:18 volumio nmbd[602]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Oct 05 08:56:18 volumio nmbd[602]: [2024/10/05 08:56:18.129984, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Oct 05 08:56:18 volumio nmbd[602]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Oct 05 08:56:18 volumio nmbd[602]: [2024/10/05 08:56:18.130088, 0] ../source3/libsmb/nmblib.c:917(send_udp) Oct 05 08:56:18 volumio nmbd[602]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Oct 05 08:56:18 volumio nmbd[602]: [2024/10/05 08:56:18.130196, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Oct 05 08:56:18 volumio nmbd[602]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Oct 05 08:56:18 volumio nmbd[602]: [2024/10/05 08:56:18.130289, 0] ../source3/libsmb/nmblib.c:917(send_udp) Oct 05 08:56:18 volumio nmbd[602]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Oct 05 08:56:18 volumio nmbd[602]: [2024/10/05 08:56:18.130386, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Oct 05 08:56:18 volumio nmbd[602]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Oct 05 08:56:18 volumio nmbd[602]: [2024/10/05 08:56:18.130509, 0] ../source3/libsmb/nmblib.c:917(send_udp) Oct 05 08:56:18 volumio nmbd[602]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Oct 05 08:56:18 volumio nmbd[602]: [2024/10/05 08:56:18.130591, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Oct 05 08:56:18 volumio nmbd[602]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Oct 05 08:56:18 volumio go-librespot[1305]: time="2024-10-05T08:56:18+08:00" level=debug msg="obtained new client token: AADWZSL1st2IwdK4D6QZzhkK5OdrKbpJ584RN+KkIpeeHnC+UmNe/N2w1A2z/YUHl5DTmux689BeqvlKHkR+4RQAlPdDE5iHKNGkImUH/t/Kt7LEvFhQdR1+BlNIW7iaSEV5oVEggKwuxFCyXki6lwiJIP6EJdgraPe40REOf1YgEA27w7N06TwvrfeSjvk/BiKJxCMDGzWPvUoRx2FBqvAnqY9ZaNnNQOds5kXFrSAAp6gdNNuMpJ2hu6Pd0mgH" Oct 05 08:56:18 volumio go-librespot[1305]: time="2024-10-05T08:56:18+08:00" level=debug msg="completed keyexchange" Oct 05 08:56:19 volumio volumio[1103]: ...........++++ Oct 05 08:56:19 volumio volumio[1103]: e is 65537 (0x010001) Oct 05 08:56:19 volumio volumio[1103]: writing RSA key Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="completed challenge" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="authenticated as 21o6rbem2o2hrcmc7akx5vqlq" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="authenticated as 21o6rbem2o2hrcmc7akx5vqlq" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="dealer connection opened" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=info msg="accepted zeroconf user 21o6rbem2o2hrcmc7akx5vqlq from 美訓 的 Z Flip5" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="received connection id: Y2M3NWI2NjAtZjE4Mi00NzRmLTkxN2QtNmIzOWUwNGIzNTI4K2RlYWxlcit0Y3A6Ly8wYWM5NDhlMy5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArMEM1RkExNjM1RUU3NTI4QzU5RUNBQ0E2NERFNTM5MDZDNTlCMDQ5QUNFMjI5RDM0NjIwMTMzNTUyMEE3MzY4MQ==" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="put connect state because NEW_DEVICE" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="handling transfer player command from b47a1a7a9227c224019d6fed9cc685ed10d7474d" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="loading track spotify:track:7bQ0virCxnDvvoRUjKLheW (paused: true, position: 171236ms)" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=trace msg="emitting websocket event: will_play" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:7bQ0virCxnDvvoRUjKLheW" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="requested aes key for file 08fbb7613c637f0384cf7b11ade402753f785a81, gid: 7bQ0virCxnDvvoRUjKLheW" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 05 08:56:19 volumio go-librespot[1305]: time="2024-10-05T08:56:19+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2051" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="fetched first chunk of 22, total size is 11362528 bytes" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="fetched chunk 3/21, size: 524288" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1487" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="fetched chunk 1/21, size: 524288" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="fetched chunk 16/21, size: 524288" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="fetched chunk 13/21, size: 524288" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=trace msg="seek to 171236ms (diff: 142ms, samples: 7551507, bytes: 7101700)" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="fetched chunk 14/21, size: 524288" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="fetched chunk 2/21, size: 524288" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="fetched chunk 15/21, size: 524288" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=info msg="loaded track \"用心良苦\" (uri: spotify:track:7bQ0virCxnDvvoRUjKLheW, paused: true, position: 171236ms, duration: 276093ms)" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=trace msg="emitting websocket event: metadata" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=trace msg="emitting websocket event: active" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="sending successful reply for delaer request" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 08:56:20 volumio go-librespot[1305]: time="2024-10-05T08:56:20+08:00" level=trace msg="emitting websocket event: paused" Oct 05 08:56:22 volumio systemd-journald[197]: Suppressed 9040 messages from volumio.service Oct 05 08:56:22 volumio sudo[1433]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-05 08:55 Oct 05 08:56:22 volumio sudo[1433]: 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="893d2e91c55a7857b58762e70c2f65b9d163562b" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="30b77d58bf3c2745acc494ddafed946392a79905" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 20 Oct 2023 03:38:28 PM CEST" VOLUMIO_VERSION="3.569" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4163d3756b55b3bf7c480d7285f68954"