-- Logs begin at Fri 2024-03-29 21:56:52 CET, end at Mon 2024-04-01 12:37:14 CEST. -- Apr 01 12:36:15 volumio go-librespot[5989]: time="2024-04-01T12:36:15+02:00" level=debug msg="handling transfer player command from 33ab87867000ddc53e47de29f2bc6e95ea1c4ed8" Apr 01 12:36:15 volumio go-librespot[5989]: time="2024-04-01T12:36:15+02:00" level=debug msg="loading track spotify:track:5x0qufZkT7XVcOhyg0S7XI (paused: true, position: 26168ms)" Apr 01 12:36:15 volumio go-librespot[5989]: time="2024-04-01T12:36:15+02:00" level=debug msg="renewing login5 access token" Apr 01 12:36:16 volumio go-librespot[5989]: time="2024-04-01T12:36:16+02:00" level=debug msg="authenticated as 21bldj6w74brdm5obmp7av3ka" Apr 01 12:36:16 volumio go-librespot[5989]: time="2024-04-01T12:36:16+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 01 12:36:16 volumio go-librespot[5989]: time="2024-04-01T12:36:16+02:00" level=trace msg="emitting websocket event: will_play" Apr 01 12:36:16 volumio volumio[822]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5x0qufZkT7XVcOhyg0S7XI","play_origin":"album"}} Apr 01 12:36:16 volumio go-librespot[5989]: time="2024-04-01T12:36:16+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:5x0qufZkT7XVcOhyg0S7XI" Apr 01 12:36:16 volumio go-librespot[5989]: time="2024-04-01T12:36:16+02:00" level=debug msg="requested aes key for file 405d55869b2df4d59c5f8d629856080ec31cf543, track: spotify:track:5x0qufZkT7XVcOhyg0S7XI" Apr 01 12:36:16 volumio go-librespot[5989]: time="2024-04-01T12:36:16+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2328" Apr 01 12:36:17 volumio go-librespot[5989]: time="2024-04-01T12:36:17+02:00" level=debug msg="fetched first chunk of 21, total size is 10646088 bytes" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="fetched chunk 3/20, size: 524288" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="fetched chunk 2/20, size: 524288" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="fetched chunk 1/20, size: 524288" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=trace msg="seek to 26168ms (diff: 56ms, samples: 1154008, bytes: 909401)" Apr 01 12:36:18 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="fetched chunk 4/20, size: 524288" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=info msg="loaded track \"No Jane\" (uri: spotify:track:5x0qufZkT7XVcOhyg0S7XI, paused: true, position: 26168ms, duration: 320626ms)" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=trace msg="emitting websocket event: metadata" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=trace msg="emitting websocket event: active" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="sending successful reply for delaer request" Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5x0qufZkT7XVcOhyg0S7XI","name":"No Jane","artist_names":["Radio Moscow"],"album_name":"Brain Cycles","album_cover_url":"https://i.scdn.co/image/ab67616d00001e023ae820020865f6589d06aa01","position":26168,"duration":320626}} Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: received: {"type":"active","data":null} Apr 01 12:36:18 volumio volumio[822]: info: Aligning Spotify Volume to Volumio Volume Apr 01 12:36:18 volumio volumio[822]: info: CoreCommandRouter::volumioGetState Apr 01 12:36:18 volumio volumio[822]: info: CorePlayQueue::getTrack 0 Apr 01 12:36:18 volumio volumio[822]: info: Setting Spotify Volume from Volumio: 100 Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Apr 01 12:36:18 volumio volumio[822]: info: Sending Spotify command with payload to local API: /player/volume Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=trace msg="emitting websocket event: paused" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="update volume to 65535/65535" Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:5x0qufZkT7XVcOhyg0S7XI","play_origin":"album"}} Apr 01 12:36:18 volumio volumio[822]: info: Spotify is playing in volatile mode Apr 01 12:36:18 volumio volumio[822]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: UNSET VOLATILE Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: {"status":"play","position":0,"title":"Yello - I Love You","artist":"80s80s Party","album":"","albumart":"https://is1-ssl.mzstatic.com/image/thumb/Music114/v4/1e/23/30/1e233090-d396-f2f7-fc92-3d7c7e90f1a6/source/600x600bb.jpg","uri":"http://streams.80s80s.de/party/mp3-192/volumio","trackType":"80s80s Radio","seek":0,"duration":"245","samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"80s80s Radio","volatile":false,"service":"80s80s"} Apr 01 12:36:18 volumio volumio[822]: info: Setting Spotify stop after unset volatile call Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: PUSH STATE SPOTIFY Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: {"status":"pause","service":"spop","title":"No Jane","artist":"Radio Moscow","album":"Brain Cycles","albumart":"https://i.scdn.co/image/ab67616d00001e023ae820020865f6589d06aa01","uri":"spotify:track:5x0qufZkT7XVcOhyg0S7XI","trackType":"spotify","seek":26168,"duration":320,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2} Apr 01 12:36:18 volumio volumio[822]: info: CoreCommandRouter::servicePushState Apr 01 12:36:18 volumio volumio[822]: info: CoreStateMachine::pushState Apr 01 12:36:18 volumio volumio[822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 01 12:36:18 volumio volumio[822]: info: CoreCommandRouter::volumioPushState Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2332" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=trace msg="emitting websocket event: volume" Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2328" Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 01 12:36:18 volumio go-librespot[5989]: time="2024-04-01T12:36:18+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 01 12:36:18 volumio volumio[822]: info: Spotify Stop Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: SPOTIFY STOP Apr 01 12:36:18 volumio volumio[822]: SPOTIFY: {"status":"pause","title":"No Jane","artist":"Radio Moscow","album":"Brain Cycles","albumart":"https://i.scdn.co/image/ab67616d00001e023ae820020865f6589d06aa01","uri":"spotify:track:5x0qufZkT7XVcOhyg0S7XI","trackType":"spotify","seek":26168,"duration":320,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"consume":false,"volume":100,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Apr 01 12:36:20 volumio go-librespot[5989]: time="2024-04-01T12:36:20+02:00" level=debug msg="handling play player command from 33ab87867000ddc53e47de29f2bc6e95ea1c4ed8" Apr 01 12:36:20 volumio go-librespot[5989]: time="2024-04-01T12:36:20+02:00" level=debug msg="loading track spotify:track:4ABXkvilk9vyS5FXkunxF4 (paused: false, position: 0ms)" Apr 01 12:36:20 volumio go-librespot[5989]: time="2024-04-01T12:36:20+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 01 12:36:20 volumio go-librespot[5989]: time="2024-04-01T12:36:20+02:00" level=trace msg="emitting websocket event: will_play" Apr 01 12:36:20 volumio volumio[822]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4ABXkvilk9vyS5FXkunxF4","play_origin":"playlist"}} Apr 01 12:36:20 volumio go-librespot[5989]: time="2024-04-01T12:36:20+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:4ABXkvilk9vyS5FXkunxF4" Apr 01 12:36:20 volumio go-librespot[5989]: time="2024-04-01T12:36:20+02:00" level=debug msg="requested aes key for file be897efe90a5d1c1ea2aaa29a4d4017f1e072c33, track: spotify:track:4ABXkvilk9vyS5FXkunxF4" Apr 01 12:36:21 volumio go-librespot[5989]: time="2024-04-01T12:36:21+02:00" level=debug msg="fetched first chunk of 16, total size is 8101996 bytes" Apr 01 12:36:21 volumio go-librespot[5989]: time="2024-04-01T12:36:21+02:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Apr 01 12:36:21 volumio go-librespot[5989]: time="2024-04-01T12:36:21+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" Apr 01 12:36:21 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Apr 01 12:36:21 volumio go-librespot[5989]: time="2024-04-01T12:36:21+02:00" level=info msg="loaded track \"Cuban Cigar\" (uri: spotify:track:4ABXkvilk9vyS5FXkunxF4, paused: false, position: 0ms, duration: 192626ms)" Apr 01 12:36:21 volumio go-librespot[5989]: time="2024-04-01T12:36:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 01 12:36:21 volumio go-librespot[5989]: time="2024-04-01T12:36:21+02:00" level=trace msg="emitting websocket event: metadata" Apr 01 12:36:21 volumio go-librespot[5989]: time="2024-04-01T12:36:21+02:00" level=debug msg="sending successful reply for delaer request" Apr 01 12:36:21 volumio volumio[822]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4ABXkvilk9vyS5FXkunxF4","name":"Cuban Cigar","artist_names":["Peter Godfrey"],"album_name":"Peter Godfrey, Vol. 7","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0252fd3ed8a796362bee08d319","position":0,"duration":192626}} Apr 01 12:36:21 volumio go-librespot[5989]: time="2024-04-01T12:36:21+02:00" level=debug msg="fetched chunk 2/15, size: 524288" Apr 01 12:36:21 volumio go-librespot[5989]: time="2024-04-01T12:36:21+02:00" level=debug msg="fetched chunk 3/15, size: 524288" Apr 01 12:36:21 volumio go-librespot[5989]: time="2024-04-01T12:36:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 01 12:36:21 volumio go-librespot[5989]: time="2024-04-01T12:36:21+02:00" level=trace msg="emitting websocket event: playing" Apr 01 12:36:21 volumio volumio[822]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4ABXkvilk9vyS5FXkunxF4","play_origin":"playlist"}} Apr 01 12:36:21 volumio volumio[822]: SPOTIFY: PUSH STATE SPOTIFY Apr 01 12:36:21 volumio volumio[822]: SPOTIFY: {"status":"play","service":"spop","title":"Cuban Cigar","artist":"Peter Godfrey","album":"Peter Godfrey, Vol. 7","albumart":"https://i.scdn.co/image/ab67616d00001e0252fd3ed8a796362bee08d319","uri":"spotify:track:4ABXkvilk9vyS5FXkunxF4","trackType":"spotify","seek":0,"duration":192,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"stream":false,"repeatMode":"all"} Apr 01 12:36:21 volumio volumio[822]: info: CoreCommandRouter::servicePushState Apr 01 12:36:21 volumio volumio[822]: info: CoreStateMachine::pushState Apr 01 12:36:21 volumio volumio[822]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 01 12:36:21 volumio volumio[822]: info: CoreCommandRouter::volumioPushState Apr 01 12:36:21 volumio volumio[822]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 01 12:36:21 volumio go-librespot[5989]: time="2024-04-01T12:36:21+02:00" level=debug msg="fetched chunk 1/15, size: 524288" Apr 01 12:36:22 volumio volumio[822]: SPOTIFY: PUSH STATE SPOTIFY Apr 01 12:36:22 volumio volumio[822]: SPOTIFY: {"status":"play","service":"spop","title":"Cuban Cigar","artist":"Peter Godfrey","album":"Peter Godfrey, Vol. 7","albumart":"https://i.scdn.co/image/ab67616d00001e0252fd3ed8a796362bee08d319","uri":"spotify:track:4ABXkvilk9vyS5FXkunxF4","trackType":"spotify","seek":0,"duration":192,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"stream":false,"repeatMode":"all"} Apr 01 12:36:22 volumio volumio[822]: info: CoreCommandRouter::servicePushState Apr 01 12:36:22 volumio volumio[822]: info: CoreStateMachine::pushState Apr 01 12:36:22 volumio volumio[822]: info: CoreCommandRouter::volumioPushState Apr 01 12:36:22 volumio volumio[822]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 01 12:36:32 volumio go-librespot[5989]: time="2024-04-01T12:36:32+02:00" level=debug msg="fetched chunk 4/15, size: 524288" Apr 01 12:36:38 volumio go-librespot[5989]: time="2024-04-01T12:36:38+02:00" level=debug msg="handling set_queue player command from 33ab87867000ddc53e47de29f2bc6e95ea1c4ed8" Apr 01 12:36:38 volumio go-librespot[5989]: time="2024-04-01T12:36:38+02:00" level=warning msg="failed handling dealer request" error="unsupported player command: set_queue" Apr 01 12:36:45 volumio go-librespot[5989]: time="2024-04-01T12:36:45+02:00" level=debug msg="fetched chunk 5/15, size: 524288" Apr 01 12:36:57 volumio go-librespot[5989]: time="2024-04-01T12:36:57+02:00" level=debug msg="fetched chunk 6/15, size: 524288" Apr 01 12:37:10 volumio go-librespot[5989]: time="2024-04-01T12:37:10+02:00" level=debug msg="fetched chunk 7/15, size: 524288" Apr 01 12:37:13 volumio volumio[822]: info: [1711967833667] [80s80s] Pushing the next song state Prince & The Revolution - Raspberry Beret and getting next track. Apr 01 12:37:13 volumio volumio[822]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 01 12:37:13 volumio volumio[822]: TypeError: Cannot set property 'name' of undefined Apr 01 12:37:13 volumio volumio[822]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Apr 01 12:37:13 volumio volumio[822]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Apr 01 12:37:13 volumio volumio[822]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Apr 01 12:37:13 volumio volumio[822]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Apr 01 12:37:13 volumio volumio[822]: at processImmediate (internal/timers.js:461:21) Apr 01 12:37:13 volumio volumio[822]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 01 12:37:14 volumio sudo[8725]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-01 12:36 Apr 01 12:37:14 volumio sudo[8725]: 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="cd8cf34b47ce852e70b71e6f7b6e0265f7fdb695" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="8f88153f9a18f312d56050e6613b45a852ac819a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 27 Sep 2023 11:35:49 AM CEST" VOLUMIO_VERSION="3.546" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="6823c0d83061ff736b7e0dd4481bc496"