-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Mon 2024-07-15 10:13:14 CEST. -- Jul 15 10:13:09 scotch ntpd[650]: receive: Unexpected origin timestamp 0xe8b596d6.1769acbe does not match aorg 0000000000.00000000 from server@93.94.88.50 xmt 0xea3f5895.5f015b35 Jul 15 10:13:09 scotch systemd[1]: Starting Daily apt download activities... Jul 15 10:13:09 scotch volumio[923]: info: Discovery: A device disappeared from network Jul 15 10:13:09 scotch volumio[923]: info: Discovery: Device scotch disappeared from network Jul 15 10:13:09 scotch volumio[923]: info: Discovery: A device disappeared from network Jul 15 10:13:09 scotch volumio[923]: info: Discovery: adding a7b6003b-cb14-441f-b3a1-e3072f732e33 Jul 15 10:13:09 scotch volumio[923]: info: Discovery: Found device Scotch Jul 15 10:13:09 scotch volumio[923]: info: CoreCommandRouter::volumioGetState Jul 15 10:13:09 scotch volumio[923]: info: CorePlayQueue::getTrack 0 Jul 15 10:13:09 scotch volumio[923]: info: Discovery: this is already registered, a7b6003b-cb14-441f-b3a1-e3072f732e33 Jul 15 10:13:09 scotch volumio[923]: info: Discovery: Found device Scotch Jul 15 10:13:09 scotch volumio[923]: info: CoreCommandRouter::volumioGetState Jul 15 10:13:09 scotch volumio[923]: info: CorePlayQueue::getTrack 0 Jul 15 10:13:09 scotch systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 15 10:13:09 scotch systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Jul 15 10:13:09 scotch systemd[1]: Stopped go-librespot Daemon. Jul 15 10:13:09 scotch systemd[1]: Started go-librespot Daemon. Jul 15 10:13:09 scotch go-librespot[1300]: Librespot-go daemon starting... Jul 15 10:13:09 scotch go-librespot[1300]: time="2024-07-15T10:13:09+02:00" level=info msg="generated new device id: 8bfa6c48dd0b5ea3fd142d4bc0b02c05a6e6e4ef" Jul 15 10:13:10 scotch systemd[1]: apt-daily.service: Succeeded. Jul 15 10:13:10 scotch systemd[1]: Started Daily apt download activities. Jul 15 10:13:10 scotch systemd[1]: Starting Daily apt upgrade and clean activities... Jul 15 10:13:10 scotch go-librespot[1300]: time="2024-07-15T10:13:10+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 15 10:13:10 scotch go-librespot[1300]: time="2024-07-15T10:13:10+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 15 10:13:10 scotch go-librespot[1300]: time="2024-07-15T10:13:10+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 15 10:13:10 scotch go-librespot[1300]: time="2024-07-15T10:13:10+02:00" level=debug msg="zeroconf server listening on port 37851" Jul 15 10:13:10 scotch systemd[1]: apt-daily-upgrade.service: Succeeded. Jul 15 10:13:10 scotch systemd[1]: Started Daily apt upgrade and clean activities. Jul 15 10:13:11 scotch go-librespot[1300]: time="2024-07-15T10:13:11+02:00" level=debug msg="obtained new client token: AADAQ2Qp4RzkBgJD7uFuLr6eq1sikPuazAm0CdA+4XuoQWKHYcf/2bQ1sguCTwe0SiMOmEbJDh8/8IBS5PBaVLJHSNj/c/sVKItVpu3i34ReK8hPsu/cEml/21f86J5x/OZy071/3Mu6ko/B0+YuSYv1BjNUy3yX2T9iu98/RRXcHa8ZhVE9FepMpdP191noPeGRGED8CekTjsQ0V9wW4ApFE5DQ5CRvx+PGs+lu69E/vGByIaTRr/330Vnpe80=" Jul 15 10:13:11 scotch go-librespot[1300]: time="2024-07-15T10:13:11+02:00" level=debug msg="completed keyexchange" Jul 15 10:13:11 scotch volumio[923]: info: Initializing connection to go-librespot Websocket Jul 15 10:13:11 scotch go-librespot[1300]: time="2024-07-15T10:13:11+02:00" level=debug msg="new websocket client" Jul 15 10:13:11 scotch volumio[923]: info: Connection to go-librespot Websocket established Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="completed challenge" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="authenticated as 11128375303" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="authenticated as 11128375303" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="dealer connection opened" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=info msg="accepted zeroconf user 11128375303 from Pixel 6a" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="received connection id: Nzg4MWMxOTAtM2E0Yy00NTFhLWFmMjYtN2U2Zjc2ZjA3MDA4K2RlYWxlcit0Y3A6Ly9nZXc0LWRlYWxlci1hLXQzbXQuZ2V3NC5zcG90aWZ5Lm5ldDo1NzAwKzBDMzIzNEE5NEYyOTE1Njk1RTcwQjRFNERFRTczNzE0RUJDNUE2NUIzOUNFRUFCN0UwNzMwQTNGNTg5QzgyRTY=" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="handling transfer player command from 790cf8551e15b4e426e39ed1bf66c644385d263f" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=trace msg="fetched new page 0 with 159 items (list: 159)" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="loading track spotify:track:3sm6GfmHISsEjJrPExmxqz (paused: true, position: 161533ms)" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=trace msg="emitting websocket event: will_play" Jul 15 10:13:12 scotch volumio[923]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3sm6GfmHISsEjJrPExmxqz","play_origin":"playlist"}} Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:3sm6GfmHISsEjJrPExmxqz" Jul 15 10:13:12 scotch go-librespot[1300]: time="2024-07-15T10:13:12+02:00" level=debug msg="requested aes key for file b8e3c93181894f560e90e3583544c3dc9a9971b7, gid: 3sm6GfmHISsEjJrPExmxqz" Jul 15 10:13:13 scotch go-librespot[1300]: time="2024-07-15T10:13:13+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2867" Jul 15 10:13:13 scotch go-librespot[1300]: time="2024-07-15T10:13:13+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2006" Jul 15 10:13:13 scotch go-librespot[1300]: time="2024-07-15T10:13:13+02:00" level=debug msg="fetched first chunk of 21, total size is 10928656 bytes" Jul 15 10:13:13 scotch go-librespot[1300]: time="2024-07-15T10:13:13+02:00" level=debug msg="fetched chunk 2/20, size: 524288" Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=debug msg="fetched chunk 3/20, size: 524288" Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=debug msg="fetched chunk 1/20, size: 524288" Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=debug msg="fetched chunk 16/20, size: 524288" Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=debug msg="fetched chunk 15/20, size: 524288" Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=debug msg="fetched chunk 14/20, size: 524288" Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=debug msg="fetched chunk 13/20, size: 524288" Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=trace msg="seek to 161533ms (diff: 159ms, samples: 7123605, bytes: 6889060)" Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=info msg="loaded track \"Molehills\" (uri: spotify:track:3sm6GfmHISsEjJrPExmxqz, paused: true, position: 161533ms, duration: 251100ms)" Jul 15 10:13:14 scotch kernel: bcm2835-i2s fe203000.i2s: I2S SYNC error! Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=trace msg="emitting websocket event: metadata" Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=trace msg="emitting websocket event: active" Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=debug msg="sending successful reply for delaer request" Jul 15 10:13:14 scotch volumio[923]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3sm6GfmHISsEjJrPExmxqz","name":"Molehills","artist_names":["Arab Strap"],"album_name":"I'm totally fine with it 👍 don't give a fuck anymore 👍","album_cover_url":"https://i.scdn.co/image/ab67616d00001e025f2d162fb92a4885602c9e2a","position":161533,"duration":251100,"release_date":"year:2024 month:5 day:10","track_number":6,"disc_number":1}} Jul 15 10:13:14 scotch volumio[923]: SPOTIFY: received: {"type":"active","data":null} Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 15 10:13:14 scotch volumio[923]: info: Aligning Spotify Volume to Volumio Volume Jul 15 10:13:14 scotch volumio[923]: info: CoreCommandRouter::volumioGetState Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 15 10:13:14 scotch volumio[923]: info: CorePlayQueue::getTrack 0 Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 15 10:13:14 scotch go-librespot[1300]: time="2024-07-15T10:13:14+02:00" level=trace msg="emitting websocket event: paused" Jul 15 10:13:14 scotch volumio[923]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3sm6GfmHISsEjJrPExmxqz","play_origin":"playlist"}} Jul 15 10:13:14 scotch volumio[923]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 15 10:13:14 scotch volumio[923]: TypeError: Cannot read property 'service' of undefined Jul 15 10:13:14 scotch volumio[923]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Jul 15 10:13:14 scotch volumio[923]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Jul 15 10:13:14 scotch volumio[923]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Jul 15 10:13:14 scotch volumio[923]: at WebSocket.emit (events.js:315:20) Jul 15 10:13:14 scotch volumio[923]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1209:20) Jul 15 10:13:14 scotch volumio[923]: at Receiver.emit (events.js:315:20) Jul 15 10:13:14 scotch volumio[923]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:594:14) Jul 15 10:13:14 scotch volumio[923]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jul 15 10:13:14 scotch volumio[923]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jul 15 10:13:14 scotch volumio[923]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jul 15 10:13:14 scotch volumio[923]: at writeOrBuffer (internal/streams/writable.js:358:12) Jul 15 10:13:14 scotch volumio[923]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jul 15 10:13:14 scotch volumio[923]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1303:35) Jul 15 10:13:14 scotch volumio[923]: at Socket.emit (events.js:315:20) Jul 15 10:13:14 scotch volumio[923]: at addChunk (internal/streams/readable.js:309:12) Jul 15 10:13:14 scotch volumio[923]: at readableAddChunk (internal/streams/readable.js:284:9) Jul 15 10:13:14 scotch volumio[923]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 15 10:13:14 scotch sudo[1384]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-15 10:12 Jul 15 10:13:14 scotch sudo[1384]: 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="b1c3cf61c2a0027c66bab1eb0a3795f80c1f2e95" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="e3eb3ee5b16063502f3a1735e11a28cfe54a0f46" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sun 25 Jun 2023 07:20:58 PM CEST" VOLUMIO_VERSION="3.512" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="946a42b62509f37b5e7e2d86a2932a62"