-- Logs begin at Thu 2024-03-07 15:48:41 CET, end at Sun 2025-01-19 12:05:19 CET. -- Jan 19 12:05:14 sejour ntpd[648]: receive: Unexpected origin timestamp 0xe994529b.b45a545e does not match aorg 0000000000.00000000 from server@51.75.31.74 xmt 0xeb375aea.ade3f6d3 Jan 19 12:05:14 sejour ntpd[648]: receive: Unexpected origin timestamp 0xe994529b.b45caa6d does not match aorg 0000000000.00000000 from server@82.64.247.11 xmt 0xeb375aea.acf48a5f Jan 19 12:05:14 sejour volumio[707]: info: Initializing connection to go-librespot Websocket Jan 19 12:05:14 sejour ntpd[648]: receive: Unexpected origin timestamp 0xe994529b.b45e98d7 does not match aorg 0000000000.00000000 from server@185.123.84.51 xmt 0xeb375aea.ad6fbad7 Jan 19 12:05:14 sejour volumio[707]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 19 12:05:14 sejour ntpd[648]: receive: Unexpected origin timestamp 0xe994529b.b45d9628 does not match aorg 0000000000.00000000 from server@45.132.96.81 xmt 0xeb375aea.ae249aca Jan 19 12:05:14 sejour ntpd[648]: receive: Unexpected origin timestamp 0xe994529b.b456da83 does not match aorg 0000000000.00000000 from server@51.195.104.188 xmt 0xeb375aea.ae577a1a Jan 19 12:05:14 sejour systemd[1]: Starting Daily apt download activities... Jan 19 12:05:14 sejour volumio[707]: info: Discovery: A device disappeared from network Jan 19 12:05:14 sejour volumio[707]: info: Discovery: Device sejour disappeared from network Jan 19 12:05:14 sejour systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 19 12:05:14 sejour systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Jan 19 12:05:14 sejour systemd[1]: Stopped go-librespot Daemon. Jan 19 12:05:14 sejour systemd[1]: Started go-librespot Daemon. Jan 19 12:05:15 sejour go-librespot[1251]: Librespot-go daemon starting... Jan 19 12:05:15 sejour volumio[707]: info: Discovery: adding 3867cb74-054b-4492-9e49-99a20d421ba5 Jan 19 12:05:15 sejour volumio[707]: info: Discovery: Found device Sejour Jan 19 12:05:15 sejour volumio[707]: info: CoreCommandRouter::volumioGetState Jan 19 12:05:15 sejour go-librespot[1251]: time="2025-01-19T12:05:15+01:00" level=info msg="generated new device id: aeab5f435cb7f219e9de036dc8b7d126bad865f3" Jan 19 12:05:15 sejour volumio[707]: info: CorePlayQueue::getTrack 0 Jan 19 12:05:15 sejour go-librespot[1251]: time="2025-01-19T12:05:15+01:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Jan 19 12:05:15 sejour go-librespot[1251]: time="2025-01-19T12:05:15+01:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 19 12:05:15 sejour go-librespot[1251]: time="2025-01-19T12:05:15+01:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 19 12:05:15 sejour go-librespot[1251]: time="2025-01-19T12:05:15+01:00" level=debug msg="zeroconf server listening on port 33145" Jan 19 12:05:16 sejour systemd[1]: apt-daily.service: Succeeded. Jan 19 12:05:16 sejour systemd[1]: Started Daily apt download activities. Jan 19 12:05:16 sejour systemd[1]: Starting Daily apt upgrade and clean activities... Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="obtained new client token: AADp/qKsTlbNQzYKUKcaTp1m6onpko91ywCLXYZyH5Ps3aQ8N6pQlnM56J2ZjpMhfSRUsyqnRGeiTGHEtJebg3US7POxry9XCdcaWclaxOkAjzAhHSYpKK62vhJKdWiBAxkEoYcUVfMM2NM3hltZ2ecKe4LA8NLHfhgLELGVRTkgpPoRtJaJFAux7XSp8GQHMLKkkP8rsMAvoAWOR1GN7Pp6HkA0RDrg+57Z1DhVuBK5fbM3UpYPmzb1jV0=" Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="completed keyexchange" Jan 19 12:05:17 sejour systemd[1]: apt-daily-upgrade.service: Succeeded. Jan 19 12:05:17 sejour systemd[1]: Started Daily apt upgrade and clean activities. Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="completed challenge" Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="authenticated as marlenedx" Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="authenticated as marlenedx" Jan 19 12:05:17 sejour volumio[707]: info: Initializing connection to go-librespot Websocket Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="new websocket client" Jan 19 12:05:17 sejour volumio[707]: info: Connection to go-librespot Websocket established Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="dealer connection opened" Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=info msg="accepted zeroconf user marlenedx from iPhone" Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="received connection id: MmU2MTIzMjAtZWViOC00NjdlLTg4YmUtOTZhNWI1MTlmOWQzK2RlYWxlcit0Y3A6Ly8wYWNhNDI2MS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMTkxODcwMjg5RTIyMUU1NkI5QUNCMzgzNTY2MjM1NTNCRjgwOTJCMDU4QUI1NEU1QjU0M0NBMjM2MTE0RkM5Nw==" Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="put connect state because NEW_DEVICE" Jan 19 12:05:17 sejour go-librespot[1251]: time="2025-01-19T12:05:17+01:00" level=debug msg="handling transfer player command from 769a6dac3d41c66c3c42f708848889333c530206" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="loading track spotify:track:5fDDId1Ke6mCMSQCFBSKPD (paused: false, position: 54711ms)" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=trace msg="emitting websocket event: will_play" Jan 19 12:05:18 sejour volumio[707]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5fDDId1Ke6mCMSQCFBSKPD","play_origin":"playlist/ondemand"}} Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1279" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:5fDDId1Ke6mCMSQCFBSKPD" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="requested aes key for file 10353241a28fb907733c2e404e4026282af39c67, gid: 5fDDId1Ke6mCMSQCFBSKPD" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="fetched first chunk of 15, total size is 7682632 bytes" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="fetched chunk 2/14, size: 524288" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="fetched chunk 3/14, size: 524288" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="fetched chunk 1/14, size: 524288" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="fetched chunk 5/14, size: 524288" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="fetched chunk 6/14, size: 524288" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="fetched chunk 4/14, size: 524288" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="fetched chunk 7/14, size: 524288" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=trace msg="seek to 54711ms (diff: 100ms, samples: 2412755, bytes: 2209551)" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=info msg="loaded track \"Reality Cuts Me Like A Knife\" (uri: spotify:track:5fDDId1Ke6mCMSQCFBSKPD, paused: false, position: 54711ms, duration: 192559ms)" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=trace msg="emitting websocket event: metadata" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=trace msg="emitting websocket event: active" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="sending successful reply for delaer request" Jan 19 12:05:18 sejour volumio[707]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5fDDId1Ke6mCMSQCFBSKPD","name":"Reality Cuts Me Like A Knife","artist_names":["Faada Freddy"],"album_name":"Gospel Journey","album_cover_url":"https://i.scdn.co/image/ab67616d00001e022234762c558e0859fb1b322c","position":54711,"duration":192559,"release_date":"year:2015 month:3 day:16","track_number":3,"disc_number":1}} Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 19 12:05:18 sejour volumio[707]: SPOTIFY: received: {"type":"active","data":null} Jan 19 12:05:18 sejour volumio[707]: info: Aligning Spotify Volume to Volumio Volume Jan 19 12:05:18 sejour volumio[707]: info: CoreCommandRouter::volumioGetState Jan 19 12:05:18 sejour volumio[707]: info: CorePlayQueue::getTrack 0 Jan 19 12:05:18 sejour volumio[707]: info: Setting Spotify Volume from Volumio: 88 Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 19 12:05:18 sejour go-librespot[1251]: time="2025-01-19T12:05:18+01:00" level=trace msg="emitting websocket event: playing" Jan 19 12:05:18 sejour volumio[707]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5fDDId1Ke6mCMSQCFBSKPD","play_origin":"playlist/ondemand"}} Jan 19 12:05:18 sejour volumio[707]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 19 12:05:18 sejour volumio[707]: TypeError: Cannot read property 'service' of undefined Jan 19 12:05:18 sejour volumio[707]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Jan 19 12:05:18 sejour volumio[707]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Jan 19 12:05:18 sejour volumio[707]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Jan 19 12:05:18 sejour volumio[707]: at WebSocket.emit (events.js:315:20) Jan 19 12:05:18 sejour volumio[707]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Jan 19 12:05:18 sejour volumio[707]: at Receiver.emit (events.js:315:20) Jan 19 12:05:18 sejour volumio[707]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Jan 19 12:05:18 sejour volumio[707]: at internal/process/task_queues.js:149:7 Jan 19 12:05:18 sejour volumio[707]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Jan 19 12:05:18 sejour volumio[707]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Jan 19 12:05:18 sejour volumio[707]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jan 19 12:05:18 sejour volumio[707]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 19 12:05:19 sejour sudo[1355]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-01-19 12:04 Jan 19 12:05:19 sejour sudo[1355]: 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="5f6179c32cc5e5322b38e581552489aaa618132a" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="5c2a4dd264103bf71fc88af4cee05f0956e5f082" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 07 Mar 2024 03:43:06 PM CET" VOLUMIO_VERSION="3.638" VOLUMIO_HARDWARE="pi-uuid" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="671975747a94304dd578930394a62806"