-- Logs begin at Tue 2024-06-04 20:46:45 CEST, end at Thu 2025-10-16 11:16:14 CEST. -- Oct 16 11:16:09 volumio ntpd[775]: receive: Unexpected origin timestamp 0xea09dfe4.0fcc62b1 does not match aorg 0000000000.00000000 from server@151.22.209.90 xmt 0xec9b3659.f68aae2e Oct 16 11:16:09 volumio ntpd[775]: receive: Unexpected origin timestamp 0xea09dfe4.0fc952ca does not match aorg 0000000000.00000000 from server@162.159.200.1 xmt 0xec9b3659.f5fe19aa Oct 16 11:16:09 volumio ntpd[775]: receive: Unexpected origin timestamp 0xea09dfe4.0fc582db does not match aorg 0000000000.00000000 from server@185.19.184.35 xmt 0xec9b3659.f5fe6a70 Oct 16 11:16:10 volumio systemd[1]: Starting Daily apt download activities... Oct 16 11:16:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 16 11:16:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Oct 16 11:16:10 volumio systemd[1]: Stopped go-librespot Daemon. Oct 16 11:16:10 volumio systemd[1]: Started go-librespot Daemon. Oct 16 11:16:10 volumio go-librespot[1424]: go-librespot daemon starting... Oct 16 11:16:10 volumio go-librespot[1424]: time="2025-10-16T11:16:10+02:00" level=info msg="running go-librespot 0.3.2" Oct 16 11:16:10 volumio go-librespot[1424]: time="2025-10-16T11:16:10+02:00" level=debug msg="app state loaded" Oct 16 11:16:10 volumio go-librespot[1424]: time="2025-10-16T11:16:10+02:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 16 11:16:10 volumio ntpd[775]: Soliciting pool server 2600:3c0b::f03c:94ff:fee2:cbb9 Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=info msg="zeroconf server listening on port 43123" Oct 16 11:16:11 volumio volumio[959]: info: Discovery: A device disappeared from network Oct 16 11:16:11 volumio volumio[959]: info: Discovery: Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="obtained new client token: AACX7fcoP88L0+Qh8S0q/TxdL1AVt0F8GIhah3xPqXlVp686raeeCyuoEWshE0EDA1bmfPPzL0GT62NedSqLQZ7tLMlzvM8gw8qdVpDzalIKBl1mB/xpzckvSEA+7sPk4xWWdhDfEiJ9+HC+u8COvDbeQGK2EyYX3fZ+be6/9ZczXW3ST+gZDppENUPm5HAK/c/ze/xnHHk8aMkA54UU2zn+3rQiXDbROyE3HoAQMOuA0cBZMUpHWo66" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Oct 16 11:16:11 volumio volumio[959]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007 Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="completed keyexchange" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="completed challenge" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=info msg="authenticated AP" username="yp*********************lj" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=info msg="authenticated Login5" username="yp*********************lj" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="initializing zeroconf session" username="yp*********************lj" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="dealer connection opened" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=trace msg="starting accesspoint recv loop" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=trace msg="starting dealer recv loop" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=trace msg="received accesspoint ping" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="received connection id: MTcyN2MxNWYtZDRh...NUM4Qjg5RTNFQg==" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=trace msg="received accesspoint pong ack" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 16 11:16:11 volumio go-librespot[1424]: time="2025-10-16T11:16:11+02:00" level=debug msg="update volume requested to 65535/65535" Oct 16 11:16:12 volumio go-librespot[1424]: time="2025-10-16T11:16:12+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 16 11:16:12 volumio go-librespot[1424]: time="2025-10-16T11:16:12+02:00" level=trace msg="emitting websocket event: volume" Oct 16 11:16:12 volumio volumio[959]: info: Initializing connection to go-librespot Websocket Oct 16 11:16:12 volumio go-librespot[1424]: time="2025-10-16T11:16:12+02:00" level=debug msg="new websocket client" Oct 16 11:16:12 volumio volumio[959]: info: Connection to go-librespot Websocket established Oct 16 11:16:12 volumio systemd[1]: apt-daily.service: Succeeded. Oct 16 11:16:12 volumio systemd[1]: Started Daily apt download activities. Oct 16 11:16:12 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="handling transfer player command from c3a3f445c3784089aec16e1e4e4b3585445b8e81" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:2yULzkG7T9RU7DdCGuyo6g" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=trace msg="fetched new page 0 with 28 items (list: 28)" uri="spotify:playlist:2yULzkG7T9RU7DdCGuyo6g" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="loading track (paused: false, position: 19976ms)" uri="spotify:track:0GwZZXOpymYUQShcWVqyk5" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=trace msg="emitting websocket event: will_play" Oct 16 11:16:13 volumio volumio[959]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0GwZZXOpymYUQShcWVqyk5","play_origin":"playlist"}} Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="selected format OGG_VORBIS_320 (a6f21748b05c8335ea0e4bde72b3fb5a0716e2dd)" uri="spotify:track:0GwZZXOpymYUQShcWVqyk5" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="requested aes key for file a6f21748b05c8335ea0e4bde72b3fb5a0716e2dd, gid: 0GwZZXOpymYUQShcWVqyk5" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0GwZZXOpymYUQShcWVqyk5" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 391" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1400" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="fetched first chunk of 16, total size is 8383008 bytes" uri="spotify:track:0GwZZXOpymYUQShcWVqyk5" Oct 16 11:16:13 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Oct 16 11:16:13 volumio systemd[1]: Started Daily apt upgrade and clean activities. Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:0GwZZXOpymYUQShcWVqyk5" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=trace msg="seek to 19976ms (diff: 61ms, samples: 880941, bytes: 804433)" uri="spotify:track:0GwZZXOpymYUQShcWVqyk5" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="created new output device" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=info msg="loaded track \"Orchestral Suite in D Major, No. 3, BWV 1068: II. Air\" (paused: false, position: 19976ms, duration: 206969ms, prefetched: false)" uri="spotify:track:0GwZZXOpymYUQShcWVqyk5" Oct 16 11:16:13 volumio go-librespot[1424]: time="2025-10-16T11:16:13+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1144" Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=trace msg="scheduling prefetch in 157s" Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=trace msg="emitting websocket event: metadata" Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=trace msg="emitting websocket event: active" Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=debug msg="sending successful reply for dealer request" Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 16 11:16:14 volumio volumio[959]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0GwZZXOpymYUQShcWVqyk5","name":"Orchestral Suite in D Major, No. 3, BWV 1068: II. Air","artist_names":["J.S. Bach Orchestra"],"album_name":"Bach: Air On the G String \u0026 Violin Concerto - Vivaldi: the Four Seasons - Pachelbel: Canon - Albinoni: Adagio - Walter Rinaldi: Piano Concerto - Granados: Danza Espanola - Sinding: Rustle of Spring - Liszt: Love Dream","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0298567c417822c24437f930a5","position":19976,"duration":206969,"release_date":"year:2012 month:12 day:3","track_number":1,"disc_number":1}} Oct 16 11:16:14 volumio volumio[959]: SPOTIFY: received: {"type":"active","data":null} Oct 16 11:16:14 volumio volumio[959]: info: Aligning Spotify Volume to Volumio Volume Oct 16 11:16:14 volumio volumio[959]: info: CoreCommandRouter::volumioGetState Oct 16 11:16:14 volumio volumio[959]: info: CorePlayQueue::getTrack 0 Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:0GwZZXOpymYUQShcWVqyk5" Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=debug msg="fetched chunk 4/15, size: 524288" uri="spotify:track:0GwZZXOpymYUQShcWVqyk5" Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=trace msg="emitting websocket event: playing" Oct 16 11:16:14 volumio volumio[959]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0GwZZXOpymYUQShcWVqyk5","resume":false,"play_origin":"playlist"}} Oct 16 11:16:14 volumio volumio[959]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 16 11:16:14 volumio volumio[959]: TypeError: Cannot read property 'service' of undefined Oct 16 11:16:14 volumio volumio[959]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Oct 16 11:16:14 volumio volumio[959]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Oct 16 11:16:14 volumio volumio[959]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Oct 16 11:16:14 volumio volumio[959]: at WebSocket.emit (events.js:315:20) Oct 16 11:16:14 volumio volumio[959]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Oct 16 11:16:14 volumio volumio[959]: at Receiver.emit (events.js:315:20) Oct 16 11:16:14 volumio volumio[959]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Oct 16 11:16:14 volumio volumio[959]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Oct 16 11:16:14 volumio volumio[959]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Oct 16 11:16:14 volumio volumio[959]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Oct 16 11:16:14 volumio volumio[959]: at writeOrBuffer (internal/streams/writable.js:358:12) Oct 16 11:16:14 volumio volumio[959]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Oct 16 11:16:14 volumio volumio[959]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Oct 16 11:16:14 volumio volumio[959]: at Socket.emit (events.js:315:20) Oct 16 11:16:14 volumio volumio[959]: at addChunk (internal/streams/readable.js:309:12) Oct 16 11:16:14 volumio volumio[959]: at readableAddChunk (internal/streams/readable.js:284:9) Oct 16 11:16:14 volumio volumio[959]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 16 11:16:14 volumio sudo[1524]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-10-16 11:15 Oct 16 11:16:14 volumio sudo[1524]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 16 11:16:14 volumio go-librespot[1424]: time="2025-10-16T11:16:14+02:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:0GwZZXOpymYUQShcWVqyk5" 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="4b122b2365bb8c09786cd63b50d1ea6db780eb4e" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="49f98390f2d84c6549f33dc85b694fbd99e4c720" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 04 Jun 2024 08:41:12 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="8e78a6e3f56f1bcbbd1760812129a8e9"