-- Logs begin at Wed 2026-04-15 15:12:50 CST, end at Wed 2026-04-15 15:22:40 CST. -- Apr 15 15:21:03 primo kernel: asoc-aml-card auge_sound: S/PDIF Playback disable Apr 15 15:21:03 primo kernel: spdif_a keep clk continuous Apr 15 15:21:03 primo kernel: aml_spdif_close Apr 15 15:21:03 primo kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:spdif@0 Apr 15 15:21:03 primo go-librespot[5871]: time="2026-04-15T15:21:03+08:00" level=debug msg="dealer connection closed" Apr 15 15:21:03 primo go-librespot[5871]: time="2026-04-15T15:21:03+08:00" level=debug msg="dealer recv loop stopped" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=debug msg="obtained new client token: AADg2iItZpGWo1NFIQ+Mh6QSWCj3MhmRhpaKZyEiKC6hPm5cLhkbVIaovIQToiBLXbiuRG0EEmLDq8+QJKCWS0gEplTO/qDNivz/00opEP8++Nrcci1YjL09U9E5fqJOr0QGEkwhOOh62rmexPLslB5AROUjyigztlRV7zZQyojAtsLW/g8enJAHMw9Zb1HofKOkhJ8XD9Eye4YjKA0D7z9GzjjmzNECqS3Oc4FjEc+YDGZ1Grei3IA=" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=debug msg="completed keyexchange" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=debug msg="completed challenge" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=info msg="authenticated AP" username="21*********************yi" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=info msg="authenticated Login5" username="21*********************yi" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=info msg="accepted zeroconf from iPhone" username="21*********************yi" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=debug msg="dealer connection opened" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=trace msg="starting accesspoint recv loop" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=trace msg="starting dealer recv loop" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=trace msg="received accesspoint ping" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=debug msg="received connection id: ODZjZmFlMTMtN2Nl...NjM2NDdGNTg2Mg==" Apr 15 15:21:04 primo go-librespot[5871]: time="2026-04-15T15:21:04+08:00" level=trace msg="received accesspoint pong ack" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="put connect state because NEW_DEVICE" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="update volume requested to 65535/65535" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=trace msg="emitting websocket event: volume" Apr 15 15:21:05 primo volumio[3214]: info: Setting Volumio Volume from Spotify: 100 Apr 15 15:21:05 primo volumio[3214]: info: VolumeController::SetAlsaVolume100 Apr 15 15:21:05 primo volumio[3214]: info: CoreStateMachine::pushState Apr 15 15:21:05 primo volumio[3214]: info: CorePlayQueue::getTrack 69 Apr 15 15:21:05 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 15:21:05 primo volumio[3214]: info: CoreCommandRouter::volumioPushState Apr 15 15:21:05 primo volumio[3214]: info: CoreCommandRouter::volumioGetState Apr 15 15:21:05 primo volumio[3214]: info: CorePlayQueue::getTrack 69 Apr 15 15:21:05 primo volumio[3214]: info: MRS: Pushing multiroomSync output update for this device Apr 15 15:21:05 primo volumio[3214]: info: MRS: Pushing multiroomSync output Apr 15 15:21:05 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:05.279Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.101:54567 @ 0x2eb82a0" state=STATUS_PLAYING positionMs=158738 volume=100 Apr 15 15:21:05 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:05.280Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%12,192.168.1.101:54567 @ 0x2c010b0" state=STATUS_PLAYING positionMs=158738 volume=100 Apr 15 15:21:05 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:05.280Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.101:54567 @ 0x2eb82a0" id=spotify:track:2Fxmhks0bxGSBdJ92vM42m title="bad guy" Apr 15 15:21:05 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:05.281Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%12,192.168.1.101:54567 @ 0x2c010b0" id=spotify:track:2Fxmhks0bxGSBdJ92vM42m title="bad guy" Apr 15 15:21:05 primo volumio[3214]: info: Signalling Playback active due to playback status change Apr 15 15:21:05 primo volumio[3214]: info: Updating RAAT Signal Path Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="handling transfer player command from d85263662a9b2db489f8f786214ad4f2db1a8456" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="resolved context of track" uri="spotify:search:heroes+tonight" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:search:heroes+tonight" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="loading track (paused: true, position: 1173ms)" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=trace msg="emitting websocket event: will_play" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1472" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="selected format OGG_VORBIS_320 (75644476f75a0138c8635e027b5edd97ac4fce42)" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="requested aes key for file 75644476f75a0138c8635e027b5edd97ac4fce42, gid: 1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=trace msg="found 2 cdn urls" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="fetched first chunk of 18, total size is 8924882 bytes" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=trace msg="seek to 1173ms (diff: 78ms, samples: 51729, bytes: 42190)" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=debug msg="created new output device" Apr 15 15:21:05 primo go-librespot[5871]: time="2026-04-15T15:21:05+08:00" level=info msg="loaded track \"Heroes Tonight\" (paused: true, position: 1173ms, duration: 208139ms, prefetched: false)" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:06 primo go-librespot[5871]: time="2026-04-15T15:21:06+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 15 15:21:06 primo go-librespot[5871]: time="2026-04-15T15:21:06+08:00" level=trace msg="emitting websocket event: metadata" Apr 15 15:21:06 primo go-librespot[5871]: time="2026-04-15T15:21:06+08:00" level=trace msg="emitting websocket event: active" Apr 15 15:21:06 primo go-librespot[5871]: time="2026-04-15T15:21:06+08:00" level=debug msg="sending successful reply for dealer request" Apr 15 15:21:06 primo go-librespot[5871]: time="2026-04-15T15:21:06+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 15 15:21:06 primo volumio[3214]: info: Aligning Spotify Volume to Volumio Volume Apr 15 15:21:06 primo volumio[3214]: info: CoreCommandRouter::volumioGetState Apr 15 15:21:06 primo volumio[3214]: info: CorePlayQueue::getTrack 69 Apr 15 15:21:06 primo go-librespot[5871]: time="2026-04-15T15:21:06+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 15 15:21:06 primo go-librespot[5871]: time="2026-04-15T15:21:06+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 15 15:21:06 primo go-librespot[5871]: time="2026-04-15T15:21:06+08:00" level=trace msg="emitting websocket event: paused" Apr 15 15:21:06 primo volumio[3214]: info: Spotify is playing in volatile mode Apr 15 15:21:06 primo volumio[3214]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 15 15:21:06 primo volumio[3214]: info: Setting Spotify stop after unset volatile call Apr 15 15:21:06 primo volumio[3214]: info: CoreCommandRouter::servicePushState Apr 15 15:21:06 primo volumio[3214]: info: CoreStateMachine::pushState Apr 15 15:21:06 primo go-librespot[5871]: time="2026-04-15T15:21:06+08:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:06 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 15:21:06 primo volumio[3214]: info: CoreCommandRouter::volumioPushState Apr 15 15:21:06 primo volumio[3214]: info: CoreCommandRouter::volumioGetState Apr 15 15:21:06 primo volumio[3214]: info: MRS: Pushing multiroomSync output update for this device Apr 15 15:21:06 primo volumio[3214]: info: MRS: Pushing multiroomSync output Apr 15 15:21:06 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:06.128Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.101:54567 @ 0x2eb82a0" state=STATUS_PAUSED positionMs=1173 volume=100 Apr 15 15:21:06 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:06.129Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%12,192.168.1.101:54567 @ 0x2c010b0" state=STATUS_PAUSED positionMs=1173 volume=100 Apr 15 15:21:06 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:06.129Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.101:54567 @ 0x2eb82a0" id=spotify:track:1TayNhoH7cuNwMO8F058Ei title="Heroes Tonight" Apr 15 15:21:06 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:06.130Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%12,192.168.1.101:54567 @ 0x2c010b0" id=spotify:track:1TayNhoH7cuNwMO8F058Ei title="Heroes Tonight" Apr 15 15:21:06 primo volumio[3214]: info: Updating RAAT Signal Path Apr 15 15:21:06 primo volumio[3214]: info: MCU Signalled Playback Inactive Apr 15 15:21:06 primo go-librespot[5871]: time="2026-04-15T15:21:06+08:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:06 primo go-librespot[5871]: time="2026-04-15T15:21:06+08:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:06 primo volumio[3214]: info: Spotify Stop Apr 15 15:21:08 primo go-librespot[5871]: time="2026-04-15T15:21:08+08:00" level=debug msg="handling resume player command from d85263662a9b2db489f8f786214ad4f2db1a8456" Apr 15 15:21:08 primo go-librespot[5871]: time="2026-04-15T15:21:08+08:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:08 primo go-librespot[5871]: time="2026-04-15T15:21:08+08:00" level=trace msg="seek to 1173ms (diff: 78ms, samples: 51729, bytes: 42190)" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:08 primo kernel: aml_spdif_open Apr 15 15:21:08 primo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:spdif@0 Apr 15 15:21:08 primo go-librespot[5871]: time="2026-04-15T15:21:08+08:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Apr 15 15:21:08 primo go-librespot[5871]: time="2026-04-15T15:21:08+08:00" level=debug msg="resume track at 1095ms" Apr 15 15:21:08 primo kernel: set normal 512 fs /4 fs Apr 15 15:21:08 primo kernel: set spdifout clk:5644800, mpll:22579200 Apr 15 15:21:08 primo kernel: get spdifout clk:5644797, mpll:22579186 Apr 15 15:21:08 primo kernel: aml_dai_set_spdif_fmt , fmt 0x4000 Apr 15 15:21:08 primo kernel: set normal 512 fs /4 fs Apr 15 15:21:08 primo kernel: set spdifout clk:5644800, mpll:22579200 Apr 15 15:21:08 primo kernel: get spdifout clk:5644797, mpll:22579186 Apr 15 15:21:08 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Apr 15 15:21:08 primo kernel: aml_spdif_fifo_ctrl, bit depth:24, frddr type:4, toddr:type:4 Apr 15 15:21:08 primo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 Apr 15 15:21:08 primo kernel: aml_spdif_fifo_ctrl, bit depth:24, frddr type:4, toddr:type:4 Apr 15 15:21:08 primo go-librespot[5871]: time="2026-04-15T15:21:08+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 15 15:21:08 primo go-librespot[5871]: time="2026-04-15T15:21:08+08:00" level=trace msg="scheduling prefetch in 177s" Apr 15 15:21:08 primo go-librespot[5871]: time="2026-04-15T15:21:08+08:00" level=debug msg="sending successful reply for dealer request" Apr 15 15:21:08 primo volumio[3214]: info: Executing endpoint metavolumio Apr 15 15:21:08 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 15 15:21:08 primo go-librespot[5871]: time="2026-04-15T15:21:08+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 15 15:21:08 primo go-librespot[5871]: time="2026-04-15T15:21:08+08:00" level=trace msg="emitting websocket event: playing" Apr 15 15:21:08 primo volumio[3214]: info: CoreCommandRouter::servicePushState Apr 15 15:21:08 primo volumio[3214]: info: CoreStateMachine::pushState Apr 15 15:21:08 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 15:21:08 primo volumio[3214]: info: CoreCommandRouter::volumioPushState Apr 15 15:21:08 primo volumio[3214]: info: CoreCommandRouter::volumioGetState Apr 15 15:21:08 primo volumio[3214]: info: MRS: Pushing multiroomSync output update for this device Apr 15 15:21:08 primo volumio[3214]: info: MRS: Pushing multiroomSync output Apr 15 15:21:08 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:08.320Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.101:54567 @ 0x2eb82a0" state=STATUS_PLAYING positionMs=1173 volume=100 Apr 15 15:21:08 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:08.321Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%12,192.168.1.101:54567 @ 0x2c010b0" state=STATUS_PLAYING positionMs=1173 volume=100 Apr 15 15:21:08 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:08.321Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.101:54567 @ 0x2eb82a0" id=spotify:track:1TayNhoH7cuNwMO8F058Ei title="Heroes Tonight" Apr 15 15:21:08 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:08.322Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%12,192.168.1.101:54567 @ 0x2c010b0" id=spotify:track:1TayNhoH7cuNwMO8F058Ei title="Heroes Tonight" Apr 15 15:21:08 primo volumio[3214]: info: Signalling Playback active due to playback status change Apr 15 15:21:08 primo kernel: asoc-aml-card auge_sound: S/PDIF Playback enable Apr 15 15:21:08 primo volumio[3214]: info: Updating RAAT Signal Path Apr 15 15:21:08 primo volumio[3214]: info: Executing endpoint metavolumio Apr 15 15:21:08 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 15 15:21:08 primo volumio[3214]: info: Executing endpoint metavolumio Apr 15 15:21:08 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 15 15:21:08 primo volumio[3214]: info: MCU Signalled Playback Active Apr 15 15:21:08 primo volumio[3214]: info: CoreCommandRouter::servicePushState Apr 15 15:21:08 primo volumio[3214]: info: CoreStateMachine::pushState Apr 15 15:21:08 primo volumio[3214]: info: CoreCommandRouter::volumioPushState Apr 15 15:21:08 primo volumio[3214]: info: CoreCommandRouter::volumioGetState Apr 15 15:21:08 primo volumio[3214]: info: MRS: Pushing multiroomSync output update for this device Apr 15 15:21:08 primo volumio[3214]: info: MRS: Pushing multiroomSync output Apr 15 15:21:08 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:08.617Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.101:54567 @ 0x2eb82a0" state=STATUS_PLAYING positionMs=1173 volume=100 Apr 15 15:21:08 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:08.618Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%12,192.168.1.101:54567 @ 0x2c010b0" state=STATUS_PLAYING positionMs=1173 volume=100 Apr 15 15:21:08 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:08.618Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.101:54567 @ 0x2eb82a0" id=spotify:track:1TayNhoH7cuNwMO8F058Ei title="Heroes Tonight" Apr 15 15:21:08 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:08.618Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%12,192.168.1.101:54567 @ 0x2c010b0" id=spotify:track:1TayNhoH7cuNwMO8F058Ei title="Heroes Tonight" Apr 15 15:21:08 primo volumio[3214]: info: Signalling Playback active due to playback status change Apr 15 15:21:08 primo volumio[3214]: info: Updating RAAT Signal Path Apr 15 15:21:18 primo volumio[3214]: verbose: New Socket.io Connection to 192.168.1.102 from 192.168.1.101 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::volumioGetVisibleSources Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::volumioGetState Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 15 15:21:18 primo volumio[3214]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Apr 15 15:21:18 primo volumio[3214]: info: Received Get System Info Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 15 15:21:18 primo volumio[3214]: info: Discovery: Getting this device information Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::volumioGetState Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::volumioGetState Apr 15 15:21:18 primo volumio[3214]: info: Listing playlists Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::volumioGetQueue Apr 15 15:21:18 primo volumio[3214]: info: CoreStateMachine::getQueue Apr 15 15:21:18 primo volumio[3214]: info: CorePlayQueue::getQueue Apr 15 15:21:18 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 15 15:21:19 primo go-librespot[5871]: time="2026-04-15T15:21:19+08:00" level=debug msg="fetched chunk 4/17, size: 524288" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:30 primo go-librespot[5871]: time="2026-04-15T15:21:30+08:00" level=debug msg="fetched chunk 5/17, size: 524288" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:34 primo go-librespot[5871]: time="2026-04-15T15:21:34+08:00" level=trace msg="sent dealer ping" Apr 15 15:21:34 primo go-librespot[5871]: time="2026-04-15T15:21:34+08:00" level=trace msg="received dealer pong" Apr 15 15:21:35 primo volumio[3214]: info: CorePlayQueue::getTrack 69 Apr 15 15:21:35 primo volumio[3214]: info: CorePlayQueue::getTrack 70 Apr 15 15:21:35 primo volumio[3214]: info: Prefetching next song Apr 15 15:21:35 primo volumio[3214]: info: [1776237695451] ControllerSpotify::prefetch Apr 15 15:21:35 primo volumio[3214]: info: Sending Spotify command with payload to local API: /player/add_to_queue Apr 15 15:21:35 primo go-librespot[5871]: time="2026-04-15T15:21:35+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 15 15:21:35 primo go-librespot[5871]: time="2026-04-15T15:21:35+08:00" level=trace msg="scheduling prefetch in 150s" Apr 15 15:21:39 primo volumio[3214]: info: CoreStateMachine::startPlaybackTimer Apr 15 15:21:39 primo volumio[3214]: info: CorePlayQueue::getTrack 70 Apr 15 15:21:40 primo volumio[3214]: info: CoreStateMachine::pushState Apr 15 15:21:40 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 15:21:40 primo volumio[3214]: info: CoreCommandRouter::volumioPushState Apr 15 15:21:40 primo volumio[3214]: info: CoreCommandRouter::volumioGetState Apr 15 15:21:40 primo volumio[3214]: info: MRS: Pushing multiroomSync output update for this device Apr 15 15:21:40 primo volumio[3214]: info: MRS: Pushing multiroomSync output Apr 15 15:21:40 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:40.470Z level=INFO msg="emitting player state changed event" component=server peer="192.168.1.101:54567 @ 0x2eb82a0" state=STATUS_PLAYING positionMs=33173 volume=100 Apr 15 15:21:40 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:40.470Z level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%12,192.168.1.101:54567 @ 0x2c010b0" state=STATUS_PLAYING positionMs=33173 volume=100 Apr 15 15:21:40 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:40.471Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.1.101:54567 @ 0x2eb82a0" id=spotify:track:1TayNhoH7cuNwMO8F058Ei title="Heroes Tonight" Apr 15 15:21:40 primo volumio5-onboarding[3999]: time=2026-04-15T07:21:40.471Z level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%12,192.168.1.101:54567 @ 0x2c010b0" id=spotify:track:1TayNhoH7cuNwMO8F058Ei title="Heroes Tonight" Apr 15 15:21:40 primo volumio[3214]: info: Signalling Playback active due to playback status change Apr 15 15:21:40 primo volumio[3214]: info: Updating RAAT Signal Path Apr 15 15:21:42 primo go-librespot[5871]: time="2026-04-15T15:21:42+08:00" level=debug msg="fetched chunk 6/17, size: 524288" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:21:54 primo go-librespot[5871]: time="2026-04-15T15:21:54+08:00" level=debug msg="fetched chunk 7/17, size: 524288" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:22:04 primo go-librespot[5871]: time="2026-04-15T15:22:04+08:00" level=trace msg="sent dealer ping" Apr 15 15:22:04 primo go-librespot[5871]: time="2026-04-15T15:22:04+08:00" level=trace msg="received dealer pong" Apr 15 15:22:05 primo go-librespot[5871]: time="2026-04-15T15:22:05+08:00" level=debug msg="fetched chunk 8/17, size: 524288" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:22:18 primo go-librespot[5871]: time="2026-04-15T15:22:18+08:00" level=debug msg="fetched chunk 9/17, size: 524288" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:22:22 primo ntpd[3545]: 17.253.116.253 local addr 192.168.1.102 -> Apr 15 15:22:23 primo volumio[3214]: verbose: New Socket.io Connection to 192.168.1.102 from 192.168.1.101 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Apr 15 15:22:23 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 15 15:22:23 primo volumio[3214]: info: CoreCommandRouter::volumioGetVisibleSources Apr 15 15:22:23 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 15 15:22:23 primo volumio[3214]: info: CoreCommandRouter::volumioGetState Apr 15 15:22:23 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 15 15:22:23 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 15 15:22:23 primo volumio[3214]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Apr 15 15:22:23 primo volumio[3214]: info: Received Get System Info Apr 15 15:22:23 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 15 15:22:23 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 15 15:22:23 primo volumio[3214]: info: Discovery: Getting this device information Apr 15 15:22:23 primo volumio[3214]: info: CoreCommandRouter::volumioGetState Apr 15 15:22:23 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 15 15:22:23 primo volumio[3214]: info: CoreCommandRouter::volumioGetState Apr 15 15:22:23 primo volumio[3214]: info: Listing playlists Apr 15 15:22:23 primo volumio[3214]: info: CoreCommandRouter::volumioGetQueue Apr 15 15:22:23 primo volumio[3214]: info: CoreStateMachine::getQueue Apr 15 15:22:23 primo volumio[3214]: info: CorePlayQueue::getQueue Apr 15 15:22:24 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 15 15:22:31 primo go-librespot[5871]: time="2026-04-15T15:22:31+08:00" level=debug msg="fetched chunk 10/17, size: 524288" uri="spotify:track:1TayNhoH7cuNwMO8F058Ei" Apr 15 15:22:33 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Apr 15 15:22:33 primo volumio[3214]: info: In handleBrowseUri, curUri=spotify:artist:2p0xfX8cfkLJBfe0zl0mOi Apr 15 15:22:34 primo volumio[3214]: info: Preload queue cleared Apr 15 15:22:34 primo volumio[3214]: info: Preloading song: spotify:track:5Q46F9rT7RTGjI0lV8M44w Apr 15 15:22:34 primo volumio[3214]: info: Preloading song: spotify:track:19WipbxeVKcvShT1qCdLNW Apr 15 15:22:34 primo volumio[3214]: info: Preloading song: spotify:track:70mlfuSLM5QTf3RQDPxER1 Apr 15 15:22:34 primo volumio[3214]: info: Preloading song: spotify:track:2in1KFuY6E4y58VeM91J10 Apr 15 15:22:34 primo volumio[3214]: info: Preloading song: spotify:track:7uMBgDsFATCA6pwsZl5435 Apr 15 15:22:34 primo volumio[3214]: info: Preloading song: spotify:track:4xxeQfWrGUl23j7L9NrTGs Apr 15 15:22:34 primo volumio[3214]: info: Preloading song: spotify:track:3SY9CFWTI8LNmLToidly35 Apr 15 15:22:34 primo volumio[3214]: info: Preloading song: spotify:track:2WGabXqfJOytjEx30cj3qM Apr 15 15:22:34 primo volumio[3214]: info: Preloading song: spotify:track:5CevczBDuKzXfmmzc7HxnK Apr 15 15:22:34 primo volumio[3214]: info: Preloading song: spotify:track:2N9L5i8aXCsV4izpQNx3Hx Apr 15 15:22:34 primo volumio[3214]: info: Preload queue cleared Apr 15 15:22:34 primo go-librespot[5871]: time="2026-04-15T15:22:34+08:00" level=trace msg="sent dealer ping" Apr 15 15:22:34 primo go-librespot[5871]: time="2026-04-15T15:22:34+08:00" level=trace msg="received dealer pong" Apr 15 15:22:35 primo volumio[3214]: info: Executing endpoint getSimilarArtists Apr 15 15:22:35 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Apr 15 15:22:35 primo volumio[3214]: info: Executing endpoint getSimilarArtists Apr 15 15:22:35 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Apr 15 15:22:35 primo volumio[3214]: info: Executing endpoint metavolumio Apr 15 15:22:35 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 15 15:22:35 primo volumio[3214]: info: Executing endpoint metavolumio Apr 15 15:22:35 primo volumio[3214]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 15 15:22:37 primo volumio[3214]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/Bleeding%20In%20Stereo/049b812f-319c-4848-af54-62475dbdb63e.jpg' Apr 15 15:22:39 primo volumio[3214]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/Surrender%20The%20Fall/6eacf7e1-2842-4838-beb6-647678ab379c.jpg' Apr 15 15:22:39 primo volumio[3214]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 15 15:22:39 primo volumio[3214]: TypeError: Cannot read property 'slice' of null Apr 15 15:22:39 primo volumio[3214]: at download (/volumio/app/plugins/miscellanea/albumart/albumart.js:718:41) Apr 15 15:22:39 primo volumio[3214]: at ClientRequest. (/volumio/app/plugins/miscellanea/albumart/albumart.js:728:7) Apr 15 15:22:39 primo volumio[3214]: at Object.onceWrapper (events.js:520:26) Apr 15 15:22:39 primo volumio[3214]: at ClientRequest.emit (events.js:400:28) Apr 15 15:22:39 primo volumio[3214]: at HTTPParser.parserOnIncomingClient [as onIncoming] (_http_client.js:647:27) Apr 15 15:22:39 primo volumio[3214]: at HTTPParser.parserOnHeadersComplete (_http_common.js:127:17) Apr 15 15:22:39 primo volumio[3214]: at TLSSocket.socketOnData (_http_client.js:515:22) Apr 15 15:22:39 primo volumio[3214]: at TLSSocket.emit (events.js:400:28) Apr 15 15:22:39 primo volumio[3214]: at addChunk (internal/streams/readable.js:293:12) Apr 15 15:22:39 primo volumio[3214]: at readableAddChunk (internal/streams/readable.js:267:9) Apr 15 15:22:39 primo volumio[3214]: at TLSSocket.Readable.push (internal/streams/readable.js:206:10) Apr 15 15:22:39 primo volumio[3214]: at TLSWrap.onStreamRead (internal/stream_base_commons.js:188:23) Apr 15 15:22:39 primo volumio[3214]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 15 15:22:40 primo sudo[6910]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-04-15 15:21 Apr 15 15:22:40 primo sudo[6910]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="464fc672d77d3df6ee72b331d36cdf1fa936e1ec" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="primo2rev2" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 27 Feb 2026 12:16:07 PM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Primo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo" VOLUMIO_HASH="88686576587e39571d6cf25f3920fbc0"