-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Tue 2025-05-13 18:14:51 CEST. -- May 13 18:13:02 volumio go-librespot[1346]: time="2025-05-13T18:13:02+02:00" level=trace msg="sent dealer ping" May 13 18:13:02 volumio go-librespot[1346]: time="2025-05-13T18:13:02+02:00" level=trace msg="received dealer pong" May 13 18:13:05 volumio volumio[1038]: verbose: New Socket.io Connection to 192.168.89.192 from 192.168.89.220 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/136.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::volumioGetVisibleSources May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::volumioGetState May 13 18:13:05 volumio volumio[1038]: info: CorePlayQueue::getTrack 0 May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::volumioGetQueue May 13 18:13:05 volumio volumio[1038]: info: CoreStateMachine::getQueue May 13 18:13:05 volumio volumio[1038]: info: CorePlayQueue::getQueue May 13 18:13:05 volumio volumio[1038]: info: Listing playlists May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom May 13 18:13:05 volumio volumio[1038]: info: Received Get System Info May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 13 18:13:05 volumio volumio[1038]: info: Discovery: Getting this device information May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::volumioGetState May 13 18:13:05 volumio volumio[1038]: info: CorePlayQueue::getTrack 0 May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::volumioGetState May 13 18:13:05 volumio volumio[1038]: info: CorePlayQueue::getTrack 0 May 13 18:13:05 volumio volumio[1038]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache May 13 18:13:06 volumio volumio[1038]: info: CoreCommandRouter::volumioPause May 13 18:13:06 volumio volumio[1038]: info: CoreStateMachine::pause May 13 18:13:06 volumio volumio[1038]: info: CoreStateMachine::stPlaybackTimer May 13 18:13:06 volumio volumio[1038]: info: CoreStateMachine::servicePause May 13 18:13:06 volumio volumio[1038]: info: CorePlayQueue::getTrack 0 May 13 18:13:06 volumio volumio[1038]: info: CoreCommandRouter::servicePause May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::sendMpdCommand pause May 13 18:13:06 volumio volumio[1038]: info: May 13 18:13:06 volumio volumio[1038]: ---------------------------- MPD announces state update: player May 13 18:13:06 volumio volumio[1038]: info: sendMpdCommand pause took 3 milliseconds May 13 18:13:06 volumio volumio[1038]: info: ControllerMpd::getState May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::sendMpdCommand status May 13 18:13:06 volumio volumio[1038]: info: CorePlayQueue::getTrack 0 May 13 18:13:06 volumio volumio[1038]: info: CoreCommandRouter::servicePushState May 13 18:13:06 volumio volumio[1038]: info: CorePlayQueue::getTrack 0 May 13 18:13:06 volumio volumio[1038]: verbose: STATE SERVICE {"status":"pause","service":"80s80s","type":"track","trackType":"80s80s Radio","radioType":"80s80s","albumart":"https://is1-ssl.mzstatic.com/image/thumb/Music122/v4/56/71/eb/5671ebb2-97f1-ebcf-ea1b-fdd38bd8da35/source/600x600bb.jpg","name":"Markus - Kleine Taschenlampe brenn'","title":"Kleine Taschenlampe brenn'","artist":"80s80s Love","album":"","streaming":true,"disableUiControls":true,"duration":"187","seek":83508,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2} May 13 18:13:06 volumio volumio[1038]: verbose: CURRENT POSITION 0 May 13 18:13:06 volumio volumio[1038]: info: CoreStateMachine::syncState stateService pause May 13 18:13:06 volumio volumio[1038]: info: CoreStateMachine::syncState currentStatus pause May 13 18:13:06 volumio volumio[1038]: info: CoreStateMachine::pushState May 13 18:13:06 volumio volumio[1038]: info: CorePlayQueue::getTrack 0 May 13 18:13:06 volumio volumio[1038]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 13 18:13:06 volumio volumio[1038]: info: CoreCommandRouter::volumioPushState May 13 18:13:06 volumio volumio[1038]: info: CoreStateMachine::stPlaybackTimer May 13 18:13:06 volumio volumio[1038]: info: May 13 18:13:06 volumio volumio[1038]: ---------------------------- MPD announces state update: player May 13 18:13:06 volumio volumio[1038]: info: ControllerMpd::getState May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::sendMpdCommand status May 13 18:13:06 volumio volumio[1038]: info: May 13 18:13:06 volumio volumio[1038]: ---------------------------- MPD announces state update: player May 13 18:13:06 volumio volumio[1038]: info: ControllerMpd::getState May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::sendMpdCommand status May 13 18:13:06 volumio volumio[1038]: info: sendMpdCommand status took 24 milliseconds May 13 18:13:06 volumio volumio[1038]: info: sendMpdCommand status took 6 milliseconds May 13 18:13:06 volumio volumio[1038]: info: sendMpdCommand status took 3 milliseconds May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::parseState May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::parseState May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::parseState May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 13 18:13:06 volumio volumio[1038]: info: sendMpdCommand playlistinfo took 7 milliseconds May 13 18:13:06 volumio volumio[1038]: info: sendMpdCommand playlistinfo took 7 milliseconds May 13 18:13:06 volumio volumio[1038]: info: sendMpdCommand playlistinfo took 6 milliseconds May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::parseTrackInfo May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::parseTrackInfo May 13 18:13:06 volumio volumio[1038]: verbose: ControllerMpd::parseTrackInfo May 13 18:13:06 volumio volumio[1038]: info: ControllerMpd::pushState May 13 18:13:06 volumio volumio[1038]: info: CoreCommandRouter::servicePushState May 13 18:13:06 volumio volumio[1038]: info: CorePlayQueue::getTrack 0 May 13 18:13:06 volumio volumio[1038]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd May 13 18:13:06 volumio volumio[1038]: info: ControllerMpd::pushState May 13 18:13:06 volumio volumio[1038]: info: CoreCommandRouter::servicePushState May 13 18:13:06 volumio volumio[1038]: info: CorePlayQueue::getTrack 0 May 13 18:13:06 volumio volumio[1038]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd May 13 18:13:06 volumio volumio[1038]: info: ControllerMpd::pushState May 13 18:13:06 volumio volumio[1038]: info: CoreCommandRouter::servicePushState May 13 18:13:06 volumio volumio[1038]: info: CorePlayQueue::getTrack 0 May 13 18:13:06 volumio volumio[1038]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd May 13 18:13:06 volumio volumio[1038]: info: ------------------------------ 42ms May 13 18:13:06 volumio volumio[1038]: info: ------------------------------ 23ms May 13 18:13:06 volumio volumio[1038]: info: ------------------------------ 21ms May 13 18:13:22 volumio go-librespot[1346]: time="2025-05-13T18:13:22+02:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update May 13 18:13:22 volumio go-librespot[1346]: time="2025-05-13T18:13:22+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 157" May 13 18:13:26 volumio go-librespot[1346]: time="2025-05-13T18:13:26+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 348" May 13 18:13:26 volumio go-librespot[1346]: time="2025-05-13T18:13:26+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 348" May 13 18:13:26 volumio go-librespot[1346]: time="2025-05-13T18:13:26+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 13 18:13:26 volumio go-librespot[1346]: time="2025-05-13T18:13:26+02:00" level=debug msg="handling transfer player command from 61bd3bfcec9253a75d94a09058f1ede08a81cd4c" May 13 18:13:26 volumio go-librespot[1346]: time="2025-05-13T18:13:26+02:00" level=debug msg="resolved context of track" uri="spotify:search:roses+imanbek+remix" May 13 18:13:26 volumio go-librespot[1346]: time="2025-05-13T18:13:26+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:search:roses+imanbek+remix" May 13 18:13:26 volumio go-librespot[1346]: time="2025-05-13T18:13:26+02:00" level=debug msg="loading track (paused: false, position: 6308ms)" uri="spotify:track:24Yi9hE78yPEbZ4kxyoXAI" May 13 18:13:27 volumio go-librespot[1346]: time="2025-05-13T18:13:27+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 13 18:13:27 volumio go-librespot[1346]: time="2025-05-13T18:13:27+02:00" level=trace msg="emitting websocket event: will_play" May 13 18:13:27 volumio volumio[1038]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:24Yi9hE78yPEbZ4kxyoXAI","play_origin":"search"}} May 13 18:13:27 volumio go-librespot[1346]: time="2025-05-13T18:13:27+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 13 18:13:27 volumio go-librespot[1346]: time="2025-05-13T18:13:27+02:00" level=debug msg="selected format OGG_VORBIS_320 (c5c6b4ce784d164b7b4dfa3d8b74e2c15e894578)" uri="spotify:track:24Yi9hE78yPEbZ4kxyoXAI" May 13 18:13:27 volumio go-librespot[1346]: time="2025-05-13T18:13:27+02:00" level=debug msg="requested aes key for file c5c6b4ce784d164b7b4dfa3d8b74e2c15e894578, gid: 24Yi9hE78yPEbZ4kxyoXAI" May 13 18:13:27 volumio go-librespot[1346]: time="2025-05-13T18:13:27+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1708" May 13 18:13:27 volumio go-librespot[1346]: time="2025-05-13T18:13:27+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1298" May 13 18:13:27 volumio go-librespot[1346]: time="2025-05-13T18:13:27+02:00" level=debug msg="fetched first chunk of 15, total size is 7685280 bytes" uri="spotify:track:24Yi9hE78yPEbZ4kxyoXAI" May 13 18:13:27 volumio go-librespot[1346]: time="2025-05-13T18:13:27+02:00" level=trace msg="seek to 6308ms (diff: 117ms, samples: 278182, bytes: 220435)" uri="spotify:track:24Yi9hE78yPEbZ4kxyoXAI" May 13 18:13:27 volumio go-librespot[1346]: time="2025-05-13T18:13:27+02:00" level=debug msg="created new output device" May 13 18:13:27 volumio kernel: bcm2835-i2s 3f203000.i2s: I2S SYNC error! May 13 18:13:27 volumio go-librespot[1346]: time="2025-05-13T18:13:27+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" May 13 18:13:27 volumio go-librespot[1346]: time="2025-05-13T18:13:27+02:00" level=info msg="loaded track \"Roses - Imanbek Remix\" (paused: false, position: 6308ms, duration: 176840ms, prefetched: false)" uri="spotify:track:24Yi9hE78yPEbZ4kxyoXAI" May 13 18:13:28 volumio go-librespot[1346]: time="2025-05-13T18:13:28+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 13 18:13:28 volumio go-librespot[1346]: time="2025-05-13T18:13:28+02:00" level=trace msg="scheduling prefetch in 140s" May 13 18:13:28 volumio go-librespot[1346]: time="2025-05-13T18:13:28+02:00" level=trace msg="emitting websocket event: metadata" May 13 18:13:28 volumio go-librespot[1346]: time="2025-05-13T18:13:28+02:00" level=trace msg="emitting websocket event: active" May 13 18:13:28 volumio go-librespot[1346]: time="2025-05-13T18:13:28+02:00" level=debug msg="sending successful reply for dealer request" May 13 18:13:28 volumio volumio[1038]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:24Yi9hE78yPEbZ4kxyoXAI","name":"Roses - Imanbek Remix","artist_names":["SAINt JHN","Imanbek"],"album_name":"Roses (Imanbek Remix)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b340b496cb7c38d727ff40be","position":6308,"duration":176840,"release_date":"year:2019 month:10 day:9","track_number":1,"disc_number":1}} May 13 18:13:28 volumio volumio[1038]: SPOTIFY: received: {"type":"active","data":null} May 13 18:13:28 volumio volumio[1038]: info: Aligning Spotify Volume to Volumio Volume May 13 18:13:28 volumio volumio[1038]: info: CoreCommandRouter::volumioGetState May 13 18:13:28 volumio volumio[1038]: info: CorePlayQueue::getTrack 0 May 13 18:13:28 volumio go-librespot[1346]: time="2025-05-13T18:13:28+02:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:24Yi9hE78yPEbZ4kxyoXAI" May 13 18:13:28 volumio go-librespot[1346]: time="2025-05-13T18:13:28+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 13 18:13:28 volumio go-librespot[1346]: time="2025-05-13T18:13:28+02:00" level=trace msg="emitting websocket event: playing" May 13 18:13:28 volumio volumio[1038]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:24Yi9hE78yPEbZ4kxyoXAI","play_origin":"search"}} May 13 18:13:28 volumio volumio[1038]: info: Spotify is playing in volatile mode May 13 18:13:28 volumio volumio[1038]: info: CoreStateMachine::setConsumeUpdateService undefined May 13 18:13:28 volumio volumio[1038]: SPOTIFY: UNSET VOLATILE May 13 18:13:28 volumio go-librespot[1346]: time="2025-05-13T18:13:28+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 13 18:13:28 volumio volumio[1038]: SPOTIFY: {"status":"pause","position":0,"title":"Markus - Kleine Taschenlampe brenn'","artist":"80s80s Love","album":"","albumart":"https://is1-ssl.mzstatic.com/image/thumb/Music122/v4/56/71/eb/5671ebb2-97f1-ebcf-ea1b-fdd38bd8da35/source/600x600bb.jpg","uri":"http://streams.80s80s.de/love/mp3-192/volumio","trackType":"80s80s Radio","seek":83508,"duration":"187","samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"80s80s Radio","volatile":false,"service":"80s80s"} May 13 18:13:28 volumio volumio[1038]: info: Setting Spotify stop after unset volatile call May 13 18:13:28 volumio go-librespot[1346]: time="2025-05-13T18:13:28+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 13 18:13:28 volumio go-librespot[1346]: time="2025-05-13T18:13:28+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 13 18:13:28 volumio volumio[1038]: SPOTIFY: PUSH STATE SPOTIFY May 13 18:13:28 volumio volumio[1038]: SPOTIFY: {"status":"play","service":"spop","title":"Roses - Imanbek Remix","artist":"SAINt JHN, Imanbek","album":"Roses (Imanbek Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02b340b496cb7c38d727ff40be","uri":"spotify:track:24Yi9hE78yPEbZ4kxyoXAI","trackType":"spotify","seek":6308,"duration":176,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 13 18:13:28 volumio volumio[1038]: info: CoreCommandRouter::servicePushState May 13 18:13:28 volumio volumio[1038]: info: CoreStateMachine::pushState May 13 18:13:28 volumio volumio[1038]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 13 18:13:28 volumio volumio[1038]: info: CoreCommandRouter::volumioPushState May 13 18:13:28 volumio volumio[1038]: SPOTIFY: PUSH STATE SPOTIFY May 13 18:13:28 volumio volumio[1038]: SPOTIFY: {"status":"play","service":"spop","title":"Roses - Imanbek Remix","artist":"SAINt JHN, Imanbek","album":"Roses (Imanbek Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02b340b496cb7c38d727ff40be","uri":"spotify:track:24Yi9hE78yPEbZ4kxyoXAI","trackType":"spotify","seek":6308,"duration":176,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 13 18:13:28 volumio volumio[1038]: info: CoreCommandRouter::servicePushState May 13 18:13:28 volumio volumio[1038]: info: CoreStateMachine::pushState May 13 18:13:28 volumio volumio[1038]: info: CoreCommandRouter::volumioPushState May 13 18:13:28 volumio volumio[1038]: info: Spotify Stop May 13 18:13:28 volumio volumio[1038]: SPOTIFY: SPOTIFY STOP May 13 18:13:28 volumio volumio[1038]: SPOTIFY: {"status":"play","title":"Roses - Imanbek Remix","artist":"SAINt JHN, Imanbek","album":"Roses (Imanbek Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e02b340b496cb7c38d727ff40be","uri":"spotify:track:24Yi9hE78yPEbZ4kxyoXAI","trackType":"spotify","codec":"ogg","seek":6308,"duration":176,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":100,"dbVolume":null,"mute":false,"disableVolumeControl":true,"stream":false,"volatile":true,"service":"spop"} May 13 18:13:28 volumio go-librespot[1346]: time="2025-05-13T18:13:28+02:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:24Yi9hE78yPEbZ4kxyoXAI" May 13 18:13:29 volumio go-librespot[1346]: time="2025-05-13T18:13:29+02:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:24Yi9hE78yPEbZ4kxyoXAI" May 13 18:13:32 volumio go-librespot[1346]: time="2025-05-13T18:13:32+02:00" level=trace msg="received accesspoint ping" May 13 18:13:32 volumio go-librespot[1346]: time="2025-05-13T18:13:32+02:00" level=trace msg="received accesspoint pong ack" May 13 18:13:32 volumio go-librespot[1346]: time="2025-05-13T18:13:32+02:00" level=trace msg="sent dealer ping" May 13 18:13:32 volumio go-librespot[1346]: time="2025-05-13T18:13:32+02:00" level=trace msg="received dealer pong" May 13 18:13:35 volumio go-librespot[1346]: time="2025-05-13T18:13:35+02:00" level=debug msg="fetched chunk 4/14, size: 524288" uri="spotify:track:24Yi9hE78yPEbZ4kxyoXAI" May 13 18:13:46 volumio go-librespot[1346]: time="2025-05-13T18:13:46+02:00" level=debug msg="handling play player command from 61bd3bfcec9253a75d94a09058f1ede08a81cd4c" May 13 18:13:46 volumio go-librespot[1346]: time="2025-05-13T18:13:46+02:00" level=debug msg="resolved context of track" uri="spotify:search:alors+on+danse" May 13 18:13:46 volumio go-librespot[1346]: time="2025-05-13T18:13:46+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:search:alors+on+danse" May 13 18:13:46 volumio go-librespot[1346]: time="2025-05-13T18:13:46+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2GYHyAoLWpkxLVa4oYTVko" May 13 18:13:46 volumio go-librespot[1346]: time="2025-05-13T18:13:46+02:00" level=debug msg="fetched chunk 5/14, size: 524288" uri="spotify:track:24Yi9hE78yPEbZ4kxyoXAI" May 13 18:13:46 volumio go-librespot[1346]: time="2025-05-13T18:13:46+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 13 18:13:46 volumio go-librespot[1346]: time="2025-05-13T18:13:46+02:00" level=trace msg="emitting websocket event: will_play" May 13 18:13:46 volumio volumio[1038]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2GYHyAoLWpkxLVa4oYTVko","play_origin":"search"}} May 13 18:13:46 volumio go-librespot[1346]: time="2025-05-13T18:13:46+02:00" level=debug msg="selected format OGG_VORBIS_320 (21df83d4ee20733e2cdc819ec72d80ce54020383)" uri="spotify:track:2GYHyAoLWpkxLVa4oYTVko" May 13 18:13:46 volumio go-librespot[1346]: time="2025-05-13T18:13:46+02:00" level=debug msg="requested aes key for file 21df83d4ee20733e2cdc819ec72d80ce54020383, gid: 2GYHyAoLWpkxLVa4oYTVko" May 13 18:13:47 volumio go-librespot[1346]: time="2025-05-13T18:13:47+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 152" May 13 18:13:47 volumio go-librespot[1346]: time="2025-05-13T18:13:47+02:00" level=debug msg="fetched first chunk of 18, total size is 9302932 bytes" uri="spotify:track:2GYHyAoLWpkxLVa4oYTVko" May 13 18:13:47 volumio go-librespot[1346]: time="2025-05-13T18:13:47+02:00" level=info msg="loaded track \"Alors on danse - Radio Edit\" (paused: false, position: 0ms, duration: 206066ms, prefetched: false)" uri="spotify:track:2GYHyAoLWpkxLVa4oYTVko" May 13 18:13:47 volumio go-librespot[1346]: time="2025-05-13T18:13:47+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 13 18:13:47 volumio go-librespot[1346]: time="2025-05-13T18:13:47+02:00" level=trace msg="scheduling prefetch in 176s" May 13 18:13:47 volumio go-librespot[1346]: time="2025-05-13T18:13:47+02:00" level=trace msg="emitting websocket event: metadata" May 13 18:13:47 volumio go-librespot[1346]: time="2025-05-13T18:13:47+02:00" level=debug msg="sending successful reply for dealer request" May 13 18:13:47 volumio go-librespot[1346]: time="2025-05-13T18:13:47+02:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update May 13 18:13:47 volumio volumio[1038]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2GYHyAoLWpkxLVa4oYTVko","name":"Alors on danse - Radio Edit","artist_names":["Stromae"],"album_name":"Cheese","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ae373174b14e3eac81554402","position":0,"duration":206066,"release_date":"year:2010 month:1 day:1","track_number":5,"disc_number":1}} May 13 18:13:48 volumio go-librespot[1346]: time="2025-05-13T18:13:48+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 13 18:13:48 volumio go-librespot[1346]: time="2025-05-13T18:13:48+02:00" level=trace msg="emitting websocket event: playing" May 13 18:13:48 volumio volumio[1038]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2GYHyAoLWpkxLVa4oYTVko","play_origin":"search"}} May 13 18:13:48 volumio volumio[1038]: SPOTIFY: PUSH STATE SPOTIFY May 13 18:13:48 volumio volumio[1038]: SPOTIFY: {"status":"play","service":"spop","title":"Alors on danse - Radio Edit","artist":"Stromae","album":"Cheese","albumart":"https://i.scdn.co/image/ab67616d00001e02ae373174b14e3eac81554402","uri":"spotify:track:2GYHyAoLWpkxLVa4oYTVko","trackType":"spotify","seek":0,"duration":206,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 13 18:13:48 volumio volumio[1038]: info: CoreCommandRouter::servicePushState May 13 18:13:48 volumio volumio[1038]: info: CoreStateMachine::pushState May 13 18:13:48 volumio volumio[1038]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 13 18:13:48 volumio volumio[1038]: info: CoreCommandRouter::volumioPushState May 13 18:13:48 volumio go-librespot[1346]: time="2025-05-13T18:13:48+02:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:2GYHyAoLWpkxLVa4oYTVko" May 13 18:13:48 volumio volumio[1038]: SPOTIFY: PUSH STATE SPOTIFY May 13 18:13:48 volumio volumio[1038]: SPOTIFY: {"status":"play","service":"spop","title":"Alors on danse - Radio Edit","artist":"Stromae","album":"Cheese","albumart":"https://i.scdn.co/image/ab67616d00001e02ae373174b14e3eac81554402","uri":"spotify:track:2GYHyAoLWpkxLVa4oYTVko","trackType":"spotify","seek":0,"duration":206,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 13 18:13:48 volumio volumio[1038]: info: CoreCommandRouter::servicePushState May 13 18:13:48 volumio volumio[1038]: info: CoreStateMachine::pushState May 13 18:13:48 volumio volumio[1038]: info: CoreCommandRouter::volumioPushState May 13 18:13:48 volumio go-librespot[1346]: time="2025-05-13T18:13:48+02:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:2GYHyAoLWpkxLVa4oYTVko" May 13 18:13:48 volumio go-librespot[1346]: time="2025-05-13T18:13:48+02:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:2GYHyAoLWpkxLVa4oYTVko" May 13 18:14:00 volumio go-librespot[1346]: time="2025-05-13T18:14:00+02:00" level=debug msg="fetched chunk 4/17, size: 524288" uri="spotify:track:2GYHyAoLWpkxLVa4oYTVko" May 13 18:14:02 volumio go-librespot[1346]: time="2025-05-13T18:14:02+02:00" level=trace msg="sent dealer ping" May 13 18:14:02 volumio go-librespot[1346]: time="2025-05-13T18:14:02+02:00" level=trace msg="received dealer pong" May 13 18:14:11 volumio go-librespot[1346]: time="2025-05-13T18:14:11+02:00" level=debug msg="fetched chunk 5/17, size: 524288" uri="spotify:track:2GYHyAoLWpkxLVa4oYTVko" May 13 18:14:22 volumio go-librespot[1346]: time="2025-05-13T18:14:22+02:00" level=debug msg="fetched chunk 6/17, size: 524288" uri="spotify:track:2GYHyAoLWpkxLVa4oYTVko" May 13 18:14:32 volumio go-librespot[1346]: time="2025-05-13T18:14:32+02:00" level=trace msg="sent dealer ping" May 13 18:14:33 volumio go-librespot[1346]: time="2025-05-13T18:14:33+02:00" level=trace msg="received dealer pong" May 13 18:14:45 volumio go-librespot[1346]: time="2025-05-13T18:14:45+02:00" level=debug msg="fetched chunk 8/17, size: 524288" uri="spotify:track:2GYHyAoLWpkxLVa4oYTVko" May 13 18:14:49 volumio go-librespot[1346]: time="2025-05-13T18:14:49+02:00" level=debug msg="fetched chunk 7/17, size: 524288" uri="spotify:track:2GYHyAoLWpkxLVa4oYTVko" May 13 18:14:51 volumio volumio[1038]: info: [1747152891347] [80s80s] Pushing the next song state Markus - Kleine Taschenlampe brenn' and getting next track. May 13 18:14:51 volumio volumio[1038]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 13 18:14:51 volumio volumio[1038]: TypeError: Cannot set property 'name' of undefined May 13 18:14:51 volumio volumio[1038]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) May 13 18:14:51 volumio volumio[1038]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) May 13 18:14:51 volumio volumio[1038]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) May 13 18:14:51 volumio volumio[1038]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) May 13 18:14:51 volumio volumio[1038]: at processImmediate (internal/timers.js:461:21) May 13 18:14:51 volumio volumio[1038]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 13 18:14:51 volumio sudo[2108]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-13 18:13 May 13 18:14:51 volumio sudo[2108]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"