Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=debug msg="obtained new client token: AAGTmS+JWdctbJEhz9tDooOoSeevAMmrsfEQIDpW1IFrPXllCPFpaAIgkSWOfyIn4tvU4U/gQKvYtmj4zZFxhhLrpkFcLgKJtZdrGcHxijp+vzFp4rxBOTsLKr/trKGtEJpYgR54+GFVfYqriTmacbZVZjVIrKhamRoewvhed12aSEVzRtTmc+k/CyUVVuA7KPTxcPRkMl623aSsuTmdsN02+70sIvMWoBTqBrCnC0+KPTvJd3OyHFyO" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=debug msg="completed keyexchange" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=debug msg="completed challenge" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=info msg="authenticated AP" username="31************************we" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=info msg="authenticated Login5" username="31************************we" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=info msg="accepted zeroconf from Pioneer" username="31************************we" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=debug msg="dealer connection opened" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=trace msg="starting accesspoint recv loop" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=trace msg="starting dealer recv loop" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=trace msg="received accesspoint ping" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=debug msg="received connection id: MGY4MWJkMmEtOWIz...NUVCRkFBNEQ0QQ==" Oct 12 22:08:02 volumio go-librespot[2265]: time="2026-10-12T22:08:02+09:00" level=trace msg="received accesspoint pong ack" Oct 12 22:08:03 volumio go-librespot[2265]: time="2026-10-12T22:08:03+09:00" level=debug msg="put connect state because NEW_DEVICE" Oct 12 22:08:03 volumio go-librespot[2265]: time="2026-10-12T22:08:03+09:00" level=debug msg="handling transfer player command from 4cb279a463956a3953e40cb225cda130a3d86879" Oct 12 22:08:03 volumio go-librespot[2265]: time="2026-10-12T22:08:03+09:00" level=debug msg="resolved context of track" uri="spotify:album:3EfalQgCGR2bh5tkZdZTTR" Oct 12 22:08:03 volumio go-librespot[2265]: time="2026-10-12T22:08:03+09:00" level=trace msg="fetched new page 0 with 2 items (list: 2)" uri="spotify:album:3EfalQgCGR2bh5tkZdZTTR" Oct 12 22:08:03 volumio go-librespot[2265]: time="2026-10-12T22:08:03+09:00" level=debug msg="loading track (paused: true, position: 18240ms)" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:03 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 12 22:08:03 volumio volumio[1941]: info: Received Get System Info Oct 12 22:08:03 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 12 22:08:03 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 12 22:08:03 volumio volumio[1941]: info: Discovery: Getting this device information Oct 12 22:08:03 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:08:03 volumio volumio[1941]: info: CorePlayQueue::getTrack 0 Oct 12 22:08:03 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 12 22:08:03 volumio go-librespot[2265]: time="2026-10-12T22:08:03+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 12 22:08:03 volumio go-librespot[2265]: time="2026-10-12T22:08:03+09:00" level=trace msg="emitting websocket event: will_play" Oct 12 22:08:03 volumio volumio[1941]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:3EfalQgCGR2bh5tkZdZTTR","uri":"spotify:track:02KRPJcx4TJFLCXt9qwEUE","play_origin":"android-auto"}} Oct 12 22:08:03 volumio go-librespot[2265]: time="2026-10-12T22:08:03+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 435" Oct 12 22:08:03 volumio go-librespot[2265]: time="2026-10-12T22:08:03+09:00" level=debug msg="selected format OGG_VORBIS_320 (b75c647697c719047a9babc1aa30917e61ffaef2)" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:03 volumio go-librespot[2265]: time="2026-10-12T22:08:03+09:00" level=debug msg="requested aes key for file b75c647697c719047a9babc1aa30917e61ffaef2, gid: 02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:03 volumio go-librespot[2265]: time="2026-10-12T22:08:03+09:00" level=trace msg="found 2 cdn urls" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:04 volumio go-librespot[2265]: time="2026-10-12T22:08:04+09:00" level=debug msg="fetched first chunk of 19, total size is 9510797 bytes" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:04 volumio go-librespot[2265]: time="2026-10-12T22:08:04+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 396" Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=trace msg="seek to 18240ms (diff: 122ms, samples: 804384, bytes: 782703)" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=debug msg="created new output device" Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=info msg="loaded track \"Unknown Planet\" (paused: true, position: 18240ms, duration: 225000ms, prefetched: false)" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=trace msg="emitting websocket event: metadata" Oct 12 22:08:05 volumio volumio[1941]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:02KRPJcx4TJFLCXt9qwEUE","name":"Unknown Planet","artist_names":["IU"],"album_name":"Unknown Planet","album_cover_url":"https://i.scdn.co/image/ab67616d00001e023ae0500dbe6192b013e36649","position":18240,"duration":225000,"release_date":"year:2026 month:9 day:10","track_number":1,"disc_number":1}} Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=trace msg="emitting websocket event: active" Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=debug msg="sending successful reply for dealer request" Oct 12 22:08:05 volumio volumio[1941]: SPOTIFY: received: {"type":"active","data":null} Oct 12 22:08:05 volumio volumio[1941]: info: Aligning Spotify Volume to Volumio Volume Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 12 22:08:05 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:08:05 volumio volumio[1941]: info: CorePlayQueue::getTrack 0 Oct 12 22:08:05 volumio volumio[1941]: info: Setting Spotify Volume from Volumio: 51 Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=trace msg="emitting websocket event: paused" Oct 12 22:08:05 volumio volumio[1941]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:album:3EfalQgCGR2bh5tkZdZTTR","uri":"spotify:track:02KRPJcx4TJFLCXt9qwEUE","play_origin":"android-auto"}} Oct 12 22:08:05 volumio volumio[1941]: info: Spotify is playing in volatile mode Oct 12 22:08:05 volumio volumio[1941]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 12 22:08:05 volumio volumio[1941]: SPOTIFY: UNSET VOLATILE Oct 12 22:08:05 volumio volumio[1941]: SPOTIFY: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":51,"dbVolume":null,"mute":false,"disableVolumeControl":false,"random":null,"repeat":true,"repeatSingle":false,"updatedb":false,"consume":false} Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=debug msg="skipping dealer message" uri="hm://herodotus/uri/spotify:album:3EfalQgCGR2bh5tkZdZTTR/resume-point-revision/1728a4fd-858a-48f3-998d-d835b3ac8e61" Oct 12 22:08:05 volumio volumio[1941]: SPOTIFY: PUSH STATE SPOTIFY Oct 12 22:08:05 volumio volumio[1941]: SPOTIFY: {"status":"pause","service":"spop","title":"Unknown Planet","artist":"IU","album":"Unknown Planet","albumart":"https://i.scdn.co/image/ab67616d00001e023ae0500dbe6192b013e36649","uri":"spotify:track:02KRPJcx4TJFLCXt9qwEUE","trackType":"spotify","seek":18240,"duration":225,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 12 22:08:05 volumio volumio[1941]: info: CoreCommandRouter::servicePushState Oct 12 22:08:05 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:05 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:05 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:05 volumio volumio[1941]: info: FusionDsp - volume level for loudness 51 gain applied 0 Oct 12 22:08:05 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 12 22:08:05 volumio volumio[1941]: info: Received Get System Info Oct 12 22:08:05 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 12 22:08:05 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 12 22:08:05 volumio volumio[1941]: info: Discovery: Getting this device information Oct 12 22:08:05 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:08:05 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 12 22:08:05 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 51 Oct 12 22:08:05 volumio go-librespot[2265]: time="2026-10-12T22:08:05+09:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:05 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:05 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:05 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:05 volumio volumio[1941]: error: FusionDsp - Reload WebSocket error: [object Object] Oct 12 22:08:06 volumio go-librespot[2265]: time="2026-10-12T22:08:06+09:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:06 volumio go-librespot[2265]: time="2026-10-12T22:08:06+09:00" level=debug msg="fetched chunk 4/18, size: 524288" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:06 volumio volumio[1941]: SPOTIFY: SETTING SPOTIFY VOLUME 51 Oct 12 22:08:06 volumio volumio[1941]: info: Sending Spotify command with payload to local API: /player/volume Oct 12 22:08:06 volumio go-librespot[2265]: time="2026-10-12T22:08:06+09:00" level=debug msg="update volume requested to 33422/65535" Oct 12 22:08:06 volumio go-librespot[2265]: time="2026-10-12T22:08:06+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:06 volumio go-librespot[2265]: time="2026-10-12T22:08:06+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:06 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":51,"max":100}} Oct 12 22:08:06 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 51 Oct 12 22:08:07 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 12 22:08:08 volumio go-librespot[2265]: time="2026-10-12T22:08:08+09:00" level=debug msg="update volume requested to 30801/65535" Oct 12 22:08:08 volumio go-librespot[2265]: time="2026-10-12T22:08:08+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:08 volumio go-librespot[2265]: time="2026-10-12T22:08:08+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:08 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":47,"max":100}} Oct 12 22:08:08 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 47 Oct 12 22:08:08 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 47 Oct 12 22:08:08 volumio volumio[1941]: info: VolumeController::SetAlsaVolume47 Oct 12 22:08:08 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:08 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:08 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:08 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:08.315+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" state=STATUS_PAUSED positionMs=18240 volume=47 Oct 12 22:08:08 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:08.316+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PAUSED positionMs=18240 volume=47 Oct 12 22:08:08 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:08.320+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:08 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:08.320+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:08 volumio volumio[1941]: info: FusionDsp - volume level for loudness 47 gain applied 1.53 Oct 12 22:08:08 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Oct 12 22:08:08 volumio volumio[1941]: info: Received Get System Info Oct 12 22:08:08 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 12 22:08:08 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 12 22:08:08 volumio volumio[1941]: info: Discovery: Getting this device information Oct 12 22:08:08 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:08:08 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 12 22:08:08 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 12 22:08:08 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:08 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:08 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:08 volumio volumio[1941]: error: FusionDsp - Reload WebSocket error: [object Object] Oct 12 22:08:09 volumio go-librespot[2265]: time="2026-10-12T22:08:09+09:00" level=debug msg="update volume requested to 28180/65535" Oct 12 22:08:09 volumio go-librespot[2265]: time="2026-10-12T22:08:09+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:09 volumio go-librespot[2265]: time="2026-10-12T22:08:09+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:09 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":43,"max":100}} Oct 12 22:08:09 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 43 Oct 12 22:08:09 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 43 Oct 12 22:08:09 volumio volumio[1941]: info: VolumeController::SetAlsaVolume43 Oct 12 22:08:09 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:09 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:09 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:09 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:09.673+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" state=STATUS_PAUSED positionMs=18240 volume=43 Oct 12 22:08:09 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:09.675+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PAUSED positionMs=18240 volume=43 Oct 12 22:08:09 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:09.676+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:09 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:09.676+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:09 volumio volumio[1941]: info: FusionDsp - volume level for loudness 43 gain applied 3.58 Oct 12 22:08:09 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 43 Oct 12 22:08:09 volumio go-librespot[2265]: time="2026-10-12T22:08:09+09:00" level=debug msg="update volume requested to 25559/65535" Oct 12 22:08:09 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:09 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:09 volumio go-librespot[2265]: time="2026-10-12T22:08:09+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:09 volumio go-librespot[2265]: time="2026-10-12T22:08:09+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:09 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":39,"max":100}} Oct 12 22:08:09 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 39 Oct 12 22:08:09 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 39 Oct 12 22:08:09 volumio volumio[1941]: info: VolumeController::SetAlsaVolume39 Oct 12 22:08:09 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:09 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:09 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.012+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" state=STATUS_PAUSED positionMs=18240 volume=39 Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.013+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PAUSED positionMs=18240 volume=39 Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.019+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.019+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:10 volumio volumio[1941]: info: FusionDsp - volume level for loudness 39 gain applied 5.62 Oct 12 22:08:10 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 39 Oct 12 22:08:10 volumio volumio[1941]: error: FusionDsp - Reload WebSocket error: [object Object] Oct 12 22:08:10 volumio go-librespot[2265]: time="2026-10-12T22:08:10+09:00" level=debug msg="update volume requested to 22937/65535" Oct 12 22:08:10 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:10 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:10 volumio volumio[1941]: error: FusionDsp - Reload WebSocket error: [object Object] Oct 12 22:08:10 volumio go-librespot[2265]: time="2026-10-12T22:08:10+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:10 volumio go-librespot[2265]: time="2026-10-12T22:08:10+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:10 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":35,"max":100}} Oct 12 22:08:10 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 35 Oct 12 22:08:10 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 35 Oct 12 22:08:10 volumio volumio[1941]: info: VolumeController::SetAlsaVolume35 Oct 12 22:08:10 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:10 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:10 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:10 volumio go-librespot[2265]: time="2026-10-12T22:08:10+09:00" level=debug msg="update volume requested to 20316/65535" Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.485+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" state=STATUS_PAUSED positionMs=18240 volume=35 Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.486+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PAUSED positionMs=18240 volume=35 Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.486+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.487+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:10 volumio volumio[1941]: info: FusionDsp - volume level for loudness 35 gain applied 7.67 Oct 12 22:08:10 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Oct 12 22:08:10 volumio go-librespot[2265]: time="2026-10-12T22:08:10+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:10 volumio go-librespot[2265]: time="2026-10-12T22:08:10+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:10 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":31,"max":100}} Oct 12 22:08:10 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 31 Oct 12 22:08:10 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 31 Oct 12 22:08:10 volumio volumio[1941]: info: VolumeController::SetAlsaVolume31 Oct 12 22:08:10 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:10 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:10 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:10 volumio go-librespot[2265]: time="2026-10-12T22:08:10+09:00" level=debug msg="update volume requested to 17694/65535" Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.714+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" state=STATUS_PAUSED positionMs=18240 volume=31 Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.715+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PAUSED positionMs=18240 volume=31 Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.715+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.716+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:10 volumio volumio[1941]: info: FusionDsp - volume level for loudness 31 gain applied 9.71 Oct 12 22:08:10 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 31 Oct 12 22:08:10 volumio go-librespot[2265]: time="2026-10-12T22:08:10+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:10 volumio go-librespot[2265]: time="2026-10-12T22:08:10+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:10 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":27,"max":100}} Oct 12 22:08:10 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 27 Oct 12 22:08:10 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 27 Oct 12 22:08:10 volumio volumio[1941]: info: VolumeController::SetAlsaVolume27 Oct 12 22:08:10 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:10 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:10 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.936+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" state=STATUS_PAUSED positionMs=18240 volume=27 Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.936+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PAUSED positionMs=18240 volume=27 Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.937+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:10 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:10.938+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:10 volumio volumio[1941]: info: FusionDsp - volume level for loudness 27 gain applied 11.76 Oct 12 22:08:10 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Oct 12 22:08:10 volumio go-librespot[2265]: time="2026-10-12T22:08:10+09:00" level=debug msg="update volume requested to 15073/65535" Oct 12 22:08:11 volumio go-librespot[2265]: time="2026-10-12T22:08:11+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:11 volumio go-librespot[2265]: time="2026-10-12T22:08:11+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:11 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":23,"max":100}} Oct 12 22:08:11 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 23 Oct 12 22:08:11 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 23 Oct 12 22:08:11 volumio volumio[1941]: info: VolumeController::SetAlsaVolume23 Oct 12 22:08:11 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:11 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:11 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:11 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:11.224+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" state=STATUS_PAUSED positionMs=18240 volume=23 Oct 12 22:08:11 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:11.225+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PAUSED positionMs=18240 volume=23 Oct 12 22:08:11 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:11.226+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:11 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:11.226+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:11 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:11 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:11 volumio volumio[1941]: info: FusionDsp - volume level for loudness 23 gain applied 13.8 Oct 12 22:08:11 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 23 Oct 12 22:08:11 volumio volumio[1941]: error: FusionDsp - Reload WebSocket error: [object Object] Oct 12 22:08:11 volumio go-librespot[2265]: time="2026-10-12T22:08:11+09:00" level=debug msg="update volume requested to 12452/65535" Oct 12 22:08:11 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:11 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:11 volumio volumio[1941]: error: FusionDsp - Reload WebSocket error: [object Object] Oct 12 22:08:11 volumio go-librespot[2265]: time="2026-10-12T22:08:11+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:11 volumio go-librespot[2265]: time="2026-10-12T22:08:11+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:11 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":19,"max":100}} Oct 12 22:08:11 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 19 Oct 12 22:08:11 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 19 Oct 12 22:08:11 volumio volumio[1941]: info: VolumeController::SetAlsaVolume19 Oct 12 22:08:11 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:11 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:11 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:11 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:11.567+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" state=STATUS_PAUSED positionMs=18240 volume=19 Oct 12 22:08:11 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:11.568+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PAUSED positionMs=18240 volume=19 Oct 12 22:08:11 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:11.568+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964,00:00:00:00:00:00%01 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:11 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:11.569+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:11 volumio volumio[1941]: info: FusionDsp - volume level for loudness 19 gain applied 15.84 Oct 12 22:08:11 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 19 Oct 12 22:08:11 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:11 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:11 volumio volumio[1941]: error: FusionDsp - Reload WebSocket error: [object Object] Oct 12 22:08:11 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:11.990+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:12 volumio go-librespot[2265]: time="2026-10-12T22:08:12+09:00" level=debug msg="handling resume player command from 4cb279a463956a3953e40cb225cda130a3d86879" Oct 12 22:08:12 volumio go-librespot[2265]: time="2026-10-12T22:08:12+09:00" level=trace msg="seek to 18240ms (diff: 122ms, samples: 804384, bytes: 782703)" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:12 volumio go-librespot[2265]: time="2026-10-12T22:08:12+09: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" Oct 12 22:08:12 volumio go-librespot[2265]: time="2026-10-12T22:08:12+09:00" level=debug msg="resume track at 18093ms" Oct 12 22:08:12 volumio go-librespot[2265]: time="2026-10-12T22:08:12+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 12 22:08:12 volumio go-librespot[2265]: time="2026-10-12T22:08:12+09:00" level=trace msg="scheduling prefetch in 176s" Oct 12 22:08:12 volumio go-librespot[2265]: time="2026-10-12T22:08:12+09:00" level=debug msg="sending successful reply for dealer request" Oct 12 22:08:12 volumio volumio[1941]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Oct 12 22:08:12 volumio volumio[1941]: info: FusionDsp - ---- read samplerate from file: 44100 Oct 12 22:08:12 volumio go-librespot[2265]: time="2026-10-12T22:08:12+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 12 22:08:12 volumio go-librespot[2265]: time="2026-10-12T22:08:12+09:00" level=trace msg="emitting websocket event: playing" Oct 12 22:08:12 volumio volumio[1941]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:album:3EfalQgCGR2bh5tkZdZTTR","uri":"spotify:track:02KRPJcx4TJFLCXt9qwEUE","resume":true,"play_origin":"android-auto"}} Oct 12 22:08:12 volumio volumio[1941]: SPOTIFY: PUSH STATE SPOTIFY Oct 12 22:08:12 volumio volumio[1941]: SPOTIFY: {"status":"play","service":"spop","title":"Unknown Planet","artist":"IU","album":"Unknown Planet","albumart":"https://i.scdn.co/image/ab67616d00001e023ae0500dbe6192b013e36649","uri":"spotify:track:02KRPJcx4TJFLCXt9qwEUE","trackType":"spotify","seek":18240,"duration":225,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 12 22:08:12 volumio volumio[1941]: info: CoreCommandRouter::servicePushState Oct 12 22:08:12 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:12 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:12 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:12 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:12.363+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=18240 volume=19 Oct 12 22:08:12 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:12.364+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=18240 volume=19 Oct 12 22:08:12 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:12.365+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:12 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:12.365+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:12 volumio volumio[1941]: info: FusionDsp - volume level for loudness 19 gain applied 15.84 Oct 12 22:08:12 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 19 Oct 12 22:08:12 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:12 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:12 volumio volumio[1941]: SPOTIFY: PUSH STATE SPOTIFY Oct 12 22:08:12 volumio volumio[1941]: SPOTIFY: {"status":"play","service":"spop","title":"Unknown Planet","artist":"IU","album":"Unknown Planet","albumart":"https://i.scdn.co/image/ab67616d00001e023ae0500dbe6192b013e36649","uri":"spotify:track:02KRPJcx4TJFLCXt9qwEUE","trackType":"spotify","seek":18240,"duration":225,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 12 22:08:12 volumio volumio[1941]: info: CoreCommandRouter::servicePushState Oct 12 22:08:12 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:12 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:12 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:12.676+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=18240 volume=19 Oct 12 22:08:12 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:12.677+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=18240 volume=19 Oct 12 22:08:12 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:12.678+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:12 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:12.678+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:12 volumio volumio[1941]: info: FusionDsp - volume level for loudness 19 gain applied 15.84 Oct 12 22:08:12 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 19 Oct 12 22:08:12 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:12 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:14 volumio go-librespot[2265]: time="2026-10-12T22:08:14+09:00" level=debug msg="update volume requested to 15073/65535" Oct 12 22:08:14 volumio go-librespot[2265]: time="2026-10-12T22:08:14+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:14 volumio go-librespot[2265]: time="2026-10-12T22:08:14+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:14 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":23,"max":100}} Oct 12 22:08:14 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 23 Oct 12 22:08:14 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 23 Oct 12 22:08:14 volumio volumio[1941]: info: VolumeController::SetAlsaVolume23 Oct 12 22:08:14 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:14 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:14 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:14 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:14.561+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=20240 volume=23 Oct 12 22:08:14 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:14.561+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=20240 volume=23 Oct 12 22:08:14 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:14.562+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:14 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:14.563+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:14 volumio volumio[1941]: info: FusionDsp - volume level for loudness 23 gain applied 13.8 Oct 12 22:08:14 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 23 Oct 12 22:08:14 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:14 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:14 volumio go-librespot[2265]: time="2026-10-12T22:08:14+09:00" level=debug msg="update volume requested to 17694/65535" Oct 12 22:08:15 volumio go-librespot[2265]: time="2026-10-12T22:08:15+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:15 volumio go-librespot[2265]: time="2026-10-12T22:08:15+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:15 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":27,"max":100}} Oct 12 22:08:15 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 27 Oct 12 22:08:15 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 27 Oct 12 22:08:15 volumio volumio[1941]: info: VolumeController::SetAlsaVolume27 Oct 12 22:08:15 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:15 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:15 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:15 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:15.134+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=20240 volume=27 Oct 12 22:08:15 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:15.135+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=20240 volume=27 Oct 12 22:08:15 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:15.136+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:15 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:15.136+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:15 volumio volumio[1941]: info: FusionDsp - volume level for loudness 27 gain applied 11.76 Oct 12 22:08:15 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Oct 12 22:08:15 volumio go-librespot[2265]: time="2026-10-12T22:08:15+09:00" level=debug msg="update volume requested to 20316/65535" Oct 12 22:08:15 volumio go-librespot[2265]: time="2026-10-12T22:08:15+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:15 volumio go-librespot[2265]: time="2026-10-12T22:08:15+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:15 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":31,"max":100}} Oct 12 22:08:15 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 31 Oct 12 22:08:15 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 31 Oct 12 22:08:15 volumio volumio[1941]: info: VolumeController::SetAlsaVolume31 Oct 12 22:08:15 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:15 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:15 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:15 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:15.448+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=21240 volume=31 Oct 12 22:08:15 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:15.449+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=21240 volume=31 Oct 12 22:08:15 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:15.450+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:15 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:15.450+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:15 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:15 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:15 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:15.474+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:15 volumio volumio[1941]: info: FusionDsp - volume level for loudness 31 gain applied 9.71 Oct 12 22:08:15 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 31 Oct 12 22:08:15 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:15 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:16 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 12 22:08:16 volumio volumio[1941]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 12 22:08:16 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 12 22:08:16 volumio volumio[1941]: info: Received Get System Version Oct 12 22:08:16 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 12 22:08:16 volumio volumio[1941]: info: Received Get System Info Oct 12 22:08:16 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 12 22:08:16 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 12 22:08:16 volumio volumio[1941]: info: Discovery: Getting this device information Oct 12 22:08:16 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:08:16 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 12 22:08:17 volumio go-librespot[2265]: time="2026-10-12T22:08:17+09:00" level=debug msg="fetched chunk 5/18, size: 524288" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:17 volumio go-librespot[2265]: time="2026-10-12T22:08:17+09:00" level=debug msg="update volume requested to 17694/65535" Oct 12 22:08:18 volumio go-librespot[2265]: time="2026-10-12T22:08:18+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:18 volumio go-librespot[2265]: time="2026-10-12T22:08:18+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:18 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":27,"max":100}} Oct 12 22:08:18 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 27 Oct 12 22:08:18 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 27 Oct 12 22:08:18 volumio volumio[1941]: info: VolumeController::SetAlsaVolume27 Oct 12 22:08:18 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:18 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:18 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:18 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:18.228+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=23240 volume=27 Oct 12 22:08:18 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:18.228+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=23240 volume=27 Oct 12 22:08:18 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:18.230+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:18 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:18.231+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:18 volumio volumio[1941]: info: FusionDsp - volume level for loudness 27 gain applied 11.76 Oct 12 22:08:18 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Oct 12 22:08:18 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:18 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:19 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:19.132+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:22 volumio go-librespot[2265]: time="2026-10-12T22:08:22+09:00" level=debug msg="update volume requested to 23769/65535" Oct 12 22:08:22 volumio go-librespot[2265]: time="2026-10-12T22:08:22+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:22 volumio go-librespot[2265]: time="2026-10-12T22:08:22+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:22 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":36,"max":100}} Oct 12 22:08:22 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 36 Oct 12 22:08:22 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 36 Oct 12 22:08:22 volumio volumio[1941]: info: VolumeController::SetAlsaVolume36 Oct 12 22:08:22 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:22 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:22 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:22 volumio go-librespot[2265]: time="2026-10-12T22:08:22+09:00" level=debug msg="update volume requested to 44639/65535" Oct 12 22:08:22 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:22.250+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=27240 volume=36 Oct 12 22:08:22 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:22.256+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=27240 volume=36 Oct 12 22:08:22 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:22.257+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:22 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:22.258+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:22 volumio volumio[1941]: info: FusionDsp - volume level for loudness 36 gain applied 7.16 Oct 12 22:08:22 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 36 Oct 12 22:08:22 volumio go-librespot[2265]: time="2026-10-12T22:08:22+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:22 volumio go-librespot[2265]: time="2026-10-12T22:08:22+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:22 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":68,"max":100}} Oct 12 22:08:22 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 68 Oct 12 22:08:22 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 68 Oct 12 22:08:22 volumio volumio[1941]: info: VolumeController::SetAlsaVolume68 Oct 12 22:08:22 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:22 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:22 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:22 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:22.488+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=28240 volume=68 Oct 12 22:08:22 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:22.488+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=28240 volume=68 Oct 12 22:08:22 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:22.489+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:22 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:22.490+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:22 volumio volumio[1941]: info: FusionDsp - volume level for loudness 68 gain applied 0 Oct 12 22:08:22 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68 Oct 12 22:08:22 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:22.614+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:22 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:22 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:22 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:24 volumio go-librespot[2265]: time="2026-10-12T22:08:24+09:00" level=debug msg="update volume requested to 41705/65535" Oct 12 22:08:24 volumio go-librespot[2265]: time="2026-10-12T22:08:24+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:24 volumio go-librespot[2265]: time="2026-10-12T22:08:24+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:24 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":64,"max":100}} Oct 12 22:08:24 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 64 Oct 12 22:08:24 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 64 Oct 12 22:08:24 volumio volumio[1941]: info: VolumeController::SetAlsaVolume64 Oct 12 22:08:24 volumio go-librespot[2265]: time="2026-10-12T22:08:24+09:00" level=debug msg="update volume requested to 34642/65535" Oct 12 22:08:24 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:24 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:24 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:24 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:24.293+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=29240 volume=64 Oct 12 22:08:24 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:24.294+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=29240 volume=64 Oct 12 22:08:24 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:24.294+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:24 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:24.295+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:24 volumio volumio[1941]: info: FusionDsp - volume level for loudness 64 gain applied 0 Oct 12 22:08:24 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 64 Oct 12 22:08:24 volumio go-librespot[2265]: time="2026-10-12T22:08:24+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:24 volumio go-librespot[2265]: time="2026-10-12T22:08:24+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:24 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":53,"max":100}} Oct 12 22:08:24 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 53 Oct 12 22:08:24 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 53 Oct 12 22:08:24 volumio volumio[1941]: info: VolumeController::SetAlsaVolume53 Oct 12 22:08:24 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:24 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:24 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:24 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:24.491+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=30240 volume=53 Oct 12 22:08:24 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:24.492+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=30240 volume=53 Oct 12 22:08:24 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:24.493+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:24 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:24.493+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:24 volumio volumio[1941]: info: FusionDsp - volume level for loudness 53 gain applied 0 Oct 12 22:08:24 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 53 Oct 12 22:08:24 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:24 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:24 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:25 volumio go-librespot[2265]: time="2026-10-12T22:08:25+09:00" level=debug msg="update volume requested to 37978/65535" Oct 12 22:08:26 volumio go-librespot[2265]: time="2026-10-12T22:08:26+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:26 volumio go-librespot[2265]: time="2026-10-12T22:08:26+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:26 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":58,"max":100}} Oct 12 22:08:26 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 58 Oct 12 22:08:26 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 58 Oct 12 22:08:26 volumio volumio[1941]: info: VolumeController::SetAlsaVolume58 Oct 12 22:08:26 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:26 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:26 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:26 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:26.212+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=31240 volume=58 Oct 12 22:08:26 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:26.214+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=31240 volume=58 Oct 12 22:08:26 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:26.214+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:26 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:26.215+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:26 volumio volumio[1941]: info: FusionDsp - volume level for loudness 58 gain applied 0 Oct 12 22:08:26 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Oct 12 22:08:26 volumio go-librespot[2265]: time="2026-10-12T22:08:26+09:00" level=debug msg="update volume requested to 57095/65535" Oct 12 22:08:26 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:26.420+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:26 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:26 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:26 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:26 volumio go-librespot[2265]: time="2026-10-12T22:08:26+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:26 volumio go-librespot[2265]: time="2026-10-12T22:08:26+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:26 volumio go-librespot[2265]: time="2026-10-12T22:08:26+09:00" level=debug msg="update volume requested to 57008/65535" Oct 12 22:08:26 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":87,"max":100}} Oct 12 22:08:26 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 87 Oct 12 22:08:26 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 87 Oct 12 22:08:26 volumio volumio[1941]: info: VolumeController::SetAlsaVolume87 Oct 12 22:08:26 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:26 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:26 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:26 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:26.663+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=32240 volume=87 Oct 12 22:08:26 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:26.664+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=32240 volume=87 Oct 12 22:08:26 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:26.665+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:26 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:26.665+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:26 volumio volumio[1941]: info: FusionDsp - volume level for loudness 87 gain applied 0 Oct 12 22:08:26 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 87 Oct 12 22:08:26 volumio go-librespot[2265]: time="2026-10-12T22:08:26+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:26 volumio go-librespot[2265]: time="2026-10-12T22:08:26+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:26 volumio go-librespot[2265]: time="2026-10-12T22:08:26+09:00" level=debug msg="update volume requested to 56598/65535" Oct 12 22:08:26 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":87,"max":100}} Oct 12 22:08:26 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 87 Oct 12 22:08:26 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:26 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:26 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:27 volumio go-librespot[2265]: time="2026-10-12T22:08:27+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:27 volumio go-librespot[2265]: time="2026-10-12T22:08:27+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:27 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Oct 12 22:08:27 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Oct 12 22:08:27 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 86 Oct 12 22:08:27 volumio volumio[1941]: info: VolumeController::SetAlsaVolume86 Oct 12 22:08:27 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:27 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:27 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:27 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:27.059+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=32240 volume=86 Oct 12 22:08:27 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:27.059+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=32240 volume=86 Oct 12 22:08:27 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:27.061+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:27 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:27.062+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:27 volumio volumio[1941]: info: FusionDsp - volume level for loudness 86 gain applied 0 Oct 12 22:08:27 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Oct 12 22:08:27 volumio go-librespot[2265]: time="2026-10-12T22:08:27+09:00" level=debug msg="update volume requested to 41822/65535" Oct 12 22:08:27 volumio go-librespot[2265]: time="2026-10-12T22:08:27+09:00" level=debug msg="update volume requested to 56214/65535" Oct 12 22:08:27 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:27 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:27 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:27 volumio go-librespot[2265]: time="2026-10-12T22:08:27+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:27 volumio go-librespot[2265]: time="2026-10-12T22:08:27+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:27 volumio go-librespot[2265]: time="2026-10-12T22:08:27+09:00" level=debug msg="update volume requested to 34566/65535" Oct 12 22:08:27 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Oct 12 22:08:27 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Oct 12 22:08:27 volumio go-librespot[2265]: time="2026-10-12T22:08:27+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:27 volumio go-librespot[2265]: time="2026-10-12T22:08:27+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:27 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":53,"max":100}} Oct 12 22:08:27 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 53 Oct 12 22:08:27 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 53 Oct 12 22:08:27 volumio volumio[1941]: info: VolumeController::SetAlsaVolume53 Oct 12 22:08:27 volumio go-librespot[2265]: time="2026-10-12T22:08:27+09:00" level=debug msg="update volume requested to 29899/65535" Oct 12 22:08:27 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:27 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:27 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:27 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:27.713+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=33240 volume=53 Oct 12 22:08:27 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:27.714+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=33240 volume=53 Oct 12 22:08:27 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:27.715+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:27 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:27.715+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:27 volumio volumio[1941]: info: FusionDsp - volume level for loudness 53 gain applied 0 Oct 12 22:08:27 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 53 Oct 12 22:08:27 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:27 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:27 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:28 volumio go-librespot[2265]: time="2026-10-12T22:08:28+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:28 volumio go-librespot[2265]: time="2026-10-12T22:08:28+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:28 volumio go-librespot[2265]: time="2026-10-12T22:08:28+09:00" level=debug msg="update volume requested to 27039/65535" Oct 12 22:08:28 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Oct 12 22:08:28 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Oct 12 22:08:28 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 46 Oct 12 22:08:28 volumio volumio[1941]: info: VolumeController::SetAlsaVolume46 Oct 12 22:08:28 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:28 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:28 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.084+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=33240 volume=46 Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.084+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=33240 volume=46 Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.085+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.086+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:28 volumio volumio[1941]: info: FusionDsp - volume level for loudness 46 gain applied 2.04 Oct 12 22:08:28 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Oct 12 22:08:28 volumio go-librespot[2265]: time="2026-10-12T22:08:28+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:28 volumio go-librespot[2265]: time="2026-10-12T22:08:28+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:28 volumio go-librespot[2265]: time="2026-10-12T22:08:28+09:00" level=debug msg="update volume requested to 24500/65535" Oct 12 22:08:28 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":41,"max":100}} Oct 12 22:08:28 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 41 Oct 12 22:08:28 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 41 Oct 12 22:08:28 volumio volumio[1941]: info: VolumeController::SetAlsaVolume41 Oct 12 22:08:28 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:28 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:28 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.267+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=33240 volume=41 Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.267+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=33240 volume=41 Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.268+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.269+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:28 volumio volumio[1941]: info: FusionDsp - volume level for loudness 41 gain applied 4.6 Oct 12 22:08:28 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 Oct 12 22:08:28 volumio go-librespot[2265]: time="2026-10-12T22:08:28+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:28 volumio go-librespot[2265]: time="2026-10-12T22:08:28+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:28 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":37,"max":100}} Oct 12 22:08:28 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 37 Oct 12 22:08:28 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 37 Oct 12 22:08:28 volumio volumio[1941]: info: VolumeController::SetAlsaVolume37 Oct 12 22:08:28 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:28 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:28 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.448+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=34240 volume=37 Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.450+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=34240 volume=37 Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.451+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.452+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:28 volumio volumio[1941]: info: FusionDsp - volume level for loudness 37 gain applied 6.64 Oct 12 22:08:28 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 37 Oct 12 22:08:28 volumio go-librespot[2265]: time="2026-10-12T22:08:28+09:00" level=debug msg="update volume requested to 24928/65535" Oct 12 22:08:28 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:28 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:28 volumio go-librespot[2265]: time="2026-10-12T22:08:28+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:28 volumio go-librespot[2265]: time="2026-10-12T22:08:28+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:28 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":38,"max":100}} Oct 12 22:08:28 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 38 Oct 12 22:08:28 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 38 Oct 12 22:08:28 volumio volumio[1941]: info: VolumeController::SetAlsaVolume38 Oct 12 22:08:28 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:28 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:28 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.787+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=34240 volume=38 Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.788+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=34240 volume=38 Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.789+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:28 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:28.789+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:28 volumio volumio[1941]: info: FusionDsp - volume level for loudness 38 gain applied 6.13 Oct 12 22:08:28 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Oct 12 22:08:28 volumio go-librespot[2265]: time="2026-10-12T22:08:28+09:00" level=debug msg="update volume requested to 27412/65535" Oct 12 22:08:29 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:29 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:29 volumio go-librespot[2265]: time="2026-10-12T22:08:29+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:29 volumio go-librespot[2265]: time="2026-10-12T22:08:29+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:29 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":42,"max":100}} Oct 12 22:08:29 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 42 Oct 12 22:08:29 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 42 Oct 12 22:08:29 volumio volumio[1941]: info: VolumeController::SetAlsaVolume42 Oct 12 22:08:29 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:29 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:29 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:29 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:29.150+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=34240 volume=42 Oct 12 22:08:29 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:29.151+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=34240 volume=42 Oct 12 22:08:29 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:29.153+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:29 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:29.153+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:29 volumio volumio[1941]: info: FusionDsp - volume level for loudness 42 gain applied 4.09 Oct 12 22:08:29 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42 Oct 12 22:08:29 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:29 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:30 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:29.998+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:30 volumio go-librespot[2265]: time="2026-10-12T22:08:30+09:00" level=debug msg="fetched chunk 6/18, size: 524288" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:32 volumio go-librespot[2265]: time="2026-10-12T22:08:32+09:00" level=trace msg="sent dealer ping" Oct 12 22:08:32 volumio go-librespot[2265]: time="2026-10-12T22:08:32+09:00" level=trace msg="received dealer pong" Oct 12 22:08:33 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:33.560+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:36 volumio go-librespot[2265]: time="2026-10-12T22:08:36+09:00" level=debug msg="update volume requested to 32380/65535" Oct 12 22:08:36 volumio go-librespot[2265]: time="2026-10-12T22:08:36+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:36 volumio go-librespot[2265]: time="2026-10-12T22:08:36+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:36 volumio go-librespot[2265]: time="2026-10-12T22:08:36+09:00" level=debug msg="update volume requested to 35817/65535" Oct 12 22:08:36 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":49,"max":100}} Oct 12 22:08:36 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 49 Oct 12 22:08:36 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 49 Oct 12 22:08:36 volumio volumio[1941]: info: VolumeController::SetAlsaVolume49 Oct 12 22:08:36 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:36 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:36 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:36 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:36.311+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=41240 volume=49 Oct 12 22:08:36 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:36.311+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=41240 volume=49 Oct 12 22:08:36 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:36.312+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:36 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:36.313+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:36 volumio volumio[1941]: info: FusionDsp - volume level for loudness 49 gain applied 0.51 Oct 12 22:08:36 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Oct 12 22:08:36 volumio go-librespot[2265]: time="2026-10-12T22:08:36+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:36 volumio go-librespot[2265]: time="2026-10-12T22:08:36+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:36 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":55,"max":100}} Oct 12 22:08:36 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 55 Oct 12 22:08:36 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 55 Oct 12 22:08:36 volumio volumio[1941]: info: VolumeController::SetAlsaVolume55 Oct 12 22:08:36 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:36 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:36 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:36 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:36.502+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=42240 volume=55 Oct 12 22:08:36 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:36.503+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=42240 volume=55 Oct 12 22:08:36 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:36.504+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:36 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:36.504+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:36 volumio volumio[1941]: info: FusionDsp - volume level for loudness 55 gain applied 0 Oct 12 22:08:36 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 55 Oct 12 22:08:36 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:36 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:36 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:37 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:37.131+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:37 volumio go-librespot[2265]: time="2026-10-12T22:08:37+09:00" level=debug msg="update volume requested to 40722/65535" Oct 12 22:08:37 volumio go-librespot[2265]: time="2026-10-12T22:08:37+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:37 volumio go-librespot[2265]: time="2026-10-12T22:08:37+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:37 volumio go-librespot[2265]: time="2026-10-12T22:08:37+09:00" level=debug msg="update volume requested to 42503/65535" Oct 12 22:08:37 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":62,"max":100}} Oct 12 22:08:37 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 62 Oct 12 22:08:37 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 62 Oct 12 22:08:37 volumio volumio[1941]: info: VolumeController::SetAlsaVolume62 Oct 12 22:08:37 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:37 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:37 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:38 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:37.999+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=43240 volume=62 Oct 12 22:08:38 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:38.000+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=43240 volume=62 Oct 12 22:08:38 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:38.001+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:38 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:38.002+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:38 volumio volumio[1941]: info: FusionDsp - volume level for loudness 62 gain applied 0 Oct 12 22:08:38 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 62 Oct 12 22:08:38 volumio go-librespot[2265]: time="2026-10-12T22:08:38+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:38 volumio go-librespot[2265]: time="2026-10-12T22:08:38+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:38 volumio go-librespot[2265]: time="2026-10-12T22:08:38+09:00" level=debug msg="update volume requested to 42571/65535" Oct 12 22:08:38 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":65,"max":100}} Oct 12 22:08:38 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 65 Oct 12 22:08:38 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 65 Oct 12 22:08:38 volumio volumio[1941]: info: VolumeController::SetAlsaVolume65 Oct 12 22:08:38 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:38 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:38 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:38 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:38.305+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=43240 volume=65 Oct 12 22:08:38 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:38.306+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=43240 volume=65 Oct 12 22:08:38 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:38.306+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:38 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:38.307+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:38 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:38 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:38 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:38 volumio volumio[1941]: info: FusionDsp - volume level for loudness 65 gain applied 0 Oct 12 22:08:38 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 65 Oct 12 22:08:38 volumio go-librespot[2265]: time="2026-10-12T22:08:38+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:38 volumio go-librespot[2265]: time="2026-10-12T22:08:38+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:38 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":65,"max":100}} Oct 12 22:08:38 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 65 Oct 12 22:08:38 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:38 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:38 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:40 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:40.702+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:40 volumio go-librespot[2265]: time="2026-10-12T22:08:40+09:00" level=debug msg="update volume requested to 47171/65535" Oct 12 22:08:41 volumio go-librespot[2265]: time="2026-10-12T22:08:41+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:41 volumio go-librespot[2265]: time="2026-10-12T22:08:41+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:41 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":72,"max":100}} Oct 12 22:08:41 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 72 Oct 12 22:08:41 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 72 Oct 12 22:08:41 volumio volumio[1941]: info: VolumeController::SetAlsaVolume72 Oct 12 22:08:41 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:41 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:41 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:41 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:41.085+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=46240 volume=72 Oct 12 22:08:41 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:41.086+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=46240 volume=72 Oct 12 22:08:41 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:41.087+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:41 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:41.087+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:41 volumio volumio[1941]: info: FusionDsp - volume level for loudness 72 gain applied 0 Oct 12 22:08:41 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Oct 12 22:08:41 volumio go-librespot[2265]: time="2026-10-12T22:08:41+09:00" level=debug msg="update volume requested to 48579/65535" Oct 12 22:08:41 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:41 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:41 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:41 volumio go-librespot[2265]: time="2026-10-12T22:08:41+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:41 volumio go-librespot[2265]: time="2026-10-12T22:08:41+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:41 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":74,"max":100}} Oct 12 22:08:41 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 74 Oct 12 22:08:41 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 74 Oct 12 22:08:41 volumio volumio[1941]: info: VolumeController::SetAlsaVolume74 Oct 12 22:08:41 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:41 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:41 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:41 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:41.413+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=46240 volume=74 Oct 12 22:08:41 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:41.413+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=46240 volume=74 Oct 12 22:08:41 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:41.414+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:41 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:41.414+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:41 volumio volumio[1941]: info: FusionDsp - volume level for loudness 74 gain applied 0 Oct 12 22:08:41 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 74 Oct 12 22:08:41 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:41 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:41 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:43 volumio go-librespot[2265]: time="2026-10-12T22:08:43+09:00" level=debug msg="fetched chunk 7/18, size: 524288" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:44 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:44.061+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:44 volumio go-librespot[2265]: time="2026-10-12T22:08:44+09:00" level=debug msg="update volume requested to 45875/65535" Oct 12 22:08:45 volumio go-librespot[2265]: time="2026-10-12T22:08:45+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 12 22:08:45 volumio go-librespot[2265]: time="2026-10-12T22:08:45+09:00" level=trace msg="emitting websocket event: volume" Oct 12 22:08:45 volumio volumio[1941]: SPOTIFY: received: {"type":"volume","data":{"value":70,"max":100}} Oct 12 22:08:45 volumio volumio[1941]: SPOTIFY: RECEIVED SPOTIFY VOLUME 70 Oct 12 22:08:45 volumio volumio[1941]: info: Setting Volumio Volume from Spotify: 70 Oct 12 22:08:45 volumio volumio[1941]: info: VolumeController::SetAlsaVolume70 Oct 12 22:08:45 volumio volumio[1941]: info: CoreStateMachine::pushState Oct 12 22:08:45 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 22:08:45 volumio volumio[1941]: info: CoreCommandRouter::volumioPushState Oct 12 22:08:45 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:45.169+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" state=STATUS_PLAYING positionMs=50240 volume=70 Oct 12 22:08:45 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:45.170+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" state=STATUS_PLAYING positionMs=50240 volume=70 Oct 12 22:08:45 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:45.171+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.164:38964 @ 0x2ec3740" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:45 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:45.172+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" id=spotify:track:02KRPJcx4TJFLCXt9qwEUE title="Unknown Planet" Oct 12 22:08:45 volumio volumio[1941]: info: FusionDsp - volume level for loudness 70 gain applied 0 Oct 12 22:08:45 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Oct 12 22:08:45 volumio volumio[1941]: info: FusionDsp - If filter freq >samplerate/2 then disable it Oct 12 22:08:45 volumio volumio[1941]: info: FusionDsp - Loudness is ON true Oct 12 22:08:45 volumio volumio[1941]: info: FusionDsp - else 1 -1 Oct 12 22:08:47 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:47.601+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:48 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:48.994+09:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s Oct 12 22:08:49 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:49.001+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=5.80298ms Oct 12 22:08:49 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:49.103+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=104.280106ms Oct 12 22:08:49 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:49.106+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=107.215946ms Oct 12 22:08:49 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:49.128+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=https://www.googleapis.com duration=132.410945ms Oct 12 22:08:49 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:49.158+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=https://google.com duration=162.422568ms Oct 12 22:08:49 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:49.174+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=177.085045ms Oct 12 22:08:49 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:49.248+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=http://pushupdates.volumio.org duration=249.626911ms Oct 12 22:08:49 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:49.248+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=https://securetoken.googleapis.com duration=251.118842ms Oct 12 22:08:49 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 12 22:08:49 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 12 22:08:49 volumio volumio[1941]: info: Discovery: Getting this device information Oct 12 22:08:49 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:08:49 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 12 22:08:49 volumio volumio[1941]: verbose: New Socket.io Connection to 192.168.0.145:3000 from 192.168.0.199 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 9 Oct 12 22:08:49 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 12 22:08:49 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 12 22:08:50 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:50.110+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=https://functions.volumio.cloud duration=1.112406263s Oct 12 22:08:50 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:50.110+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=https://functions.volumio.cloud duration=1.111523813s Oct 12 22:08:50 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:50.205+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=https://database.volumio.cloud duration=1.206359891s Oct 12 22:08:50 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:50.845+09:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=http://cddb.volumio.org duration=1.847226717s error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 12 22:08:51 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:51.232+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:53 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:53.236+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=87.75645ms timeout=10s endpoint=http://plugins.volumio.org duration=4.236736308s Oct 12 22:08:54 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:54.590+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:08:56 volumio go-librespot[2265]: time="2026-10-12T22:08:56+09:00" level=debug msg="fetched chunk 8/18, size: 524288" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:08:58 volumio volumio5-onboarding[1715]: time=2026-10-12T22:08:58.222+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:09:00 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:00.713+09:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=67.990892ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Oct 12 22:09:00 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:00.736+09:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s Oct 12 22:09:00 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:00.746+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=9.490542ms Oct 12 22:09:00 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:00.872+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=133.155806ms Oct 12 22:09:00 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:00.872+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=134.930915ms Oct 12 22:09:00 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:00.877+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=https://www.googleapis.com duration=140.693375ms Oct 12 22:09:00 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:00.921+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=182.729038ms Oct 12 22:09:00 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:00.954+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=https://google.com duration=216.626975ms Oct 12 22:09:00 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:00.993+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=http://pushupdates.volumio.org duration=255.27461ms Oct 12 22:09:00 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:00.993+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=https://securetoken.googleapis.com duration=255.30086ms Oct 12 22:09:01 volumio sudo[2829]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 12 22:09:01 volumio sudo[2829]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 12 22:09:01 volumio sudo[2831]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 12 22:09:01 volumio sudo[2829]: pam_unix(sudo:session): session closed for user root Oct 12 22:09:01 volumio sudo[2831]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 12 22:09:01 volumio sudo[2831]: pam_unix(sudo:session): session closed for user root Oct 12 22:09:01 volumio volumio[1941]: verbose: New Socket.io Connection to 192.168.0.145 from 192.168.0.199 UA: Mozilla/5.0 (Linux; Android 17; SM-S928N Build/CP2A.260605.016; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/154.0.8037.106 Mobile Safari/537.36 VolumioApp/6.260930.0 Engine version: 3 Transport: polling Total Clients: 8 Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::volumioGetVisibleSources Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 12 22:09:01 volumio volumio[1941]: info: Received Get System Info Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 12 22:09:01 volumio volumio[1941]: info: Discovery: Getting this device information Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:01 volumio volumio[1941]: info: Listing playlists Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 12 22:09:01 volumio sudo[2835]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 12 22:09:01 volumio sudo[2835]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 12 22:09:01 volumio sudo[2835]: pam_unix(sudo:session): session closed for user root Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 12 22:09:01 volumio sudo[2837]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 12 22:09:01 volumio sudo[2837]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 12 22:09:01 volumio sudo[2837]: pam_unix(sudo:session): session closed for user root Oct 12 22:09:01 volumio volumio[1941]: verbose: New Socket.io Connection to 192.168.0.145 from 192.168.0.199 UA: Mozilla/5.0 (Linux; Android 17; SM-S928N Build/CP2A.260605.016; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/154.0.8037.106 Mobile Safari/537.36 VolumioApp/6.260930.0 Engine version: 3 Transport: polling Total Clients: 8 Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 12 22:09:01 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:01.832+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=https://functions.volumio.cloud duration=1.095206317s Oct 12 22:09:01 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:01.861+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=https://functions.volumio.cloud duration=1.1229932s Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::volumioGetVisibleSources Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 12 22:09:01 volumio volumio[1941]: info: Received Get System Info Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 12 22:09:01 volumio volumio[1941]: info: Discovery: Getting this device information Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:01 volumio volumio[1941]: info: Listing playlists Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 12 22:09:01 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:01.936+09:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=http://cddb.volumio.org duration=1.198770187s error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 12 22:09:01 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:01.975+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:09:01 volumio volumio[1941]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 12 22:09:02 volumio go-librespot[2265]: time="2026-10-12T22:09:02+09:00" level=trace msg="sent dealer ping" Oct 12 22:09:02 volumio go-librespot[2265]: time="2026-10-12T22:09:02+09:00" level=trace msg="received dealer pong" Oct 12 22:09:03 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 12 22:09:03 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 12 22:09:03 volumio volumio[1941]: info: Received Get System Info Oct 12 22:09:03 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 12 22:09:03 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 12 22:09:03 volumio volumio[1941]: info: Discovery: Getting this device information Oct 12 22:09:03 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:03 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 12 22:09:03 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:03.690+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=http://plugins.volumio.org duration=2.951675241s Oct 12 22:09:04 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 12 22:09:04 volumio volumio[1941]: info: Received Get System Info Oct 12 22:09:04 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 12 22:09:04 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 12 22:09:04 volumio volumio[1941]: info: Discovery: Getting this device information Oct 12 22:09:04 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:04 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 12 22:09:04 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 12 22:09:04 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 12 22:09:04 volumio volumio[1941]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 12 22:09:05 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:05.602+09:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 Oct 12 22:09:06 volumio volumio5-onboarding[1715]: time=2026-10-12T22:09:06.144+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.199:40928,00:00:00:00:00:00%03 @ 0x300e930" latency=64.68102ms timeout=10s endpoint=https://database.volumio.cloud duration=5.405370518s Oct 12 22:09:07 volumio volumio[1941]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 12 22:09:08 volumio go-librespot[2265]: time="2026-10-12T22:09:08+09:00" level=debug msg="fetched chunk 9/18, size: 524288" uri="spotify:track:02KRPJcx4TJFLCXt9qwEUE" Oct 12 22:09:11 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 12 22:09:18 volumio volumio[1941]: info: Received OAUTH Data Oct 12 22:09:18 volumio volumio[1941]: info: Executing Spotify Oauth Login Oct 12 22:09:18 volumio volumio[1941]: info: Saving Spotify Refresh Token Oct 12 22:09:18 volumio volumio[1941]: info: New Spotify access tokenBQAi1kQSSo... Oct 12 22:09:18 volumio volumio[1941]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 12 22:09:18 volumio volumio[1941]: SPOTIFY: User informations: {"account_id":"nnxTbsmzFp","country":"IN","display_name":"Tania","email":"tania20@dralune.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31gx3roqz6ud7xrs5h4cbpuyvhwe"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31gx3roqz6ud7xrs5h4cbpuyvhwe","id":"31gx3roqz6ud7xrs5h4cbpuyvhwe","images":[],"product":"premium","type":"user","uri":"spotify:user:31gx3roqz6ud7xrs5h4cbpuyvhwe"} Oct 12 22:09:18 volumio volumio[1941]: info: Creating Spotify config file Oct 12 22:09:18 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 12 22:09:18 volumio volumio[1941]: info: Spotify config file written Oct 12 22:09:18 volumio sudo[2873]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 12 22:09:18 volumio sudo[2873]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 12 22:09:18 volumio sudo[2876]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 12 22:09:18 volumio sudo[2876]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 12 22:09:18 volumio sudo[2876]: pam_unix(sudo:session): session closed for user root Oct 12 22:09:18 volumio sudo[2878]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 12 22:09:18 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Oct 12 22:09:18 volumio sudo[2878]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 12 22:09:18 volumio sudo[2878]: pam_unix(sudo:session): session closed for user root Oct 12 22:09:18 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Oct 12 22:09:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 12 22:09:18 volumio systemd[1]: go-librespot-daemon.service: Consumed 11.645s CPU time. Oct 12 22:09:18 volumio volumio[1941]: info: Connection to go-librespot Websocket closed Oct 12 22:09:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 12 22:09:19 volumio go-librespot[2881]: go-librespot daemon starting... Oct 12 22:09:19 volumio sudo[2873]: pam_unix(sudo:session): session closed for user root Oct 12 22:09:19 volumio go-librespot[2882]: time="2026-10-12T22:09:19+09:00" level=info msg="running go-librespot 0.6.2" Oct 12 22:09:19 volumio go-librespot[2882]: time="2026-10-12T22:09:19+09:00" level=debug msg="app state loaded" Oct 12 22:09:19 volumio volumio[1941]: verbose: New Socket.io Connection to 192.168.0.145 from 192.168.0.199 UA: Mozilla/5.0 (Linux; Android 17; SM-S928N Build/CP2A.260605.016; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/154.0.8037.106 Mobile Safari/537.36 VolumioApp/6.260930.0 Engine version: 3 Transport: polling Total Clients: 8 Oct 12 22:09:19 volumio go-librespot[2882]: time="2026-10-12T22:09:19+09:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 12 22:09:19 volumio volumio[1941]: info: New Spotify access tokenBQC0TLQDAi... Oct 12 22:09:19 volumio volumio[1941]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::volumioGetVisibleSources Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 12 22:09:19 volumio volumio[1941]: info: Received Get System Info Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 12 22:09:19 volumio volumio[1941]: info: Discovery: Getting this device information Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:19 volumio volumio[1941]: info: Listing playlists Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 12 22:09:19 volumio volumio[1941]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 12 22:09:19 volumio go-librespot[2882]: time="2026-10-12T22:09:19+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 12 22:09:19 volumio go-librespot[2882]: time="2026-10-12T22:09:19+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Oct 12 22:09:19 volumio go-librespot[2882]: time="2026-10-12T22:09:19+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Oct 12 22:09:19 volumio go-librespot[2882]: time="2026-10-12T22:09:19+09:00" level=info msg="zeroconf server listening on port 46427" Oct 12 22:09:19 volumio go-librespot[2882]: time="2026-10-12T22:09:19+09:00" level=debug msg="obtained new client token: AAE55o6xxED0cYyZomgX5ber/v92Yiq0/0F6JL0y6l18bh5Y2hKODW5SCwBIbt1En7NfAwRhFYdhcjMDZ8nr53tAeAnq8nxedKLMdUk3UCIXGuEDgPV58Axl/p+JOcQzEtsqIESUw9pk8CenFZM70WSID++p9nysjA+r2KEjhbw308xc3SwW3ecm/lzoFX3o16r21ib327qburMxZuo/44oNUz7p0rzSyE6K75+5J+8X2cjOZgyxZpfZskA=" Oct 12 22:09:19 volumio go-librespot[2882]: time="2026-10-12T22:09:19+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Oct 12 22:09:19 volumio go-librespot[2882]: time="2026-10-12T22:09:19+09:00" level=debug msg="completed keyexchange" Oct 12 22:09:19 volumio go-librespot[2882]: time="2026-10-12T22:09:19+09:00" level=debug msg="completed challenge" Oct 12 22:09:20 volumio volumio[1941]: info: camilladsp respawn in 100 ms (attempt 1/10) Oct 12 22:09:20 volumio volumio[1941]: SPOTIFY: User informations: {"account_id":"nnxTbsmzFp","country":"IN","display_name":"Tania","email":"tania20@dralune.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31gx3roqz6ud7xrs5h4cbpuyvhwe"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31gx3roqz6ud7xrs5h4cbpuyvhwe","id":"31gx3roqz6ud7xrs5h4cbpuyvhwe","images":[],"product":"premium","type":"user","uri":"spotify:user:31gx3roqz6ud7xrs5h4cbpuyvhwe"} Oct 12 22:09:20 volumio volumio[1941]: info: Spotify Successfully logged in Oct 12 22:09:20 volumio volumio[1941]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 12 22:09:20 volumio volumio[1941]: info: [1791810560055] CoreMusicLibrary::Adding element Spotify Oct 12 22:09:20 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 12 22:09:20 volumio volumio[1941]: Cannot find translation for source Spotify Oct 12 22:09:20 volumio go-librespot[2882]: time="2026-10-12T22:09:20+09:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: TravelRestriction " Oct 12 22:09:20 volumio go-librespot[2882]: time="2026-10-12T22:09:20+09:00" level=debug msg="connected to ap-gae2.spotify.com:443" Oct 12 22:09:20 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 12 22:09:20 volumio volumio[1941]: info: Received Get System Info Oct 12 22:09:20 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 12 22:09:20 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 12 22:09:20 volumio volumio[1941]: info: Discovery: Getting this device information Oct 12 22:09:20 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:20 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 12 22:09:20 volumio go-librespot[2882]: time="2026-10-12T22:09:20+09:00" level=debug msg="completed keyexchange" Oct 12 22:09:20 volumio go-librespot[2882]: time="2026-10-12T22:09:20+09:00" level=debug msg="completed challenge" Oct 12 22:09:20 volumio go-librespot[2882]: time="2026-10-12T22:09:20+09:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: TravelRestriction " Oct 12 22:09:20 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 12 22:09:21 volumio volumio[1941]: error: Cannot download Available plugins list: Error: ESOCKETTIMEDOUT Oct 12 22:09:21 volumio go-librespot[2882]: time="2026-10-12T22:09:21+09:00" level=debug msg="connected to ap-gae2.spotify.com:80" Oct 12 22:09:21 volumio go-librespot[2882]: time="2026-10-12T22:09:21+09:00" level=debug msg="completed keyexchange" Oct 12 22:09:21 volumio go-librespot[2882]: time="2026-10-12T22:09:21+09:00" level=debug msg="completed challenge" Oct 12 22:09:21 volumio go-librespot[2882]: time="2026-10-12T22:09:21+09:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: TravelRestriction " Oct 12 22:09:21 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 12 22:09:21 volumio volumio[1941]: info: Received Get System Info Oct 12 22:09:21 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 12 22:09:21 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 12 22:09:21 volumio volumio[1941]: info: Discovery: Getting this device information Oct 12 22:09:21 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:21 volumio volumio[1941]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 12 22:09:21 volumio volumio[1941]: info: Initializing connection to go-librespot Websocket Oct 12 22:09:21 volumio go-librespot[2882]: time="2026-10-12T22:09:21+09:00" level=debug msg="new websocket client" Oct 12 22:09:21 volumio volumio[1941]: info: Connection to go-librespot Websocket established Oct 12 22:09:22 volumio volumio[1941]: info: go-librespot daemon successfully initialized Oct 12 22:09:22 volumio go-librespot[2882]: time="2026-10-12T22:09:22+09:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Oct 12 22:09:22 volumio go-librespot[2882]: time="2026-10-12T22:09:22+09:00" level=debug msg="completed keyexchange" Oct 12 22:09:22 volumio go-librespot[2882]: time="2026-10-12T22:09:22+09:00" level=debug msg="completed challenge" Oct 12 22:09:22 volumio go-librespot[2882]: time="2026-10-12T22:09:22+09:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: TravelRestriction " Oct 12 22:09:23 volumio go-librespot[2882]: time="2026-10-12T22:09:23+09:00" level=debug msg="connected to ap-gue1.spotify.com:443" Oct 12 22:09:23 volumio go-librespot[2882]: time="2026-10-12T22:09:23+09:00" level=debug msg="completed keyexchange" Oct 12 22:09:23 volumio go-librespot[2882]: time="2026-10-12T22:09:23+09:00" level=debug msg="completed challenge" Oct 12 22:09:23 volumio go-librespot[2882]: time="2026-10-12T22:09:23+09:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: TravelRestriction " Oct 12 22:09:24 volumio go-librespot[2882]: time="2026-10-12T22:09:24+09:00" level=debug msg="connected to ap-gew4.spotify.com:80" Oct 12 22:09:24 volumio go-librespot[2882]: time="2026-10-12T22:09:24+09:00" level=debug msg="completed keyexchange" Oct 12 22:09:24 volumio go-librespot[2882]: time="2026-10-12T22:09:24+09:00" level=debug msg="completed challenge" Oct 12 22:09:24 volumio volumio[1941]: info: Getting Spotify volume Oct 12 22:09:24 volumio volumio[1941]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Oct 12 22:09:25 volumio volumio[1941]: info: CoreCommandRouter::volumioGetState Oct 12 22:09:25 volumio volumio[1941]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Oct 12 22:09:25 volumio volumio[1941]: info: Initializing connection to go-librespot Websocket Oct 12 22:09:25 volumio go-librespot[2882]: time="2026-10-12T22:09:25+09:00" level=debug msg="new websocket client" Oct 12 22:09:25 volumio volumio[1941]: info: Connection to go-librespot Websocket established Oct 12 22:09:25 volumio go-librespot[2882]: time="2026-10-12T22:09:25+09:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: TravelRestriction " Oct 12 22:09:25 volumio go-librespot[2882]: time="2026-10-12T22:09:25+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: TravelRestriction " Oct 12 22:09:25 volumio volumio[1941]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 12 22:09:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 12 22:09:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 12 22:09:25 volumio volumio[1941]: Error: socket hang up Oct 12 22:09:25 volumio volumio[1941]: at connResetException (node:internal/errors:720:14) Oct 12 22:09:25 volumio volumio[1941]: at Socket.socketOnEnd (node:_http_client:519:23) Oct 12 22:09:25 volumio volumio[1941]: at Socket.emit (node:events:526:35) Oct 12 22:09:25 volumio volumio[1941]: at endReadableNT (node:internal/streams/readable:1376:12) Oct 12 22:09:25 volumio volumio[1941]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Oct 12 22:09:25 volumio volumio[1941]: code: 'ECONNRESET', Oct 12 22:09:25 volumio volumio[1941]: response: undefined Oct 12 22:09:25 volumio volumio[1941]: } Oct 12 22:09:25 volumio volumio[1941]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 12 22:09:26 volumio sudo[2923]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-12 22:08' Oct 12 22:09:26 volumio sudo[2923]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"