-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Sun 2024-07-14 17:28:13 UTC. -- Jul 14 17:28:08 mamasstue ntpd[565]: receive: Unexpected origin timestamp 0xe9314c37.0a859cfe does not match aorg 0000000000.00000000 from server@77.33.79.202 xmt 0xea3e8928.2ac2bfe4 Jul 14 17:28:08 mamasstue ntpd[565]: receive: Unexpected origin timestamp 0xe9314c37.0a8c8062 does not match aorg 0000000000.00000000 from server@194.45.79.110 xmt 0xea3e8928.2b7cfc4a Jul 14 17:28:08 mamasstue systemd[1]: Starting Daily apt download activities... Jul 14 17:28:08 mamasstue ntpd[565]: receive: Unexpected origin timestamp 0xe9314c37.0a87c1d0 does not match aorg 0000000000.00000000 from server@80.209.87.103 xmt 0xea3e8928.2b430bf6 Jul 14 17:28:08 mamasstue ntpd[565]: receive: Unexpected origin timestamp 0xe9314c37.0a7e9768 does not match aorg 0000000000.00000000 from server@86.52.112.177 xmt 0xea3e8928.2b532633 Jul 14 17:28:08 mamasstue systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 14 17:28:08 mamasstue systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Jul 14 17:28:08 mamasstue systemd[1]: Stopped go-librespot Daemon. Jul 14 17:28:08 mamasstue systemd[1]: Started go-librespot Daemon. Jul 14 17:28:08 mamasstue go-librespot[1078]: Librespot-go daemon starting... Jul 14 17:28:08 mamasstue go-librespot[1078]: time="2024-07-14T17:28:08Z" level=info msg="generated new device id: d2c6531c9da66de27bb5b8771ccdeeb5e9ad45e3" Jul 14 17:28:08 mamasstue go-librespot[1078]: time="2024-07-14T17:28:08Z" level=debug msg="stored credentials found for sa7j78xgtfos1qzv5w7u7539z" Jul 14 17:28:08 mamasstue go-librespot[1078]: time="2024-07-14T17:28:08Z" level=debug msg="obtained new client token: AADp3NK+o9UqZBAf0TLEeotJaP+yCjaMX4M+twz9YxBpwesNcySeaxQwULjJZWE4GhPYXdRVv/rgvkybWBcb1/hkBWJ++1RyTvvkORWbDUk9XLx/0sPjUsfbCVrk3s0k6rKgenaip0MyHndslddjaLFQbxNMMlwJoRf+XsMH+Gn0Gcj5i2RABeETwZzpryACgJDirs8QTlWS7KuVSQSNW4eqWns+Ze/zMwxqjzKD1XLxZu74ThJMMdfjjJLYhg==" Jul 14 17:28:08 mamasstue go-librespot[1078]: time="2024-07-14T17:28:08Z" 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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 14 17:28:08 mamasstue go-librespot[1078]: time="2024-07-14T17:28:08Z" level=debug msg="completed keyexchange" Jul 14 17:28:08 mamasstue volumio[738]: info: mDNS: A device disapperared from network Jul 14 17:28:09 mamasstue volumio[738]: info: Discovery: adding 54833dea-0e13-4028-a7b4-ca6a5852e31b Jul 14 17:28:09 mamasstue volumio[738]: info: mDNS: Found device Mamas_stue Jul 14 17:28:09 mamasstue volumio[738]: info: CoreCommandRouter::volumioGetState Jul 14 17:28:09 mamasstue volumio[738]: info: CorePlayQueue::getTrack 0 Jul 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" level=debug msg="completed challenge" Jul 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" level=debug msg="authenticated as sa7j78xgtfos1qzv5w7u7539z" Jul 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" level=debug msg="authenticated as sa7j78xgtfos1qzv5w7u7539z" Jul 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" 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 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" level=debug msg="dealer connection opened" Jul 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 517" Jul 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" level=debug msg="received connection id: ZmRhYTgwNTYtZWUxNy00MDhjLWFhOTgtYTgxYmNkZTEzNmE1K2RlYWxlcit0Y3A6Ly9nZXc0LWRlYWxlci1hLXFocTIuZ2V3NC5zcG90aWZ5Lm5ldDo1NzAwKzg1REIxRUVCRkVGRUJDNzIyMzI0MjBBNUI0ODZEQkJCRkQyNEFFQzNGODQ5NkJGMzhBMjczQ0JFMTYxNzk0REY=" Jul 14 17:28:09 mamasstue go-librespot[1078]: time="2024-07-14T17:28:09Z" level=debug msg="put connect state because NEW_DEVICE" Jul 14 17:28:10 mamasstue volumio[738]: info: Initializing connection to go-librespot Websocket Jul 14 17:28:10 mamasstue go-librespot[1078]: time="2024-07-14T17:28:10Z" level=debug msg="new websocket client" Jul 14 17:28:10 mamasstue volumio[738]: info: Connection to go-librespot Websocket established Jul 14 17:28:11 mamasstue go-librespot[1078]: time="2024-07-14T17:28:11Z" level=debug msg="handling transfer player command from bf65a343446b609a229546ac803eb86204f7236e" Jul 14 17:28:11 mamasstue go-librespot[1078]: time="2024-07-14T17:28:11Z" level=trace msg="fetched new page 0 with 118 items (list: 118)" Jul 14 17:28:11 mamasstue go-librespot[1078]: time="2024-07-14T17:28:11Z" level=debug msg="shuffled context with seed 11894901919160322651 (len: 118, keep: 112)" Jul 14 17:28:11 mamasstue go-librespot[1078]: time="2024-07-14T17:28:11Z" level=debug msg="loading track spotify:track:2g9tgvHQVRrCTvErUz5bzJ (paused: true, position: 6058ms)" Jul 14 17:28:11 mamasstue go-librespot[1078]: time="2024-07-14T17:28:11Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 14 17:28:11 mamasstue go-librespot[1078]: time="2024-07-14T17:28:11Z" level=trace msg="emitting websocket event: will_play" Jul 14 17:28:11 mamasstue volumio[738]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2g9tgvHQVRrCTvErUz5bzJ","play_origin":"playlist"}} Jul 14 17:28:11 mamasstue go-librespot[1078]: time="2024-07-14T17:28:11Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Jul 14 17:28:11 mamasstue go-librespot[1078]: time="2024-07-14T17:28:11Z" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:2g9tgvHQVRrCTvErUz5bzJ" Jul 14 17:28:11 mamasstue go-librespot[1078]: time="2024-07-14T17:28:11Z" level=debug msg="requested aes key for file ea2029de1fdb01da0a9882802626cf51f491b39a, gid: 2g9tgvHQVRrCTvErUz5bzJ" Jul 14 17:28:11 mamasstue go-librespot[1078]: time="2024-07-14T17:28:11Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1636" Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=debug msg="fetched first chunk of 19, total size is 9961444 bytes" Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=trace msg="seek to 6058ms (diff: 81ms, samples: 267157, bytes: 197888)" Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1394" Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=info msg="loaded track \"Everything's So Different Without You\" (uri: spotify:track:2g9tgvHQVRrCTvErUz5bzJ, paused: true, position: 6058ms, duration: 259626ms)" Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=debug msg="fetched chunk 3/18, size: 524288" Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=trace msg="emitting websocket event: metadata" Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=trace msg="emitting websocket event: active" Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=debug msg="sending successful reply for delaer request" Jul 14 17:28:12 mamasstue volumio[738]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2g9tgvHQVRrCTvErUz5bzJ","name":"Everything's So Different Without You","artist_names":["Billy Ocean"],"album_name":"Time to Move On","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029c699227df213357da136d8a","position":6058,"duration":259626,"release_date":"year:1993 month:6 day:7","track_number":10,"disc_number":1}} Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 14 17:28:12 mamasstue volumio[738]: SPOTIFY: received: {"type":"active","data":null} Jul 14 17:28:12 mamasstue volumio[738]: info: Aligning Spotify Volume to Volumio Volume Jul 14 17:28:12 mamasstue volumio[738]: info: CoreCommandRouter::volumioGetState Jul 14 17:28:12 mamasstue volumio[738]: info: CorePlayQueue::getTrack 0 Jul 14 17:28:12 mamasstue volumio[738]: info: Setting Spotify Volume from Volumio: 50 Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=debug msg="fetched chunk 2/18, size: 524288" Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=debug msg="fetched chunk 1/18, size: 524288" Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 14 17:28:12 mamasstue go-librespot[1078]: time="2024-07-14T17:28:12Z" level=trace msg="emitting websocket event: paused" Jul 14 17:28:12 mamasstue volumio[738]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:2g9tgvHQVRrCTvErUz5bzJ","play_origin":"playlist"}} Jul 14 17:28:12 mamasstue volumio[738]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 14 17:28:12 mamasstue volumio[738]: TypeError: Cannot read property 'service' of undefined Jul 14 17:28:12 mamasstue volumio[738]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Jul 14 17:28:12 mamasstue volumio[738]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Jul 14 17:28:12 mamasstue volumio[738]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Jul 14 17:28:12 mamasstue volumio[738]: at WebSocket.emit (events.js:315:20) Jul 14 17:28:12 mamasstue volumio[738]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Jul 14 17:28:12 mamasstue volumio[738]: at Receiver.emit (events.js:315:20) Jul 14 17:28:12 mamasstue volumio[738]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Jul 14 17:28:12 mamasstue volumio[738]: at internal/process/task_queues.js:149:7 Jul 14 17:28:12 mamasstue volumio[738]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Jul 14 17:28:12 mamasstue volumio[738]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Jul 14 17:28:12 mamasstue volumio[738]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jul 14 17:28:12 mamasstue volumio[738]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 14 17:28:12 mamasstue systemd[1]: apt-daily.service: Succeeded. Jul 14 17:28:12 mamasstue systemd[1]: Started Daily apt download activities. Jul 14 17:28:12 mamasstue systemd[1]: Starting Daily apt upgrade and clean activities... Jul 14 17:28:13 mamasstue sudo[1172]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-14 17:27 Jul 14 17:28:13 mamasstue sudo[1172]: 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"