Dec 11 16:28:00 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:00 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:01 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:01 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:02 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:02 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:03 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:03 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:04 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:04 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:05 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:05 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:06 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:06+01:00" level=trace msg="sent dealer ping" Dec 11 16:28:06 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:06+01:00" level=trace msg="received dealer pong" Dec 11 16:28:06 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:06 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:06 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:06 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:06 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:28:06 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:28:06 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:28:06 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:28:06 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:06 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:07 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:07 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:08 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:08 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:09 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:09 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:10 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:10 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:11 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:11 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:12 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:12 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:13 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:13+01:00" level=debug msg="skipping dealer message" uri="hm://herodotus/uri/spotify:episode:51crgrAy4dDEDhQi6WcaLT/resume-point-revision/44bf43b8-0fc1-4e65-a232-f2e42e644c30" Dec 11 16:28:13 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:13+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 287" Dec 11 16:28:13 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:13 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:14 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:14 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:15 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:15 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:16 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:16 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:16 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:16 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:16 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:16 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:17+01:00" level=debug msg="handling transfer player command from 262ee45809a796cc4edb1939a319fec5a484bc81" Dec 11 16:28:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:17+01:00" level=debug msg="resolved context of episode" uri="spotify:show:5ZW8phuJoLC1go6GoHhY2x" Dec 11 16:28:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:17+01:00" level=trace msg="fetched new page 0 with 76 items (list: 76)" uri="spotify:show:5ZW8phuJoLC1go6GoHhY2x" Dec 11 16:28:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:17+01:00" level=debug msg="loading episode (paused: false, position: 1713913ms)" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:17 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:17 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:18 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:18 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:19 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:19 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:20 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:20 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:21 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:21 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:22 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:22+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 11 16:28:22 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:22+01:00" level=trace msg="emitting websocket event: will_play" Dec 11 16:28:22 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:show:5ZW8phuJoLC1go6GoHhY2x","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","play_origin":"com.spotify.service.podcastepisode"}} Dec 11 16:28:22 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:22 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:22 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:22+01:00" level=debug msg="selected format OGG_VORBIS_96 (a550deae223bb52cb893e07be6aaf41e5869fb4c)" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:22 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:22+01:00" level=debug msg="requested aes key for file a550deae223bb52cb893e07be6aaf41e5869fb4c, gid: 51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:22 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:22+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Dec 11 16:28:22 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:22+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1370" Dec 11 16:28:22 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:22+01:00" level=trace msg="found 2 cdn urls" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:23 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:23+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1131" Dec 11 16:28:23 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:23+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 287" Dec 11 16:28:23 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:23 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:24 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:24 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:25 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:25 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:26 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:26 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:26 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:26 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:26 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:28:26 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:28:26 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:28:26 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:28:26 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:26 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:27 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:27 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="fetched first chunk of 63, total size is 32693141 bytes" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="fetched chunk 1/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="fetched chunk 3/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="fetched chunk 2/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="fetched chunk 32/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=trace msg="seek to 1713913ms (diff: 782ms, samples: 75583563, bytes: 16876642)" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="created new output device" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 185759 us, period size = 8192 frames, buffer time = 743038 us, buffer size = 32768 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=info msg="loaded episode \"Der Bobcast - Advent, Advent ...\" (paused: false, position: 1713913ms, duration: 3342863ms, prefetched: false)" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="fetched chunk 33/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=trace msg="scheduling prefetch in 1600s" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=trace msg="emitting websocket event: metadata" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=trace msg="emitting websocket event: active" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="sending successful reply for dealer request" Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","name":"Der Bobcast - Advent, Advent ...","artist_names":["Haschimitenfürst – Der Bobcast"],"album_name":"Haschimitenfürst – Der Bobcast","album_cover_url":"https://i.scdn.co/image/ab6765630000f68d094cd853ffa40887d2d9f5ed","position":1713913,"duration":3342863,"release_date":"","track_number":0,"disc_number":0}} Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"active","data":null} Dec 11 16:28:28 volumio-215 volumio[14518]: info: Aligning Spotify Volume to Volumio Volume Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:28 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:28 volumio-215 volumio[14518]: info: Setting Spotify Volume from Volumio: 35 Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=trace msg="emitting websocket event: playing" Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:show:5ZW8phuJoLC1go6GoHhY2x","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","resume":false,"play_origin":"com.spotify.service.podcastepisode"}} Dec 11 16:28:28 volumio-215 volumio[14518]: info: Spotify is playing in volatile mode Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=info msg="playback was transferred to iPhone" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=trace msg="closed output device because of stop command" Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="fetched chunk 34/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: UNSET VOLATILE Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: {"status":"play","position":0,"title":"The Pointer Sisters - Santa Claus Is Coming to Town","artist":"80s80s Real 80s Radio","album":"","albumart":"https://is5-ssl.mzstatic.com/image/thumb/Music/v4/bd/8f/2f/bd8f2ffb-9879-34a4-9f16-072c2c2bb8b2/source/600x600bb.jpg","uri":"http://streams.80s80s.de/web/mp3-192/volumio","trackType":"80s80s Radio","seek":0,"duration":"172","samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":35,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"80s80s Radio","volatile":false,"service":"80s80s"} Dec 11 16:28:28 volumio-215 volumio[14518]: info: Setting Spotify stop after unset volatile call Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: PUSH STATE SPOTIFY Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: {"status":"play","service":"spop","title":"Der Bobcast - Advent, Advent ...","artist":"Haschimitenfürst – Der Bobcast","album":"Haschimitenfürst – Der Bobcast","albumart":"https://i.scdn.co/image/ab6765630000f68d094cd853ffa40887d2d9f5ed","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","trackType":"spotify","seek":1713913,"duration":3342,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreCommandRouter::servicePushState Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreStateMachine::pushState Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioPushState Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="put connect state inactive" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=trace msg="emitting websocket event: inactive" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=trace msg="emitting websocket event: stopped" Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"inactive","data":null} Dec 11 16:28:28 volumio-215 volumio[14518]: error: Failed to decode event: inactive Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: PUSH STATE SPOTIFY Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: {"status":"stop","service":"spop","title":"Der Bobcast - Advent, Advent ...","artist":"Haschimitenfürst – Der Bobcast","album":"Haschimitenfürst – Der Bobcast","albumart":"https://i.scdn.co/image/ab6765630000f68d094cd853ffa40887d2d9f5ed","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","trackType":"spotify","seek":1713913,"duration":3342,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreCommandRouter::servicePushState Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreStateMachine::pushState Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioPushState Dec 11 16:28:28 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:28 volumio-215 volumio[14518]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received spop Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="dealer recv loop stopped" Dec 11 16:28:28 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:28+01:00" level=debug msg="fetched chunk 35/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: PUSH STATE SPOTIFY Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: {"status":"stop","service":"spop","title":"Der Bobcast - Advent, Advent ...","artist":"Haschimitenfürst – Der Bobcast","album":"Haschimitenfürst – Der Bobcast","albumart":"https://i.scdn.co/image/ab6765630000f68d094cd853ffa40887d2d9f5ed","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","trackType":"spotify","seek":1713913,"duration":3342,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreCommandRouter::servicePushState Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreStateMachine::pushState Dec 11 16:28:28 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioPushState Dec 11 16:28:28 volumio-215 volumio[14518]: info: CorePlayQueue::getTrack 0 Dec 11 16:28:28 volumio-215 volumio[14518]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received spop Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Dec 11 16:28:28 volumio-215 volumio[14518]: info: Spotify Stop Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: SPOTIFY STOP Dec 11 16:28:28 volumio-215 volumio[14518]: SPOTIFY: {"status":"stop","title":"Der Bobcast - Advent, Advent ...","artist":"Haschimitenfürst – Der Bobcast","album":"Haschimitenfürst – Der Bobcast","albumart":"https://i.scdn.co/image/ab6765630000f68d094cd853ffa40887d2d9f5ed","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","trackType":"spotify","codec":"ogg","seek":1713913,"duration":3342,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":35,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Dec 11 16:28:29 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:29 volumio-215 volumio[14518]: SPOTIFY: SETTING SPOTIFY VOLUME 35 Dec 11 16:28:29 volumio-215 volumio[14518]: info: Sending Spotify command with payload to local API: /player/volume Dec 11 16:28:30 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:31 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:32 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:33 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:33+01:00" level=debug msg="obtained new client token: AACtp6PwkckN479aLcUEFTXAbMff7SQA3I7UnytGSQjehAZVGRN8qs+l1xaqbmwJrsCasS7bq0uEeZoGP8RtohxZNPliOWV0FUDQumKJZR+StqrkT9qeeNtluyriMoClbxnOhM0Gx+zJOqecbYuUDw6pQaJoQLn0Fx9oDpkC4ThTHG5GZNA00yIQ6Hzb/jz+JXX1osp8t8+AwF2R7WwXQgp12yhem3qDndz6vZsOE+XV7pKMWQIFHDlt" Dec 11 16:28:33 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:34 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:35 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:36 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:36 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:36 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:37 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:38 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:38 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:38+01: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-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 11 16:28:38 volumio-215 systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 11 16:28:39 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:40 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:41 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:42 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:43 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:43 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:43+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 11 16:28:43 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:43+01:00" level=debug msg="completed keyexchange" Dec 11 16:28:43 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:43+01:00" level=debug msg="completed challenge" Dec 11 16:28:43 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:43+01:00" level=info msg="authenticated AP" username="31************************6y" Dec 11 16:28:44 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:44 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:45 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:46 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:46 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:46 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:28:46 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:28:46 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:28:46 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:28:46 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:47 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:48 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:48 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:48+01:00" level=info msg="authenticated Login5" username="31************************6y" Dec 11 16:28:48 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:48+01: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]" Dec 11 16:28:48 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:48+01:00" level=debug msg="restored session after logout" username="31************************6y" Dec 11 16:28:49 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:50 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:51 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:52 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:53 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=debug msg="dealer connection opened" Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=trace msg="starting accesspoint recv loop" Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=trace msg="starting dealer recv loop" Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=trace msg="received accesspoint ping" Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 287" Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=debug msg="received connection id: YmYyMmI0YTktYWQz...RjFERjgwQjdDRQ==" Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=trace msg="received accesspoint pong ack" Dec 11 16:28:53 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:53+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 11 16:28:54 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:55 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:55 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:55+01:00" level=debug msg="handling transfer player command from 262ee45809a796cc4edb1939a319fec5a484bc81" Dec 11 16:28:55 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:55+01:00" level=debug msg="resolved context of episode" uri="spotify:show:5ZW8phuJoLC1go6GoHhY2x" Dec 11 16:28:55 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:55+01:00" level=trace msg="fetched new page 0 with 33 items (list: 33)" uri="spotify:show:5ZW8phuJoLC1go6GoHhY2x" Dec 11 16:28:55 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:55+01:00" level=debug msg="loading episode (paused: true, position: 1715605ms)" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:55 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:55+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 11 16:28:55 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:55+01:00" level=trace msg="emitting websocket event: will_play" Dec 11 16:28:55 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:show:5ZW8phuJoLC1go6GoHhY2x","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","play_origin":"com.spotify.service.podcastepisode"}} Dec 11 16:28:55 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:55+01:00" level=debug msg="selected format OGG_VORBIS_96 (a550deae223bb52cb893e07be6aaf41e5869fb4c)" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:55 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:55+01:00" level=debug msg="requested aes key for file a550deae223bb52cb893e07be6aaf41e5869fb4c, gid: 51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:55 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:55+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1131" Dec 11 16:28:55 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:55+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=trace msg="found 2 cdn urls" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="fetched first chunk of 63, total size is 32693141 bytes" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="fetched chunk 1/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="fetched chunk 2/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="fetched chunk 3/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="fetched chunk 32/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=trace msg="seek to 1715605ms (diff: 848ms, samples: 75658180, bytes: 16892472)" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="created new output device" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=info msg="loaded episode \"Der Bobcast - Advent, Advent ...\" (paused: true, position: 1715605ms, duration: 3342863ms, prefetched: false)" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=trace msg="emitting websocket event: metadata" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=trace msg="emitting websocket event: active" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="sending successful reply for dealer request" Dec 11 16:28:56 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","name":"Der Bobcast - Advent, Advent ...","artist_names":["Haschimitenfürst – Der Bobcast"],"album_name":"Haschimitenfürst – Der Bobcast","album_cover_url":"https://i.scdn.co/image/ab6765630000f68d094cd853ffa40887d2d9f5ed","position":1715605,"duration":3342863,"release_date":"","track_number":0,"disc_number":0}} Dec 11 16:28:56 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"active","data":null} Dec 11 16:28:56 volumio-215 volumio[14518]: info: Aligning Spotify Volume to Volumio Volume Dec 11 16:28:56 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:56 volumio-215 volumio[14518]: info: Setting Spotify Volume from Volumio: 35 Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="fetched chunk 33/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=trace msg="emitting websocket event: paused" Dec 11 16:28:56 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:show:5ZW8phuJoLC1go6GoHhY2x","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","play_origin":"com.spotify.service.podcastepisode"}} Dec 11 16:28:56 volumio-215 volumio[14518]: SPOTIFY: PUSH STATE SPOTIFY Dec 11 16:28:56 volumio-215 volumio[14518]: SPOTIFY: {"status":"pause","service":"spop","title":"Der Bobcast - Advent, Advent ...","artist":"Haschimitenfürst – Der Bobcast","album":"Haschimitenfürst – Der Bobcast","albumart":"https://i.scdn.co/image/ab6765630000f68d094cd853ffa40887d2d9f5ed","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","trackType":"spotify","seek":1715605,"duration":3342,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 11 16:28:56 volumio-215 volumio[14518]: info: CoreCommandRouter::servicePushState Dec 11 16:28:56 volumio-215 volumio[14518]: info: CoreStateMachine::pushState Dec 11 16:28:56 volumio-215 volumio[14518]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 11 16:28:56 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioPushState Dec 11 16:28:56 volumio-215 volumio[14518]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="fetched chunk 34/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:56 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:56 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:56 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:56 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:56+01:00" level=debug msg="fetched chunk 35/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:57 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:58 volumio-215 volumio[14518]: SPOTIFY: SETTING SPOTIFY VOLUME 35 Dec 11 16:28:58 volumio-215 volumio[14518]: info: Sending Spotify command with payload to local API: /player/volume Dec 11 16:28:58 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:58+01:00" level=debug msg="update volume requested to 22937/65535" Dec 11 16:28:58 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:58+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 11 16:28:58 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:58+01:00" level=trace msg="emitting websocket event: volume" Dec 11 16:28:58 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"volume","data":{"value":35,"max":100}} Dec 11 16:28:58 volumio-215 volumio[14518]: SPOTIFY: RECEIVED SPOTIFY VOLUME 35 Dec 11 16:28:58 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:58+01:00" level=debug msg="handling resume player command from 262ee45809a796cc4edb1939a319fec5a484bc81" Dec 11 16:28:58 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:58+01:00" level=trace msg="seek to 1715605ms (diff: 848ms, samples: 75658180, bytes: 16892472)" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:28:58 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:58+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 185759 us, period size = 8192 frames, buffer time = 743038 us, buffer size = 32768 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Dec 11 16:28:58 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:58+01:00" level=debug msg="resume track at 1714757ms" Dec 11 16:28:58 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:58+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 11 16:28:58 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:58+01:00" level=trace msg="scheduling prefetch in 1598s" Dec 11 16:28:58 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:58+01:00" level=debug msg="sending successful reply for dealer request" Dec 11 16:28:58 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:58+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 11 16:28:58 volumio-215 go-librespot[14699]: time="2025-12-11T16:28:58+01:00" level=trace msg="emitting websocket event: playing" Dec 11 16:28:58 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:show:5ZW8phuJoLC1go6GoHhY2x","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","resume":true,"play_origin":"com.spotify.service.podcastepisode"}} Dec 11 16:28:58 volumio-215 volumio[14518]: SPOTIFY: PUSH STATE SPOTIFY Dec 11 16:28:58 volumio-215 volumio[14518]: SPOTIFY: {"status":"play","service":"spop","title":"Der Bobcast - Advent, Advent ...","artist":"Haschimitenfürst – Der Bobcast","album":"Haschimitenfürst – Der Bobcast","albumart":"https://i.scdn.co/image/ab6765630000f68d094cd853ffa40887d2d9f5ed","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","trackType":"spotify","seek":1715605,"duration":3342,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 11 16:28:58 volumio-215 volumio[14518]: info: CoreCommandRouter::servicePushState Dec 11 16:28:58 volumio-215 volumio[14518]: info: CoreStateMachine::pushState Dec 11 16:28:58 volumio-215 volumio[14518]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 11 16:28:58 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioPushState Dec 11 16:28:58 volumio-215 volumio[14518]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Dec 11 16:28:58 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:28:58 volumio-215 volumio[14518]: SPOTIFY: PUSH STATE SPOTIFY Dec 11 16:28:58 volumio-215 volumio[14518]: SPOTIFY: {"status":"play","service":"spop","title":"Der Bobcast - Advent, Advent ...","artist":"Haschimitenfürst – Der Bobcast","album":"Haschimitenfürst – Der Bobcast","albumart":"https://i.scdn.co/image/ab6765630000f68d094cd853ffa40887d2d9f5ed","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","trackType":"spotify","seek":1715605,"duration":3342,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 11 16:28:58 volumio-215 volumio[14518]: info: CoreCommandRouter::servicePushState Dec 11 16:28:58 volumio-215 volumio[14518]: info: CoreStateMachine::pushState Dec 11 16:28:58 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioPushState Dec 11 16:28:58 volumio-215 volumio[14518]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Dec 11 16:28:59 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:00 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:01 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:02 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:03 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:04 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:05 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:06 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:06 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:06 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:29:06 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:29:06 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:29:06 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:29:06 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:07 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:08 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:09 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:09 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:09+01:00" level=debug msg="handling seek_to player command from 262ee45809a796cc4edb1939a319fec5a484bc81" Dec 11 16:29:09 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:09+01:00" level=debug msg="seek track to 1354473ms" Dec 11 16:29:09 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:09+01:00" level=debug msg="fetched chunk 25/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:29:09 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:09+01:00" level=trace msg="seek to 1354473ms (diff: 386ms, samples: 59732259, bytes: 13401729)" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:29:09 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:09+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 11 16:29:09 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:09+01:00" level=trace msg="scheduling prefetch in 1959s" Dec 11 16:29:09 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:09+01:00" level=trace msg="emitting websocket event: seek" Dec 11 16:29:09 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:09+01:00" level=debug msg="sending successful reply for dealer request" Dec 11 16:29:09 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"seek","data":{"context_uri":"spotify:show:5ZW8phuJoLC1go6GoHhY2x","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","position":1354473,"duration":3342863,"play_origin":"com.spotify.service.podcastepisode"}} Dec 11 16:29:09 volumio-215 volumio[14518]: SPOTIFY: PUSH STATE SPOTIFY Dec 11 16:29:09 volumio-215 volumio[14518]: SPOTIFY: {"status":"play","service":"spop","title":"Der Bobcast - Advent, Advent ...","artist":"Haschimitenfürst – Der Bobcast","album":"Haschimitenfürst – Der Bobcast","albumart":"https://i.scdn.co/image/ab6765630000f68d094cd853ffa40887d2d9f5ed","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","trackType":"spotify","seek":1354473,"duration":3342,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 11 16:29:09 volumio-215 volumio[14518]: info: CoreCommandRouter::servicePushState Dec 11 16:29:09 volumio-215 volumio[14518]: info: CoreStateMachine::pushState Dec 11 16:29:09 volumio-215 volumio[14518]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 11 16:29:09 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioPushState Dec 11 16:29:09 volumio-215 volumio[14518]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Dec 11 16:29:09 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:09+01:00" level=debug msg="fetched chunk 26/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:29:10 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:10+01:00" level=debug msg="fetched chunk 28/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:29:10 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:10+01:00" level=debug msg="fetched chunk 27/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:29:10 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:11 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:12 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:13 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:14 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:14+01:00" level=debug msg="handling seek_to player command from 262ee45809a796cc4edb1939a319fec5a484bc81" Dec 11 16:29:14 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:14+01:00" level=debug msg="seek track to 1361165ms" Dec 11 16:29:14 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:14+01:00" level=trace msg="seek to 1361165ms (diff: 321ms, samples: 60027376, bytes: 13468031)" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:29:14 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:14+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 11 16:29:14 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:14+01:00" level=trace msg="scheduling prefetch in 1952s" Dec 11 16:29:14 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:14+01:00" level=trace msg="emitting websocket event: seek" Dec 11 16:29:14 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:14+01:00" level=debug msg="sending successful reply for dealer request" Dec 11 16:29:14 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"seek","data":{"context_uri":"spotify:show:5ZW8phuJoLC1go6GoHhY2x","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","position":1361165,"duration":3342863,"play_origin":"com.spotify.service.podcastepisode"}} Dec 11 16:29:14 volumio-215 volumio[14518]: SPOTIFY: PUSH STATE SPOTIFY Dec 11 16:29:14 volumio-215 volumio[14518]: SPOTIFY: {"status":"play","service":"spop","title":"Der Bobcast - Advent, Advent ...","artist":"Haschimitenfürst – Der Bobcast","album":"Haschimitenfürst – Der Bobcast","albumart":"https://i.scdn.co/image/ab6765630000f68d094cd853ffa40887d2d9f5ed","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","trackType":"spotify","seek":1361165,"duration":3342,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 11 16:29:14 volumio-215 volumio[14518]: info: CoreCommandRouter::servicePushState Dec 11 16:29:14 volumio-215 volumio[14518]: info: CoreStateMachine::pushState Dec 11 16:29:14 volumio-215 volumio[14518]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 11 16:29:14 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioPushState Dec 11 16:29:14 volumio-215 volumio[14518]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Dec 11 16:29:14 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:15 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:16 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:16 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:16 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:17+01:00" level=debug msg="handling seek_to player command from 262ee45809a796cc4edb1939a319fec5a484bc81" Dec 11 16:29:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:17+01:00" level=debug msg="seek track to 1089770ms" Dec 11 16:29:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:17+01:00" level=debug msg="fetched chunk 20/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:29:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:17+01:00" level=trace msg="seek to 1089770ms (diff: 505ms, samples: 48058857, bytes: 10781032)" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:29:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:17+01:00" level=debug msg="fetched chunk 21/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:29:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:17+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 11 16:29:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:17+01:00" level=trace msg="scheduling prefetch in 2224s" Dec 11 16:29:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:17+01:00" level=trace msg="emitting websocket event: seek" Dec 11 16:29:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:17+01:00" level=debug msg="sending successful reply for dealer request" Dec 11 16:29:17 volumio-215 volumio[14518]: SPOTIFY: received: {"type":"seek","data":{"context_uri":"spotify:show:5ZW8phuJoLC1go6GoHhY2x","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","position":1089770,"duration":3342863,"play_origin":"com.spotify.service.podcastepisode"}} Dec 11 16:29:17 volumio-215 volumio[14518]: SPOTIFY: PUSH STATE SPOTIFY Dec 11 16:29:17 volumio-215 volumio[14518]: SPOTIFY: {"status":"play","service":"spop","title":"Der Bobcast - Advent, Advent ...","artist":"Haschimitenfürst – Der Bobcast","album":"Haschimitenfürst – Der Bobcast","albumart":"https://i.scdn.co/image/ab6765630000f68d094cd853ffa40887d2d9f5ed","uri":"spotify:episode:51crgrAy4dDEDhQi6WcaLT","trackType":"spotify","seek":1089770,"duration":3342,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"96 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 11 16:29:17 volumio-215 volumio[14518]: info: CoreCommandRouter::servicePushState Dec 11 16:29:17 volumio-215 volumio[14518]: info: CoreStateMachine::pushState Dec 11 16:29:17 volumio-215 volumio[14518]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 11 16:29:17 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioPushState Dec 11 16:29:17 volumio-215 volumio[14518]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Dec 11 16:29:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:17+01:00" level=debug msg="fetched chunk 22/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:29:17 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:17+01:00" level=debug msg="fetched chunk 23/62, size: 524288" uri="spotify:episode:51crgrAy4dDEDhQi6WcaLT" Dec 11 16:29:17 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:18 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:19 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:20 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:21 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:22 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:23 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:23 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:23+01:00" level=trace msg="sent dealer ping" Dec 11 16:29:23 volumio-215 go-librespot[14699]: time="2025-12-11T16:29:23+01:00" level=trace msg="received dealer pong" Dec 11 16:29:24 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:25 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:26 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:26 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:26 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:29:26 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:29:26 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:29:26 volumio-215 volumio[14518]: info: Listing playlists Dec 11 16:29:26 volumio-215 volumio[14518]: info: CoreCommandRouter::volumioGetState Dec 11 16:29:27 volumio-215 volumio[14518]: info: [1765466967365] [80s80s] Pushing the next song state Fine Young Cannibals - She Drives Me Crazy and getting next track. Dec 11 16:29:27 volumio-215 volumio[14518]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 11 16:29:27 volumio-215 volumio[14518]: TypeError: Cannot set properties of undefined (setting 'name') Dec 11 16:29:27 volumio-215 volumio[14518]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Dec 11 16:29:27 volumio-215 volumio[14518]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Dec 11 16:29:27 volumio-215 volumio[14518]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Dec 11 16:29:27 volumio-215 volumio[14518]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Dec 11 16:29:27 volumio-215 volumio[14518]: at process.processImmediate (node:internal/timers:478:21) Dec 11 16:29:27 volumio-215 volumio[14518]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 11 16:29:28 volumio-215 sudo[1359]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-11 16:28' Dec 11 16:29:28 volumio-215 sudo[1359]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="ac7dd5922ede329d1459d48b226ddc71f5209a2c" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="3441cddd43405c36fe444484553f10f2f5bc830b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Nov 13 11:04:27 UTC 2025" VOLUMIO_VERSION="4.069" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="7da8d6d9f8baf8621af4ec2af5a00f00"