-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Tue 2024-04-09 13:28:39 CEST. -- Apr 09 13:28:30 evaluna ntpd[666]: receive: Unexpected origin timestamp 0xe948d6e5.e709d478 does not match aorg 0000000000.00000000 from server@37.247.53.178 xmt 0xe9bfa4de.b5bced34 Apr 09 13:28:30 evaluna ntpd[666]: receive: Unexpected origin timestamp 0xe948d6e5.e70be516 does not match aorg 0000000000.00000000 from server@185.19.184.35 xmt 0xe9bfa4de.b61eeb91 Apr 09 13:28:30 evaluna ntpd[666]: receive: Unexpected origin timestamp 0xe948d6e5.e705ee20 does not match aorg 0000000000.00000000 from server@95.230.240.5 xmt 0xe9bfa4de.b6c2bd7f Apr 09 13:28:30 evaluna ntpd[666]: receive: Unexpected origin timestamp 0xe948d6e5.e70e3d3c does not match aorg 0000000000.00000000 from server@31.14.133.122 xmt 0xe9bfa4de.b684971e Apr 09 13:28:30 evaluna ntpd[666]: receive: Unexpected origin timestamp 0xe948d6e5.e6ffb108 does not match aorg 0000000000.00000000 from server@93.94.88.51 xmt 0xe9bfa4de.b8326bf4 Apr 09 13:28:30 evaluna systemd[1]: Starting Daily apt download activities... Apr 09 13:28:30 evaluna volumio[710]: info: Discovery: A device disappeared from network Apr 09 13:28:30 evaluna volumio[710]: info: Discovery: Device evaluna disappeared from network Apr 09 13:28:30 evaluna volumio[710]: info: Discovery: adding 0a89cf31-a173-4893-8a0e-88e2a1439709 Apr 09 13:28:30 evaluna volumio[710]: info: Discovery: Found device EvaLuna Apr 09 13:28:30 evaluna volumio[710]: info: CoreCommandRouter::volumioGetState Apr 09 13:28:30 evaluna volumio[710]: info: CorePlayQueue::getTrack 0 Apr 09 13:28:31 evaluna volumio[710]: info: Initializing connection to go-librespot Websocket Apr 09 13:28:31 evaluna volumio[710]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 09 13:28:31 evaluna systemd[1]: apt-daily.service: Succeeded. Apr 09 13:28:31 evaluna systemd[1]: Started Daily apt download activities. Apr 09 13:28:31 evaluna systemd[1]: Starting Daily apt upgrade and clean activities... Apr 09 13:28:31 evaluna systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 09 13:28:31 evaluna systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Apr 09 13:28:31 evaluna systemd[1]: Stopped go-librespot Daemon. Apr 09 13:28:31 evaluna systemd[1]: Started go-librespot Daemon. Apr 09 13:28:31 evaluna go-librespot[1107]: Librespot-go daemon starting... Apr 09 13:28:31 evaluna go-librespot[1107]: time="2024-04-09T13:28:31+02:00" level=info msg="generated new device id: 4a6887c7c555b69a635f00c3691a59e238947b94" Apr 09 13:28:31 evaluna go-librespot[1107]: time="2024-04-09T13:28:31+02:00" level=debug msg="stored credentials found for 21vhjescdjfgafxmqwhw76tra" Apr 09 13:28:32 evaluna go-librespot[1107]: time="2024-04-09T13:28:32+02:00" level=debug msg="obtained new client token: AADJPzrJVDfcmDrkAEF5LntwvgZhTCbA6nmnzSiO5UChMeuA/S8aNYn90QhGR8XFNAcQQsFTOHZ0WYSEIcrV9JJWTPrPq+jdjXYnZNG7f8nSMLiC4DBwYxE8Nt8HlTxZc8wq+LAkGtc0g4JZ89wYBYq2o+ei+QMvunygERvnCKVf40sIZP/JCU3CVxa2TgghpnP0uIRb1YT6eut3camgUiyTcyLRAkS474Zlj2iyP8YSO5Zw04bnD2zq6nyF" Apr 09 13:28:32 evaluna go-librespot[1107]: time="2024-04-09T13:28:32+02:00" 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]" Apr 09 13:28:32 evaluna go-librespot[1107]: time="2024-04-09T13:28:32+02:00" level=debug msg="completed keyexchange" Apr 09 13:28:32 evaluna systemd[1]: apt-daily-upgrade.service: Succeeded. Apr 09 13:28:32 evaluna systemd[1]: Started Daily apt upgrade and clean activities. Apr 09 13:28:32 evaluna go-librespot[1107]: time="2024-04-09T13:28:32+02:00" level=debug msg="completed challenge" Apr 09 13:28:32 evaluna go-librespot[1107]: time="2024-04-09T13:28:32+02:00" level=debug msg="authenticated as 21vhjescdjfgafxmqwhw76tra" Apr 09 13:28:33 evaluna go-librespot[1107]: time="2024-04-09T13:28:33+02:00" level=debug msg="authenticated as 21vhjescdjfgafxmqwhw76tra" Apr 09 13:28:33 evaluna go-librespot[1107]: time="2024-04-09T13:28:33+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]" Apr 09 13:28:33 evaluna go-librespot[1107]: time="2024-04-09T13:28:33+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]" Apr 09 13:28:33 evaluna go-librespot[1107]: time="2024-04-09T13:28:33+02:00" level=debug msg="dealer connection opened" Apr 09 13:28:33 evaluna go-librespot[1107]: time="2024-04-09T13:28:33+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 09 13:28:33 evaluna go-librespot[1107]: time="2024-04-09T13:28:33+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 09 13:28:33 evaluna go-librespot[1107]: time="2024-04-09T13:28:33+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 09 13:28:33 evaluna go-librespot[1107]: time="2024-04-09T13:28:33+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 09 13:28:33 evaluna go-librespot[1107]: time="2024-04-09T13:28:33+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" Apr 09 13:28:33 evaluna go-librespot[1107]: time="2024-04-09T13:28:33+02:00" level=debug msg="received connection id: YWUyZmUyYzUtZDQ4Yy00MjVhLTgwMTgtNGY1ZDA1ZGU1YTkyK2RlYWxlcit0Y3A6Ly9nZXc0LWRlYWxlci1hLW41YjUuZ2V3NC5zcG90aWZ5Lm5ldDo1NzAwK0E0RDU4MUZCREUxMjgzM0I0ODIzRUVCNzE5QUY1MTM5RkUxOTgxQTMxMkM0MTY4NjY4QkQ3ODRENEQ3RURFMzg=" Apr 09 13:28:33 evaluna go-librespot[1107]: time="2024-04-09T13:28:33+02:00" level=debug msg="put connect state because NEW_DEVICE" Apr 09 13:28:34 evaluna volumio[710]: info: Initializing connection to go-librespot Websocket Apr 09 13:28:34 evaluna go-librespot[1107]: time="2024-04-09T13:28:34+02:00" level=debug msg="new websocket client" Apr 09 13:28:34 evaluna volumio[710]: info: Connection to go-librespot Websocket established Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="handling transfer player command from 28a5c724747b0e7bef0a2ab857c8a3e4fdaab95e" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="loading track spotify:track:1UP7PXne1lIYZB5G5aiRGL (paused: false, position: 7486ms)" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=trace msg="emitting websocket event: will_play" Apr 09 13:28:35 evaluna volumio[710]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1UP7PXne1lIYZB5G5aiRGL","play_origin":"playlist/ondemand"}} Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:1UP7PXne1lIYZB5G5aiRGL" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="requested aes key for file 549caa41e1d54c3c52d068732cd8b0ae8e1a3830, gid: 1UP7PXne1lIYZB5G5aiRGL" Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2331" Apr 09 13:28:35 evaluna volumio[710]: info: Adding plugin bluetooth to MyMusic Plugins Apr 09 13:28:35 evaluna volumio[710]: info: Adding plugin multiroom to MyMusic Plugins Apr 09 13:28:35 evaluna volumio[710]: info: Adding plugin metavolumio to MyMusic Plugins Apr 09 13:28:35 evaluna volumio[710]: info: Adding plugin cd_controller to MyMusic Plugins Apr 09 13:28:35 evaluna volumio[710]: info: Adding plugin smart_inputs to MyMusic Plugins Apr 09 13:28:35 evaluna volumio[710]: info: Adding plugin tidalconnect to MyMusic Plugins Apr 09 13:28:35 evaluna volumio[710]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1718" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="fetched first chunk of 16, total size is 8176301 bytes" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=trace msg="seek to 7486ms (diff: 68ms, samples: 330132, bytes: 300895)" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=info msg="loaded track \"II MOST WANTED\" (uri: spotify:track:1UP7PXne1lIYZB5G5aiRGL, paused: false, position: 7486ms, duration: 208521ms)" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="fetched chunk 1/15, size: 524288" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=trace msg="emitting websocket event: metadata" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=trace msg="emitting websocket event: active" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="sending successful reply for delaer request" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 09 13:28:35 evaluna go-librespot[1107]: time="2024-04-09T13:28:35+02:00" level=trace msg="emitting websocket event: playing" Apr 09 13:28:36 evaluna go-librespot[1107]: time="2024-04-09T13:28:36+02:00" level=debug msg="fetched chunk 2/15, size: 524288" Apr 09 13:28:36 evaluna go-librespot[1107]: time="2024-04-09T13:28:36+02:00" level=debug msg="fetched chunk 3/15, size: 524288" Apr 09 13:28:36 evaluna volumio[710]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Apr 09 13:28:36 evaluna volumio[710]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Apr 09 13:28:36 evaluna volumio[710]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 09 13:28:36 evaluna volumio[710]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 09 13:28:36 evaluna volumio[710]: info: Starting MyVolumio Remote Streaming Endpoints Apr 09 13:28:36 evaluna volumio[710]: info: MyVolumio login type: Token Apr 09 13:28:36 evaluna volumio[710]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Apr 09 13:28:36 evaluna volumio[710]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Apr 09 13:28:38 evaluna volumio[710]: info: Starting Streaming Service Transparent Proxy Apr 09 13:28:38 evaluna volumio[710]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Apr 09 13:28:38 evaluna volumio[710]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Apr 09 13:28:38 evaluna volumio[710]: info: Streaming services startup Apr 09 13:28:38 evaluna volumio[710]: info: Starting Streaming Daemon Apr 09 13:28:38 evaluna sudo[1174]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Apr 09 13:28:38 evaluna sudo[1174]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 09 13:28:38 evaluna volumio[710]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Apr 09 13:28:38 evaluna sudo[1174]: pam_unix(sudo:session): session closed for user root Apr 09 13:28:38 evaluna volumio[710]: info: Getting Spotify volume Apr 09 13:28:38 evaluna volumio[710]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1UP7PXne1lIYZB5G5aiRGL","name":"II MOST WANTED","artist_names":["Beyoncé","Miley Cyrus"],"album_name":"COWBOY CARTER","album_cover_url":"https://i.scdn.co/image/ab67616d00001e021572698fff8a1db257a53599","position":7486,"duration":208521}} Apr 09 13:28:38 evaluna volumio[710]: SPOTIFY: received: {"type":"active","data":null} Apr 09 13:28:38 evaluna volumio[710]: info: Aligning Spotify Volume to Volumio Volume Apr 09 13:28:38 evaluna volumio[710]: info: CoreCommandRouter::volumioGetState Apr 09 13:28:38 evaluna volumio[710]: info: CorePlayQueue::getTrack 0 Apr 09 13:28:38 evaluna volumio[710]: info: Setting Spotify Volume from Volumio: 10 Apr 09 13:28:38 evaluna volumio[710]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1UP7PXne1lIYZB5G5aiRGL","play_origin":"playlist/ondemand"}} Apr 09 13:28:38 evaluna volumio[710]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 09 13:28:38 evaluna volumio[710]: TypeError: Cannot read property 'service' of undefined Apr 09 13:28:38 evaluna volumio[710]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:322:50) Apr 09 13:28:38 evaluna volumio[710]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:248:18) Apr 09 13:28:38 evaluna volumio[710]: at WebSocket.message (/data/plugins/music_service/spop/index.js:175:14) Apr 09 13:28:38 evaluna volumio[710]: at WebSocket.emit (events.js:315:20) Apr 09 13:28:38 evaluna volumio[710]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1192:20) Apr 09 13:28:38 evaluna volumio[710]: at Receiver.emit (events.js:315:20) Apr 09 13:28:38 evaluna volumio[710]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:560:14) Apr 09 13:28:38 evaluna volumio[710]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:478:17) Apr 09 13:28:38 evaluna volumio[710]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:22) Apr 09 13:28:38 evaluna volumio[710]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:180:18 Apr 09 13:28:38 evaluna volumio[710]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 09 13:28:39 evaluna sudo[1190]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-09 13:27 Apr 09 13:28:39 evaluna sudo[1190]: 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="893d2e91c55a7857b58762e70c2f65b9d163562b" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="30b77d58bf3c2745acc494ddafed946392a79905" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 20 Oct 2023 03:38:28 PM CEST" VOLUMIO_VERSION="3.569" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4163d3756b55b3bf7c480d7285f68954"