-- Logs begin at Fri 2026-04-10 17:41:23 CEST, end at Sat 2026-04-11 17:34:36 CEST. -- Apr 11 17:33:06 rivoplus go-librespot[4762]: time="2026-04-11T17:33:06+02:00" level=debug msg="dealer connection closed" Apr 11 17:33:06 rivoplus go-librespot[4762]: time="2026-04-11T17:33:06+02:00" level=debug msg="dealer recv loop stopped" Apr 11 17:33:06 rivoplus go-librespot[4762]: time="2026-04-11T17:33:06+02:00" level=debug msg="obtained new client token: AACm1Qz2kwjjNSFW1cal4ChCeTP4M303uIedON32OIR3wFnxpR1oAx31sdpbFWO2inn4Y55pGPaeQ+YbRyc3GMdY2Rgule75CVntH3HvzVpugF/51PJxJ5FP/scxN2ge69a7/RjW0SwFIwjEYGTdMX5m+6FwzVPlu6gzyD7puX8hP4z6G7ghr0Q3LOE3VRXzUmCDtsNA88Ppv4pJyQ0OUj5HWIO2d4fJh0gsKrtO8MmOqru27nAKdw==" Apr 11 17:33:06 rivoplus go-librespot[4762]: time="2026-04-11T17:33:06+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Apr 11 17:33:06 rivoplus go-librespot[4762]: time="2026-04-11T17:33:06+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Apr 11 17:33:06 rivoplus go-librespot[4762]: time="2026-04-11T17:33:06+02:00" level=debug msg="completed keyexchange" Apr 11 17:33:06 rivoplus go-librespot[4762]: time="2026-04-11T17:33:06+02:00" level=debug msg="completed challenge" Apr 11 17:33:06 rivoplus go-librespot[4762]: time="2026-04-11T17:33:06+02:00" level=info msg="authenticated AP" username="sj****pl" Apr 11 17:33:06 rivoplus go-librespot[4762]: time="2026-04-11T17:33:06+02:00" level=info msg="authenticated Login5" username="sj****pl" Apr 11 17:33:06 rivoplus go-librespot[4762]: time="2026-04-11T17:33:06+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Apr 11 17:33:06 rivoplus go-librespot[4762]: time="2026-04-11T17:33:06+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Apr 11 17:33:06 rivoplus go-librespot[4762]: time="2026-04-11T17:33:06+02:00" level=info msg="accepted zeroconf from JACEK" username="sj****pl" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="dealer connection opened" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=trace msg="starting accesspoint recv loop" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=trace msg="starting dealer recv loop" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=trace msg="received accesspoint ping" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="received connection id: MWViY2NhODEtZWU5...MDkxRDc2NUMwQw==" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=trace msg="received accesspoint pong ack" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="put connect state because NEW_DEVICE" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="handling transfer player command from 11ad8fb342802796db2fdb414c55cfa82b6838f5" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:2LZWMe7zxyPhdbjXW9soh3" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=trace msg="fetched new page 0 with 142 items (list: 142)" uri="spotify:playlist:2LZWMe7zxyPhdbjXW9soh3" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:2LdAX67Dr2mzRed9gOQzqX" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=trace msg="emitting websocket event: will_play" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1679" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="selected format OGG_VORBIS_320 (20cef2729c45f14d14dfd0d8c97f3f92cdb7724e)" uri="spotify:track:2LdAX67Dr2mzRed9gOQzqX" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="requested aes key for file 20cef2729c45f14d14dfd0d8c97f3f92cdb7724e, gid: 1l91nppwMquHCzLcu3UdHs" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:2LdAX67Dr2mzRed9gOQzqX" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1293" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="fetched first chunk of 20, total size is 10280780 bytes" uri="spotify:track:2LdAX67Dr2mzRed9gOQzqX" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:2LdAX67Dr2mzRed9gOQzqX" Apr 11 17:33:07 rivoplus go-librespot[4762]: time="2026-04-11T17:33:07+02:00" level=debug msg="created new output device" Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=info msg="loaded track \"Somebody That I Used to Know - Bossa Version\" (paused: false, position: 1ms, duration: 246569ms, prefetched: false)" uri="spotify:track:2LdAX67Dr2mzRed9gOQzqX" Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=trace msg="scheduling prefetch in 216s" Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=trace msg="emitting websocket event: metadata" Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=trace msg="emitting websocket event: active" Apr 11 17:33:08 rivoplus volumio[3176]: info: Aligning Spotify Volume to Volumio Volume Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:33:08 rivoplus volumio[3176]: info: Setting Spotify Volume from Volumio: 100 Apr 11 17:33:08 rivoplus volumio[3176]: info: Aligning Spotify Volume to Volumio Volume Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:33:08 rivoplus volumio[3176]: info: Setting Spotify Volume from Volumio: 100 Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:2LdAX67Dr2mzRed9gOQzqX" Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=debug msg="sending successful reply for dealer request" Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=trace msg="emitting websocket event: playing" Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::servicePushState Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreStateMachine::pushState Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::volumioPushState Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:33:08 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output update for this device Apr 11 17:33:08 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output Apr 11 17:33:08 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:08.190+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" state=STATUS_PLAYING positionMs=1 volume=100 Apr 11 17:33:08 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:08.191+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" id=spotify:track:1l91nppwMquHCzLcu3UdHs title="Somebody That I Used to Know - Bossa Version" Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::servicePushState Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreStateMachine::pushState Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::volumioPushState Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:33:08 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output update for this device Apr 11 17:33:08 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output Apr 11 17:33:08 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:08.222+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" state=STATUS_PLAYING positionMs=1 volume=100 Apr 11 17:33:08 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:08.222+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" id=spotify:track:1l91nppwMquHCzLcu3UdHs title="Somebody That I Used to Know - Bossa Version" Apr 11 17:33:08 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:08 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:08 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:08 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:2LdAX67Dr2mzRed9gOQzqX" Apr 11 17:33:08 rivoplus volumio[3176]: info: Updating RAAT Signal Path Apr 11 17:33:08 rivoplus go-librespot[4762]: time="2026-04-11T17:33:08+02:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:2LdAX67Dr2mzRed9gOQzqX" Apr 11 17:33:08 rivoplus volumio[3176]: info: Updating RAAT Signal Path Apr 11 17:33:08 rivoplus volumio[3176]: info: MCU Signalled Playback Active Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::servicePushState Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreStateMachine::pushState Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::volumioPushState Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:33:08 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output update for this device Apr 11 17:33:08 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output Apr 11 17:33:08 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:08.486+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" state=STATUS_PLAYING positionMs=1 volume=100 Apr 11 17:33:08 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:08.486+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" id=spotify:track:1l91nppwMquHCzLcu3UdHs title="Somebody That I Used to Know - Bossa Version" Apr 11 17:33:08 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:08 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:08 rivoplus volumio[3176]: info: Updating RAAT Signal Path Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::servicePushState Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreStateMachine::pushState Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::volumioPushState Apr 11 17:33:08 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:33:08 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output update for this device Apr 11 17:33:08 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output Apr 11 17:33:08 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:08.529+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" state=STATUS_PLAYING positionMs=1 volume=100 Apr 11 17:33:08 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:08.530+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" id=spotify:track:1l91nppwMquHCzLcu3UdHs title="Somebody That I Used to Know - Bossa Version" Apr 11 17:33:08 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:08 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:08 rivoplus volumio[3176]: info: Updating RAAT Signal Path Apr 11 17:33:09 rivoplus volumio[3176]: info: Sending Spotify command with payload to local API: /player/volume Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=debug msg="update volume requested to 65535/65535" Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1345" Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 455" Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=trace msg="emitting websocket event: volume" Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=info msg="playback was transferred to JACEK" Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=trace msg="closed output device because of stop command" Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=debug msg="put connect state inactive" Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=trace msg="emitting websocket event: inactive" Apr 11 17:33:09 rivoplus volumio[3176]: error: Failed to decode event: inactive Apr 11 17:33:09 rivoplus volumio[3176]: error: Failed to decode event: inactive Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=debug msg="dealer connection closed" Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=debug msg="dealer recv loop stopped" Apr 11 17:33:09 rivoplus go-librespot[4762]: time="2026-04-11T17:33:09+02:00" level=debug msg="obtained new client token: AAD554U4d+Kkn+mntusyX9waoGmnPpLLdy1VpMx4apg4iQFyk4BkiMLHlbaU9NG1zP4FANZBn1JoD7M9+9EpBufEpEOxTrQrFoERKJPdj2i+nmu4NX+ptAUzIM4DhWuX0SNjZe3TYenRArk4tzVwzN4OmFRR1JvJNP6Yu/BaBBfxgvOGcJk5QeLXY2cHIPqFb24BIlpSrNHM6spHhrXLFdwAmTnWOmjGYDw4HKG3DYkBqEyWC+x2vQ==" Apr 11 17:33:10 rivoplus go-librespot[4762]: time="2026-04-11T17:33:10+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Apr 11 17:33:10 rivoplus volumio[3176]: info: Executing endpoint metavolumio Apr 11 17:33:10 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 11 17:33:10 rivoplus volumio[3176]: info: Executing endpoint metavolumio Apr 11 17:33:10 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 11 17:33:10 rivoplus volumio[3176]: info: Executing endpoint metavolumio Apr 11 17:33:10 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 11 17:33:10 rivoplus go-librespot[4762]: time="2026-04-11T17:33:10+02:00" level=debug msg="completed keyexchange" Apr 11 17:33:10 rivoplus go-librespot[4762]: time="2026-04-11T17:33:10+02:00" level=debug msg="completed challenge" Apr 11 17:33:10 rivoplus go-librespot[4762]: time="2026-04-11T17:33:10+02:00" level=info msg="authenticated AP" username="s0*********************kc" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=info msg="authenticated Login5" username="s0*********************kc" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=debug msg="restored session after logout" username="s0*********************kc" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=debug msg="dealer connection opened" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=trace msg="starting accesspoint recv loop" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=trace msg="starting dealer recv loop" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=trace msg="received accesspoint ping" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=debug msg="received connection id: MzMwN2U3MzUtMzU4...MzJBNDY0QjdFRQ==" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=debug msg="put connect state because NEW_DEVICE" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 11 17:33:11 rivoplus go-librespot[4762]: time="2026-04-11T17:33:11+02:00" level=trace msg="received accesspoint pong ack" Apr 11 17:33:20 rivoplus go-librespot[4762]: time="2026-04-11T17:33:20+02:00" level=debug msg="dealer connection closed" Apr 11 17:33:20 rivoplus go-librespot[4762]: time="2026-04-11T17:33:20+02:00" level=debug msg="dealer recv loop stopped" Apr 11 17:33:20 rivoplus go-librespot[4762]: time="2026-04-11T17:33:20+02:00" level=debug msg="obtained new client token: AAAFieCZxZECaGJ0o2PfRG3sHGqmKqPSqMevb1EC5/dM266EYj6r5l+oI1UfFPvsBELULcUl/n1t45KjIk8W2+Mr0ggnsysPCXIwcPsaN1UjJie//ri4S8vhfVCA5URL30seAcsSv0rKXuXQh381IS0mv6c6bjGLw1jB/4eRLLDzoU4X5HET74LY5GWrHklfAdZwgrGGWrdzgIsq0/Mm3z9oPecHi+8JBDMO5D2yOyBsuR24aBbZkg==" Apr 11 17:33:20 rivoplus go-librespot[4762]: time="2026-04-11T17:33:20+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Apr 11 17:33:20 rivoplus go-librespot[4762]: time="2026-04-11T17:33:20+02:00" level=debug msg="completed keyexchange" Apr 11 17:33:20 rivoplus go-librespot[4762]: time="2026-04-11T17:33:20+02:00" level=debug msg="completed challenge" Apr 11 17:33:20 rivoplus go-librespot[4762]: time="2026-04-11T17:33:20+02:00" level=info msg="authenticated AP" username="sj****pl" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=info msg="authenticated Login5" username="sj****pl" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=info msg="accepted zeroconf from JACEK" username="sj****pl" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="dealer connection opened" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=trace msg="starting accesspoint recv loop" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=trace msg="starting dealer recv loop" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=trace msg="received accesspoint ping" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="received connection id: N2ZlMjk2NjEtMmQx...NjA3OTZDRkE5NA==" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=trace msg="received accesspoint pong ack" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="put connect state because NEW_DEVICE" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="handling transfer player command from 11ad8fb342802796db2fdb414c55cfa82b6838f5" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:2LZWMe7zxyPhdbjXW9soh3" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=trace msg="fetched new page 0 with 142 items (list: 142)" uri="spotify:playlist:2LZWMe7zxyPhdbjXW9soh3" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=trace msg="emitting websocket event: will_play" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1293" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="selected format OGG_VORBIS_320 (732aa11d3aefc9ec9839da5f2715d06b2b01160b)" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=debug msg="requested aes key for file 732aa11d3aefc9ec9839da5f2715d06b2b01160b, gid: 1L5Z46VjM15XWr6pjXKeu1" Apr 11 17:33:21 rivoplus go-librespot[4762]: time="2026-04-11T17:33:21+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=debug msg="fetched first chunk of 17, total size is 8636384 bytes" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=debug msg="created new output device" Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=info msg="loaded track \"White Wedding\" (paused: false, position: 0ms, duration: 226318ms, prefetched: false)" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=trace msg="scheduling prefetch in 196s" Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=trace msg="emitting websocket event: metadata" Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=trace msg="emitting websocket event: active" Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=debug msg="sending successful reply for dealer request" Apr 11 17:33:22 rivoplus volumio[3176]: info: Aligning Spotify Volume to Volumio Volume Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:33:22 rivoplus volumio[3176]: info: Setting Spotify Volume from Volumio: 100 Apr 11 17:33:22 rivoplus volumio[3176]: info: Aligning Spotify Volume to Volumio Volume Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:33:22 rivoplus volumio[3176]: info: Setting Spotify Volume from Volumio: 100 Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=trace msg="emitting websocket event: playing" Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::servicePushState Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreStateMachine::pushState Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::volumioPushState Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:33:22 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output update for this device Apr 11 17:33:22 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output Apr 11 17:33:22 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:22.340+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" state=STATUS_PLAYING positionMs=0 volume=100 Apr 11 17:33:22 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:22.340+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" id=spotify:track:1L5Z46VjM15XWr6pjXKeu1 title="White Wedding" Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::servicePushState Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreStateMachine::pushState Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::volumioPushState Apr 11 17:33:22 rivoplus go-librespot[4762]: time="2026-04-11T17:33:22+02:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:33:22 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output update for this device Apr 11 17:33:22 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output Apr 11 17:33:22 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:22.375+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" state=STATUS_PLAYING positionMs=0 volume=100 Apr 11 17:33:22 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:22.376+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" id=spotify:track:1L5Z46VjM15XWr6pjXKeu1 title="White Wedding" Apr 11 17:33:22 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:22 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:22 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:22 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:22 rivoplus volumio[3176]: info: Updating RAAT Signal Path Apr 11 17:33:22 rivoplus volumio[3176]: info: Updating RAAT Signal Path Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::servicePushState Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreStateMachine::pushState Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::volumioPushState Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:33:22 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output update for this device Apr 11 17:33:22 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output Apr 11 17:33:22 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:22.628+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" state=STATUS_PLAYING positionMs=0 volume=100 Apr 11 17:33:22 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:22.628+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" id=spotify:track:1L5Z46VjM15XWr6pjXKeu1 title="White Wedding" Apr 11 17:33:22 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:22 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:22 rivoplus volumio[3176]: info: Updating RAAT Signal Path Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::servicePushState Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreStateMachine::pushState Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::volumioPushState Apr 11 17:33:22 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:33:22 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output update for this device Apr 11 17:33:22 rivoplus volumio[3176]: info: MRS: Pushing multiroomSync output Apr 11 17:33:22 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:22.670+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" state=STATUS_PLAYING positionMs=0 volume=100 Apr 11 17:33:22 rivoplus volumio5-onboarding[3832]: time=2026-04-11T17:33:22.670+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.19:40720 @ 0x27f8540" id=spotify:track:1L5Z46VjM15XWr6pjXKeu1 title="White Wedding" Apr 11 17:33:22 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:22 rivoplus volumio[3176]: info: Signalling Playback active due to playback status change Apr 11 17:33:22 rivoplus volumio[3176]: info: Updating RAAT Signal Path Apr 11 17:33:23 rivoplus volumio[3176]: info: Sending Spotify command with payload to local API: /player/volume Apr 11 17:33:23 rivoplus go-librespot[4762]: time="2026-04-11T17:33:23+02:00" level=debug msg="update volume requested to 65535/65535" Apr 11 17:33:24 rivoplus go-librespot[4762]: time="2026-04-11T17:33:24+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 11 17:33:24 rivoplus go-librespot[4762]: time="2026-04-11T17:33:24+02:00" level=trace msg="emitting websocket event: volume" Apr 11 17:33:24 rivoplus volumio[3176]: info: Executing endpoint metavolumio Apr 11 17:33:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 11 17:33:24 rivoplus volumio[3176]: info: Executing endpoint metavolumio Apr 11 17:33:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 11 17:33:24 rivoplus volumio[3176]: info: Executing endpoint metavolumio Apr 11 17:33:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 11 17:33:34 rivoplus kernel: usb 1-1.4.2: USB disconnect, device number 8 Apr 11 17:33:34 rivoplus go-librespot[4762]: time="2026-04-11T17:33:34+02:00" level=debug msg="fetched chunk 4/16, size: 524288" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:33:47 rivoplus go-librespot[4762]: time="2026-04-11T17:33:47+02:00" level=debug msg="fetched chunk 5/16, size: 524288" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:33:51 rivoplus go-librespot[4762]: time="2026-04-11T17:33:51+02:00" level=trace msg="sent dealer ping" Apr 11 17:33:51 rivoplus go-librespot[4762]: time="2026-04-11T17:33:51+02:00" level=trace msg="received dealer pong" Apr 11 17:34:02 rivoplus go-librespot[4762]: time="2026-04-11T17:34:02+02:00" level=debug msg="fetched chunk 6/16, size: 524288" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:34:09 rivoplus volumio[3176]: verbose: New Socket.io Connection to 192.168.1.99 from 192.168.1.19 UA: Mozilla/5.0 (Linux; Android 14; SM-G991B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.177 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Apr 11 17:34:09 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 11 17:34:09 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetVisibleSources Apr 11 17:34:09 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 11 17:34:09 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:34:09 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 11 17:34:09 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 11 17:34:09 rivoplus volumio[3176]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Apr 11 17:34:09 rivoplus volumio[3176]: info: Received Get System Info Apr 11 17:34:09 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 11 17:34:09 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 11 17:34:09 rivoplus volumio[3176]: info: Discovery: Getting this device information Apr 11 17:34:09 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:34:09 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 11 17:34:09 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetState Apr 11 17:34:09 rivoplus volumio[3176]: info: Listing playlists Apr 11 17:34:09 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 11 17:34:16 rivoplus go-librespot[4762]: time="2026-04-11T17:34:16+02:00" level=debug msg="fetched chunk 7/16, size: 524288" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:34:21 rivoplus go-librespot[4762]: time="2026-04-11T17:34:21+02:00" level=trace msg="sent dealer ping" Apr 11 17:34:21 rivoplus go-librespot[4762]: time="2026-04-11T17:34:21+02:00" level=trace msg="received dealer pong" Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 11 17:34:24 rivoplus volumio[3176]: info: Retrieving Cloud Streaming UI Apr 11 17:34:24 rivoplus volumio[3176]: info: Getting Tidal Cloud Configuration Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 11 17:34:24 rivoplus volumio[3176]: info: Getting Qobuz Cloud Configuration Apr 11 17:34:24 rivoplus volumio[3176]: info: Asking plugin for UI Config Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 11 17:34:24 rivoplus volumio[3176]: info: Getting Spotify Cloud Configuration Apr 11 17:34:24 rivoplus volumio[3176]: info: Asking plugin for UI Config Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 11 17:34:24 rivoplus volumio[3176]: info: Saving Spotify Acccount Apr 11 17:34:24 rivoplus volumio[3176]: info: Got it Apr 11 17:34:24 rivoplus volumio[3176]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Apr 11 17:34:24 rivoplus volumio[3176]: info: Got Tidal Cloud Configuration Apr 11 17:34:24 rivoplus volumio[3176]: info: Got it Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetBrowseSources Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetBrowseSources Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::volumioGetBrowseSources Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 11 17:34:24 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Apr 11 17:34:28 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 11 17:34:30 rivoplus go-librespot[4762]: time="2026-04-11T17:34:30+02:00" level=debug msg="fetched chunk 8/16, size: 524288" uri="spotify:track:5rlqpkydoN3X2oCVKgYjWO" Apr 11 17:34:32 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 11 17:34:33 rivoplus volumio[3176]: info: Disabling MyMusic plugin upnp Apr 11 17:34:33 rivoplus sudo[12982]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Apr 11 17:34:33 rivoplus sudo[12982]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 11 17:34:33 rivoplus systemd[1]: Stopping UPnP Renderer front-end to MPD... Apr 11 17:34:33 rivoplus volumio[3176]: error: Upnp client error: Error: This socket has been ended by the other party Apr 11 17:34:33 rivoplus volumio[3176]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 11 17:34:35 rivoplus volumio[3176]: info: Enabling MyMusic plugin upnp Apr 11 17:34:35 rivoplus volumio[3176]: info: Enabling plugin upnp Apr 11 17:34:35 rivoplus volumio[3176]: info: Loading plugin "upnp"... Apr 11 17:34:35 rivoplus volumio[3176]: info: [1775921675770] Starting Upmpd Daemon Apr 11 17:34:35 rivoplus volumio[3176]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 11 17:34:35 rivoplus volumio[3176]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 11 17:34:35 rivoplus volumio[3176]: Error: listen EADDRINUSE: address already in use :::6599 Apr 11 17:34:35 rivoplus volumio[3176]: at Server.setupListenHandle [as _listen2] (net.js:1331:16) Apr 11 17:34:35 rivoplus volumio[3176]: at listenInCluster (net.js:1379:12) Apr 11 17:34:35 rivoplus volumio[3176]: at Server.listen (net.js:1465:7) Apr 11 17:34:35 rivoplus volumio[3176]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Apr 11 17:34:35 rivoplus volumio[3176]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Apr 11 17:34:35 rivoplus volumio[3176]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Apr 11 17:34:35 rivoplus volumio[3176]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Apr 11 17:34:35 rivoplus volumio[3176]: at processTicksAndRejections (internal/process/task_queues.js:77:11) { Apr 11 17:34:35 rivoplus volumio[3176]: code: 'EADDRINUSE', Apr 11 17:34:35 rivoplus volumio[3176]: errno: -98, Apr 11 17:34:35 rivoplus volumio[3176]: syscall: 'listen', Apr 11 17:34:35 rivoplus volumio[3176]: address: '::', Apr 11 17:34:35 rivoplus volumio[3176]: port: 6599 Apr 11 17:34:35 rivoplus volumio[3176]: } Apr 11 17:34:35 rivoplus volumio[3176]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 11 17:34:36 rivoplus sudo[12994]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-04-11 17:33 Apr 11 17:34:36 rivoplus sudo[12994]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="464fc672d77d3df6ee72b331d36cdf1fa936e1ec" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 27 Feb 2026 11:19:27 AM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo Plus" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo Plus" VOLUMIO_HASH="a7285124ffc88c43265bb2db03526f6a"