-- Logs begin at Fri 2024-08-23 20:10:27 CEST, end at Sun 2024-08-25 15:01:04 CEST. -- Aug 25 15:00:55 volumiobetel go-librespot[1145]: time="2024-08-25T15:00:55+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 340" Aug 25 15:00:55 volumiobetel go-librespot[1145]: time="2024-08-25T15:00:55+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 25 15:00:56 volumiobetel go-librespot[1145]: time="2024-08-25T15:00:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 338" Aug 25 15:00:56 volumiobetel go-librespot[1145]: time="2024-08-25T15:00:56+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 25 15:00:59 volumiobetel go-librespot[1145]: time="2024-08-25T15:00:59+02:00" level=debug msg="handling transfer player command from 8c2bba9032d020aaba1a431993d5db3020a8b02c" Aug 25 15:00:59 volumiobetel go-librespot[1145]: time="2024-08-25T15:00:59+02:00" level=debug msg="renewing login5 access token" Aug 25 15:00:59 volumiobetel go-librespot[1145]: time="2024-08-25T15:00:59+02:00" level=debug msg="authenticated as 31kry3352hjmzm66gqd23keoygga" Aug 25 15:00:59 volumiobetel go-librespot[1145]: time="2024-08-25T15:00:59+02:00" level=trace msg="fetched new page 0 with 12 items (list: 12)" Aug 25 15:00:59 volumiobetel go-librespot[1145]: time="2024-08-25T15:00:59+02:00" level=debug msg="loading track spotify:track:2KILiorz1g3KgSLLusXWHO (paused: false, position: 5945ms)" Aug 25 15:01:00 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:00+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 25 15:01:00 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:00+02:00" level=trace msg="emitting websocket event: will_play" Aug 25 15:01:00 volumiobetel volumio[957]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2KILiorz1g3KgSLLusXWHO","play_origin":"playlist"}} Aug 25 15:01:00 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:00+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:2KILiorz1g3KgSLLusXWHO" Aug 25 15:01:00 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:00+02:00" level=debug msg="requested aes key for file c90b4064e90899657b5a7363543bd4e805295ee5, gid: 2KILiorz1g3KgSLLusXWHO" Aug 25 15:01:00 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:00+02:00" level=debug msg="fetched first chunk of 27, total size is 14010424 bytes" Aug 25 15:01:00 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:00+02:00" level=trace msg="seek to 5945ms (diff: 241ms, samples: 262174, bytes: 225926)" Aug 25 15:01:01 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:01+02:00" level=info msg="loaded track \"Shame\" (uri: spotify:track:2KILiorz1g3KgSLLusXWHO, paused: false, position: 5945ms, duration: 332026ms)" Aug 25 15:01:01 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:01+02:00" level=debug msg="fetched chunk 1/26, size: 524288" Aug 25 15:01:01 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:01+02:00" level=debug msg="fetched chunk 3/26, size: 524288" Aug 25 15:01:01 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:01+02:00" level=debug msg="fetched chunk 2/26, size: 524288" Aug 25 15:01:01 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:01+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 25 15:01:01 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:01+02:00" level=trace msg="emitting websocket event: metadata" Aug 25 15:01:01 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:01+02:00" level=trace msg="emitting websocket event: active" Aug 25 15:01:01 volumiobetel volumio[957]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2KILiorz1g3KgSLLusXWHO","name":"Shame","artist_names":["Rollins Band"],"album_name":"Come In And Burn","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b0841f4d78f490b29c91a1bd","position":5945,"duration":332026,"release_date":"year:1997 month:3 day:25","track_number":1,"disc_number":1}} Aug 25 15:01:01 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:01+02:00" level=debug msg="sending successful reply for delaer request" Aug 25 15:01:01 volumiobetel volumio[957]: SPOTIFY: received: {"type":"active","data":null} Aug 25 15:01:01 volumiobetel volumio[957]: info: Aligning Spotify Volume to Volumio Volume Aug 25 15:01:01 volumiobetel volumio[957]: info: CoreCommandRouter::volumioGetState Aug 25 15:01:01 volumiobetel volumio[957]: info: CorePlayQueue::getTrack 0 Aug 25 15:01:01 volumiobetel volumio[957]: info: Setting Spotify Volume from Volumio: 51 Aug 25 15:01:01 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:01+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Aug 25 15:01:01 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:01+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Aug 25 15:01:01 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:01+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1412" Aug 25 15:01:02 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:02+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 25 15:01:02 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 25 15:01:02 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:02+02:00" level=trace msg="emitting websocket event: playing" Aug 25 15:01:02 volumiobetel volumio[957]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2KILiorz1g3KgSLLusXWHO","play_origin":"playlist"}} Aug 25 15:01:02 volumiobetel volumio[957]: info: Spotify is playing in volatile mode Aug 25 15:01:02 volumiobetel volumio[957]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 25 15:01:02 volumiobetel volumio[957]: SPOTIFY: UNSET VOLATILE Aug 25 15:01:02 volumiobetel volumio[957]: SPOTIFY: {"status":"play","position":0,"title":"Real Life - Send Me an Angel","artist":"80s80s Real 80s Radio","album":"","albumart":"https://is3-ssl.mzstatic.com/image/thumb/Music124/v4/f8/07/4e/f8074ea8-c16b-f8b9-18ff-94caa8dfb774/source/600x600bb.jpg","uri":"http://streams.80s80s.de/web/mp3-192/volumio","trackType":"80s80s Radio","seek":0,"duration":"230","samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":51,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"80s80s Radio","volatile":false,"service":"80s80s"} Aug 25 15:01:02 volumiobetel volumio[957]: info: Setting Spotify stop after unset volatile call Aug 25 15:01:02 volumiobetel volumio[957]: SPOTIFY: PUSH STATE SPOTIFY Aug 25 15:01:02 volumiobetel volumio[957]: SPOTIFY: {"status":"play","service":"spop","title":"Shame","artist":"Rollins Band","album":"Come In And Burn","albumart":"https://i.scdn.co/image/ab67616d00001e02b0841f4d78f490b29c91a1bd","uri":"spotify:track:2KILiorz1g3KgSLLusXWHO","trackType":"spotify","seek":5945,"duration":332,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 25 15:01:02 volumiobetel volumio[957]: info: CoreCommandRouter::servicePushState Aug 25 15:01:02 volumiobetel volumio[957]: info: CoreStateMachine::pushState Aug 25 15:01:02 volumiobetel volumio[957]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 25 15:01:02 volumiobetel volumio[957]: info: CoreCommandRouter::volumioPushState Aug 25 15:01:02 volumiobetel volumio[957]: SPOTIFY: RECEIVED VOLUMIO VOLUME 51 Aug 25 15:01:02 volumiobetel volumio[957]: error: FusionDsp - File size not found in array! Aug 25 15:01:02 volumiobetel volumio[957]: info: FusionDsp - Nulleq applied Aug 25 15:01:02 volumiobetel volumio[957]: SPOTIFY: PUSH STATE SPOTIFY Aug 25 15:01:02 volumiobetel volumio[957]: SPOTIFY: {"status":"play","service":"spop","title":"Shame","artist":"Rollins Band","album":"Come In And Burn","albumart":"https://i.scdn.co/image/ab67616d00001e02b0841f4d78f490b29c91a1bd","uri":"spotify:track:2KILiorz1g3KgSLLusXWHO","trackType":"spotify","seek":5945,"duration":332,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Aug 25 15:01:02 volumiobetel volumio[957]: info: CoreCommandRouter::servicePushState Aug 25 15:01:02 volumiobetel volumio[957]: info: CoreStateMachine::pushState Aug 25 15:01:02 volumiobetel volumio[957]: info: CoreCommandRouter::volumioPushState Aug 25 15:01:02 volumiobetel volumio[957]: SPOTIFY: RECEIVED VOLUMIO VOLUME 51 Aug 25 15:01:02 volumiobetel volumio[957]: error: FusionDsp - File size not found in array! Aug 25 15:01:02 volumiobetel volumio[957]: info: FusionDsp - Nulleq applied Aug 25 15:01:03 volumiobetel volumio[957]: info: Spotify Stop Aug 25 15:01:03 volumiobetel volumio[957]: SPOTIFY: SPOTIFY STOP Aug 25 15:01:03 volumiobetel volumio[957]: SPOTIFY: {"status":"play","title":"Shame","artist":"Rollins Band","album":"Come In And Burn","albumart":"https://i.scdn.co/image/ab67616d00001e02b0841f4d78f490b29c91a1bd","uri":"spotify:track:2KILiorz1g3KgSLLusXWHO","trackType":"spotify","codec":"ogg","seek":5945,"duration":332,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":51,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Aug 25 15:01:03 volumiobetel volumio[957]: SPOTIFY: SETTING SPOTIFY VOLUME 51 Aug 25 15:01:03 volumiobetel volumio[957]: info: Sending Spotify command with payload to local API: /player/volume Aug 25 15:01:03 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:03+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1163" Aug 25 15:01:03 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:03+02:00" level=debug msg="update volume to 33422/65535" Aug 25 15:01:03 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:03+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Aug 25 15:01:03 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:03+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 25 15:01:03 volumiobetel go-librespot[1145]: time="2024-08-25T15:01:03+02:00" level=trace msg="emitting websocket event: volume" Aug 25 15:01:03 volumiobetel volumio[957]: SPOTIFY: received: {"type":"volume","data":{"value":51,"max":100}} Aug 25 15:01:03 volumiobetel volumio[957]: SPOTIFY: RECEIVED SPOTIFY VOLUME 51 Aug 25 15:01:03 volumiobetel volumio[957]: info: FusionDsp - nulleq: Aug 25 15:01:03 volumiobetel volumio[957]: type: Conv Aug 25 15:01:03 volumiobetel volumio[957]: info: FusionDsp - {"Reload":{"result":"Ok"}} Aug 25 15:01:03 volumiobetel volumio[957]: info: [1724590863631] [80s80s] Pushing the next song state Wham! - Young Guns (Go for It!) and getting next track. Aug 25 15:01:03 volumiobetel volumio[957]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 15:01:03 volumiobetel volumio[957]: TypeError: Cannot set property 'name' of undefined Aug 25 15:01:03 volumiobetel volumio[957]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Aug 25 15:01:03 volumiobetel volumio[957]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Aug 25 15:01:03 volumiobetel volumio[957]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Aug 25 15:01:03 volumiobetel volumio[957]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Aug 25 15:01:03 volumiobetel volumio[957]: at processImmediate (internal/timers.js:461:21) Aug 25 15:01:03 volumiobetel volumio[957]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 25 15:01:04 volumiobetel sudo[29490]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-25 15:00 Aug 25 15:01:04 volumiobetel sudo[29490]: 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="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"