-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Wed 2025-06-11 07:33:29 CEST. -- Jun 11 07:32:27 volumio go-librespot[1343]: time="2025-06-11T07:32:27+02:00" level=trace msg="sent dealer ping" Jun 11 07:32:27 volumio go-librespot[1343]: time="2025-06-11T07:32:27+02:00" level=trace msg="received dealer pong" Jun 11 07:32:57 volumio go-librespot[1343]: time="2025-06-11T07:32:57+02:00" level=trace msg="sent dealer ping" Jun 11 07:32:57 volumio go-librespot[1343]: time="2025-06-11T07:32:57+02:00" level=trace msg="received dealer pong" Jun 11 07:33:05 volumio go-librespot[1343]: time="2025-06-11T07:33:05+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 11 07:33:05 volumio go-librespot[1343]: time="2025-06-11T07:33:05+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 250" Jun 11 07:33:07 volumio go-librespot[1343]: time="2025-06-11T07:33:07+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 338" Jun 11 07:33:07 volumio go-librespot[1343]: time="2025-06-11T07:33:07+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 11 07:33:15 volumio go-librespot[1343]: time="2025-06-11T07:33:15+02:00" level=debug msg="handling transfer player command from 61bd3bfcec9253a75d94a09058f1ede08a81cd4c" Jun 11 07:33:15 volumio go-librespot[1343]: time="2025-06-11T07:33:15+02:00" level=debug msg="resolved context of track" uri="spotify:album:0Fys2W4ykWAcxY8iGeuMx9" Jun 11 07:33:15 volumio go-librespot[1343]: time="2025-06-11T07:33:15+02:00" level=trace msg="fetched new page 0 with 11 items (list: 11)" uri="spotify:album:0Fys2W4ykWAcxY8iGeuMx9" Jun 11 07:33:15 volumio go-librespot[1343]: time="2025-06-11T07:33:15+02:00" level=debug msg="loading track (paused: false, position: 9781ms)" uri="spotify:track:0yR9xqvqhf1mqDExTI4mZA" Jun 11 07:33:15 volumio go-librespot[1343]: time="2025-06-11T07:33:15+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 07:33:15 volumio go-librespot[1343]: time="2025-06-11T07:33:15+02:00" level=trace msg="emitting websocket event: will_play" Jun 11 07:33:15 volumio volumio[1032]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0yR9xqvqhf1mqDExTI4mZA","play_origin":"playlist"}} Jun 11 07:33:15 volumio go-librespot[1343]: time="2025-06-11T07:33:15+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jun 11 07:33:15 volumio go-librespot[1343]: time="2025-06-11T07:33:15+02:00" level=debug msg="selected format OGG_VORBIS_320 (c08cefff211908acd56030503e89cd63e36351f7)" uri="spotify:track:0yR9xqvqhf1mqDExTI4mZA" Jun 11 07:33:15 volumio go-librespot[1343]: time="2025-06-11T07:33:15+02:00" level=debug msg="requested aes key for file c08cefff211908acd56030503e89cd63e36351f7, gid: 0yR9xqvqhf1mqDExTI4mZA" Jun 11 07:33:15 volumio go-librespot[1343]: time="2025-06-11T07:33:15+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1708" Jun 11 07:33:16 volumio go-librespot[1343]: time="2025-06-11T07:33:16+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1298" Jun 11 07:33:16 volumio go-librespot[1343]: time="2025-06-11T07:33:16+02:00" level=debug msg="fetched first chunk of 23, total size is 11708644 bytes" uri="spotify:track:0yR9xqvqhf1mqDExTI4mZA" Jun 11 07:33:17 volumio go-librespot[1343]: time="2025-06-11T07:33:17+02:00" level=trace msg="seek to 9781ms (diff: 113ms, samples: 431342, bytes: 372248)" uri="spotify:track:0yR9xqvqhf1mqDExTI4mZA" Jun 11 07:33:17 volumio go-librespot[1343]: time="2025-06-11T07:33:17+02:00" level=debug msg="created new output device" Jun 11 07:33:17 volumio go-librespot[1343]: time="2025-06-11T07:33:17+02:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed setting stream for spotify:track:0yR9xqvqhf1mqDExTI4mZA: ALSA error at snd_pcm_open: Device or resource busy" Jun 11 07:33:17 volumio go-librespot[1343]: time="2025-06-11T07:33:17+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 11 07:33:17 volumio go-librespot[1343]: time="2025-06-11T07:33:17+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 11 07:33:17 volumio go-librespot[1343]: time="2025-06-11T07:33:17+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 11 07:33:17 volumio go-librespot[1343]: time="2025-06-11T07:33:17+02:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:0yR9xqvqhf1mqDExTI4mZA" Jun 11 07:33:17 volumio go-librespot[1343]: time="2025-06-11T07:33:17+02:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:0yR9xqvqhf1mqDExTI4mZA" Jun 11 07:33:17 volumio go-librespot[1343]: time="2025-06-11T07:33:17+02:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:0yR9xqvqhf1mqDExTI4mZA" Jun 11 07:33:20 volumio go-librespot[1343]: time="2025-06-11T07:33:20+02:00" level=debug msg="handling pause player command from 61bd3bfcec9253a75d94a09058f1ede08a81cd4c" Jun 11 07:33:20 volumio go-librespot[1343]: time="2025-06-11T07:33:20+02:00" level=debug msg="pause track at 9668ms" Jun 11 07:33:20 volumio go-librespot[1343]: time="2025-06-11T07:33:20+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 07:33:20 volumio go-librespot[1343]: time="2025-06-11T07:33:20+02:00" level=debug msg="sending successful reply for dealer request" Jun 11 07:33:21 volumio go-librespot[1343]: time="2025-06-11T07:33:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 11 07:33:21 volumio go-librespot[1343]: time="2025-06-11T07:33:21+02:00" level=trace msg="emitting websocket event: paused" Jun 11 07:33:21 volumio volumio[1032]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0yR9xqvqhf1mqDExTI4mZA","play_origin":"playlist"}} Jun 11 07:33:21 volumio volumio[1032]: info: Spotify is playing in volatile mode Jun 11 07:33:21 volumio volumio[1032]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 11 07:33:21 volumio volumio[1032]: SPOTIFY: UNSET VOLATILE Jun 11 07:33:21 volumio volumio[1032]: SPOTIFY: {"status":"stop","position":0,"title":"80s80s Party","albumart":"/albumart?sourceicon=music_service/80s80s/images/80s80s-party-cover.png","uri":"http://streams.80s80s.de/party/mp3-192/volumio","trackType":"80s80s Radio","seek":252,"duration":1000,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"80s80s Radio","updatedb":false,"volatile":false,"service":"80s80s"} Jun 11 07:33:21 volumio volumio[1032]: SPOTIFY: PUSH STATE SPOTIFY Jun 11 07:33:21 volumio volumio[1032]: SPOTIFY: {"status":"pause","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 11 07:33:21 volumio volumio[1032]: info: CoreCommandRouter::servicePushState Jun 11 07:33:21 volumio volumio[1032]: info: CoreStateMachine::pushState Jun 11 07:33:21 volumio volumio[1032]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 11 07:33:21 volumio volumio[1032]: info: CoreCommandRouter::volumioPushState Jun 11 07:33:27 volumio go-librespot[1343]: time="2025-06-11T07:33:27+02:00" level=trace msg="sent dealer ping" Jun 11 07:33:27 volumio go-librespot[1343]: time="2025-06-11T07:33:27+02:00" level=trace msg="received dealer pong" Jun 11 07:33:28 volumio volumio[1032]: info: [1749620008615] [80s80s] Pushing the next song state Prince - 1999 and getting next track. Jun 11 07:33:28 volumio volumio[1032]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 11 07:33:28 volumio volumio[1032]: TypeError: Cannot set property 'name' of undefined Jun 11 07:33:28 volumio volumio[1032]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Jun 11 07:33:28 volumio volumio[1032]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Jun 11 07:33:28 volumio volumio[1032]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Jun 11 07:33:28 volumio volumio[1032]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Jun 11 07:33:28 volumio volumio[1032]: at processImmediate (internal/timers.js:461:21) Jun 11 07:33:28 volumio volumio[1032]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 11 07:33:29 volumio sudo[2483]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-11 07:32 Jun 11 07:33:29 volumio sudo[2483]: 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="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"