-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sun 2025-01-12 20:55:40 CET. -- Jan 12 20:55:33 volumio systemd[1]: Starting Daily apt download activities... Jan 12 20:55:33 volumio systemd[1]: Starting Daily man-db regeneration... Jan 12 20:55:33 volumio ntpd[650]: receive: Unexpected origin timestamp 0xea9ad525.8d5bdfb6 does not match aorg 0000000000.00000000 from server@142.202.190.19 xmt 0xeb2e9cb5.8c9f36b0 Jan 12 20:55:33 volumio ntpd[650]: receive: Unexpected origin timestamp 0xea9ad525.8d555478 does not match aorg 0000000000.00000000 from server@129.146.193.200 xmt 0xeb2e9cb5.8cda832d Jan 12 20:55:33 volumio systemd[1]: man-db.service: Succeeded. Jan 12 20:55:33 volumio systemd[1]: Started Daily man-db regeneration. Jan 12 20:55:33 volumio volumio[827]: info: mDNS: A device disapperared from network Jan 12 20:55:33 volumio volumio[827]: info: mDNS: Device volumio disapperared from network Jan 12 20:55:34 volumio volumio[827]: info: Discovery: adding 8a0402fb-1e04-489d-982e-dd438bdb9770 Jan 12 20:55:34 volumio volumio[827]: info: mDNS: Found device Volumio Jan 12 20:55:34 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Jan 12 20:55:34 volumio volumio[827]: info: CorePlayQueue::getTrack 0 Jan 12 20:55:34 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Jan 12 20:55:34 volumio volumio[827]: info: CorePlayQueue::getTrack 0 Jan 12 20:55:35 volumio volumio[827]: info: Initializing connection to go-librespot Websocket Jan 12 20:55:35 volumio volumio[827]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 12 20:55:35 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Jan 12 20:55:35 volumio volumio[827]: info: CorePlayQueue::getTrack 0 Jan 12 20:55:35 volumio systemd[1]: apt-daily.service: Succeeded. Jan 12 20:55:35 volumio systemd[1]: Started Daily apt download activities. Jan 12 20:55:35 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Jan 12 20:55:35 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 12 20:55:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Jan 12 20:55:35 volumio systemd[1]: Stopped go-librespot Daemon. Jan 12 20:55:35 volumio systemd[1]: Started go-librespot Daemon. Jan 12 20:55:35 volumio go-librespot[2232]: Librespot-go daemon starting... Jan 12 20:55:35 volumio go-librespot[2232]: time="2025-01-12T20:55:35+01:00" level=info msg="generated new device id: 0b1fb3747765f495bded5249e08d582f6f02db9e" Jan 12 20:55:35 volumio go-librespot[2232]: time="2025-01-12T20:55:35+01:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Jan 12 20:55:35 volumio go-librespot[2232]: time="2025-01-12T20:55:35+01:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 12 20:55:35 volumio go-librespot[2232]: time="2025-01-12T20:55:35+01:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 12 20:55:35 volumio go-librespot[2232]: time="2025-01-12T20:55:35+01:00" level=debug msg="zeroconf server listening on port 40251" Jan 12 20:55:35 volumio node[830]: user connected through WS (port : 4152) Jan 12 20:55:36 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Jan 12 20:55:36 volumio volumio[827]: info: CorePlayQueue::getTrack 0 Jan 12 20:55:36 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Jan 12 20:55:36 volumio systemd[1]: Started Daily apt upgrade and clean activities. Jan 12 20:55:37 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Jan 12 20:55:37 volumio volumio[827]: info: CorePlayQueue::getTrack 0 Jan 12 20:55:38 volumio volumio[827]: info: Initializing connection to go-librespot Websocket Jan 12 20:55:38 volumio go-librespot[2232]: time="2025-01-12T20:55:38+01:00" level=debug msg="new websocket client" Jan 12 20:55:38 volumio volumio[827]: info: Connection to go-librespot Websocket established Jan 12 20:55:38 volumio go-librespot[2232]: time="2025-01-12T20:55:38+01:00" level=debug msg="obtained new client token: AAC+dRvUjx69eKn2B7aeP8Q81cpuH+rqKrhjzjnJ/l7wgYTh5LWfdav9lHn+V7LCZHvYd59A+na8Murv6vd58nKA+gDggKDS6IULDMZ7Ge7pEOElKX32zax1O/JrN1Ff3UWoa3C9p7iqJz3HeGYbSaCMKWWi4iXR3114Ud7fjtD7uy4b2fSSb3YE+v3qf847TQYBQnuKgqn2mTbDO7u6m7G0HQ/UEPM6oxjGBNgFYd3cMSZ9lE/WYQad9JL1oTQ=" Jan 12 20:55:38 volumio go-librespot[2232]: time="2025-01-12T20:55:38+01:00" level=info msg="connected to ap-gue1.spotify.com:4070" Jan 12 20:55:38 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Jan 12 20:55:38 volumio volumio[827]: info: CorePlayQueue::getTrack 0 Jan 12 20:55:38 volumio go-librespot[2232]: time="2025-01-12T20:55:38+01:00" level=debug msg="completed keyexchange" Jan 12 20:55:38 volumio go-librespot[2232]: time="2025-01-12T20:55:38+01:00" level=debug msg="completed challenge" Jan 12 20:55:38 volumio go-librespot[2232]: time="2025-01-12T20:55:38+01:00" level=debug msg="authenticated as 2gafp44izxih0f2g07ghw6hh4" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="authenticated as 2gafp44izxih0f2g07ghw6hh4" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="dealer connection opened" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=info msg="accepted zeroconf user 2gafp44izxih0f2g07ghw6hh4 from iPhone" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="autoplay enabled: false" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="received connection id: ZTgyY2ViNTItMmI3MS00ZTAyLTlmY2UtOTI4MDY5YjcwMzM4K2RlYWxlcit0Y3A6Ly8wYWNiZjg5Mi5pcC5ndWUxLnNwb3RpZnkubmV0OjU3MDArMjI0RDM3QjcyRkUwRTdBRDhDOTQ1N0U4QTUxQ0I0RkVCRTRGMUFCQ0E5RDgzN0NGRTZCNUEyRjhCNkM4RTJBRQ==" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="put connect state because NEW_DEVICE" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="handling transfer player command from 64b3b4856f0f5eddb1066b0a4f5bdc5763b9168c" Jan 12 20:55:39 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Jan 12 20:55:39 volumio volumio[827]: info: CorePlayQueue::getTrack 0 Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E4zXhR3f3Nbdr" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E4zXhR3f3Nbdr" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="loading track (paused: true, position: 1262ms)" uri="spotify:track:77RNVzAVwqWiZrZuWqMV2i" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=trace msg="emitting websocket event: will_play" Jan 12 20:55:39 volumio volumio[827]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:77RNVzAVwqWiZrZuWqMV2i","play_origin":"playlist/ondemand"}} Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="selected format OGG_VORBIS_320 (fb47c599d707b957f66b44674ccafd7092506deb)" uri="spotify:track:77RNVzAVwqWiZrZuWqMV2i" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="requested aes key for file fb47c599d707b957f66b44674ccafd7092506deb, gid: 77RNVzAVwqWiZrZuWqMV2i" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1362" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="fetched first chunk of 18, total size is 9133084 bytes" uri="spotify:track:77RNVzAVwqWiZrZuWqMV2i" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=trace msg="seek to 1262ms (diff: 42ms, samples: 55654, bytes: 36372)" uri="spotify:track:77RNVzAVwqWiZrZuWqMV2i" Jan 12 20:55:39 volumio volumio[827]: info: FusionDsp - ---- read samplerate, raw: Jan 12 20:55:39 volumio volumio[827]: error: FusionDsp - invalid sample rate Jan 12 20:55:39 volumio volumio[827]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jan 12 20:55:39 volumio volumio[827]: info: FusionDsp - ---- read samplerate from file: 44100 Jan 12 20:55:39 volumio volumio[827]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="created new output device" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=info msg="loaded track \"Nancy From Now On\" (paused: true, position: 1262ms, duration: 234160ms, prefetched: false)" uri="spotify:track:77RNVzAVwqWiZrZuWqMV2i" Jan 12 20:55:39 volumio volumio[827]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:77RNVzAVwqWiZrZuWqMV2i" Jan 12 20:55:39 volumio volumio[827]: info: camilladsp spawned new process with pid 2327, instance 1, run: true Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1125" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=trace msg="emitting websocket event: metadata" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=trace msg="emitting websocket event: active" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="sending successful reply for dealer request" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 12 20:55:39 volumio volumio[827]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:77RNVzAVwqWiZrZuWqMV2i","name":"Nancy From Now On","artist_names":["Father John Misty"],"album_name":"Fear Fun","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02f81572e9a17c58d81b0f70e9","position":1262,"duration":234160,"release_date":"year:2012 month:5 day:1","track_number":2,"disc_number":1}} Jan 12 20:55:39 volumio volumio[827]: SPOTIFY: received: {"type":"active","data":null} Jan 12 20:55:39 volumio volumio[827]: info: Aligning Spotify Volume to Volumio Volume Jan 12 20:55:39 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Jan 12 20:55:39 volumio volumio[827]: info: CorePlayQueue::getTrack 0 Jan 12 20:55:39 volumio volumio[827]: info: Setting Spotify Volume from Volumio: 67 Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=trace msg="emitting websocket event: paused" Jan 12 20:55:39 volumio volumio[827]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:77RNVzAVwqWiZrZuWqMV2i","play_origin":"playlist/ondemand"}} Jan 12 20:55:39 volumio volumio[827]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 20:55:39 volumio volumio[827]: TypeError: Cannot read property 'service' of undefined Jan 12 20:55:39 volumio volumio[827]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Jan 12 20:55:39 volumio volumio[827]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) Jan 12 20:55:39 volumio volumio[827]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Jan 12 20:55:39 volumio volumio[827]: at WebSocket.emit (events.js:315:20) Jan 12 20:55:39 volumio volumio[827]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jan 12 20:55:39 volumio volumio[827]: at Receiver.emit (events.js:315:20) Jan 12 20:55:39 volumio volumio[827]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jan 12 20:55:39 volumio volumio[827]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jan 12 20:55:39 volumio volumio[827]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jan 12 20:55:39 volumio volumio[827]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jan 12 20:55:39 volumio volumio[827]: at writeOrBuffer (internal/streams/writable.js:358:12) Jan 12 20:55:39 volumio volumio[827]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jan 12 20:55:39 volumio volumio[827]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Jan 12 20:55:39 volumio volumio[827]: at Socket.emit (events.js:315:20) Jan 12 20:55:39 volumio volumio[827]: at addChunk (internal/streams/readable.js:309:12) Jan 12 20:55:39 volumio volumio[827]: at readableAddChunk (internal/streams/readable.js:284:9) Jan 12 20:55:39 volumio volumio[827]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:77RNVzAVwqWiZrZuWqMV2i" Jan 12 20:55:39 volumio go-librespot[2232]: time="2025-01-12T20:55:39+01:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:77RNVzAVwqWiZrZuWqMV2i" Jan 12 20:55:40 volumio sudo[2343]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-01-12 20:54 Jan 12 20:55:40 volumio sudo[2343]: 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="1c5fa5a8788b087ca429be9d10851b25c5cc4f5b" VOLUMIO_FE_VERSION="e5ce74e254a237ac98580c4437c4ed223c7d5cd9" VOLUMIO_FE3_VERSION="a86adf3c7ed2d6c50d9bca768f58ab2f56832dc1" VOLUMIO_BE_VERSION="c8882d89d3d4e0a1571e0dc9701741128f5a1656" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 31 Mar 2022 02:51:41 PM CEST" VOLUMIO_VERSION="3.251" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e83cc5fcd68eb3ee4105ab0b8b3779ea"