-- 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"