-- Logs begin at Sat 2026-08-29 10:51:13 CEST, end at Sat 2026-08-29 12:35:04 CEST. -- Aug 29 12:34:00 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:00 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:00 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:00 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:01 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:01 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:01 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:01 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:02 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:02 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:02 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:02 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:03 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:03 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:03 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:03 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=debug msg="handling play player command from 27ed7f96e3bca5d535c9523961b321988daa022e" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=debug msg="resolved context of track" uri="spotify:album:4AOoCQTYGwd81uWjmwGSp9" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=trace msg="fetched new page 0 with 11 items (list: 11)" uri="spotify:album:4AOoCQTYGwd81uWjmwGSp9" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:3YivDvApPFQzPpF4T6d2CL" Aug 29 12:34:04 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:04 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:04 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:04 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=trace msg="emitting websocket event: will_play" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=debug msg="selected format OGG_VORBIS_320 (692e6dddbc67122639c87af688d43ed5a79d2e34)" uri="spotify:track:3YivDvApPFQzPpF4T6d2CL" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=debug msg="requested aes key for file 692e6dddbc67122639c87af688d43ed5a79d2e34, gid: 3YivDvApPFQzPpF4T6d2CL" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3YivDvApPFQzPpF4T6d2CL" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=debug msg="fetched first chunk of 29, total size is 14949032 bytes" uri="spotify:track:3YivDvApPFQzPpF4T6d2CL" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:3YivDvApPFQzPpF4T6d2CL" Aug 29 12:34:04 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate, raw: Aug 29 12:34:04 volumio-miro volumio[1192]: error: FusionDsp - invalid sample rate Aug 29 12:34:04 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 29 12:34:04 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 29 12:34:04 volumio-miro volumio[1192]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 29 12:34:04 volumio-miro volumio[1192]: info: FusionDsp - Effects disabled Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=info msg="loaded track \"Kingdom - Booka Shade Club Remix\" (paused: false, position: 1ms, duration: 336000ms, prefetched: false)" uri="spotify:track:3YivDvApPFQzPpF4T6d2CL" Aug 29 12:34:04 volumio-miro volumio[1192]: info: FusionDsp - {"Reload":{"result":"Ok"}} Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=debug msg="fetched chunk 1/28, size: 524288" uri="spotify:track:3YivDvApPFQzPpF4T6d2CL" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=trace msg="scheduling prefetch in 306s" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=trace msg="emitting websocket event: metadata" Aug 29 12:34:04 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:04+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=debug msg="fetched chunk 2/28, size: 524288" uri="spotify:track:3YivDvApPFQzPpF4T6d2CL" Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=trace msg="emitting websocket event: playing" Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:05 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:05 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:05 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:05.085+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PLAYING positionMs=1 volume=100 Aug 29 12:34:05 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:05.086+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:3YivDvApPFQzPpF4T6d2CL title="Kingdom - Booka Shade Club Remix" Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=debug msg="fetched chunk 3/28, size: 524288" uri="spotify:track:3YivDvApPFQzPpF4T6d2CL" Aug 29 12:34:05 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:05 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:05 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:05 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=debug msg="handling pause player command from 27ed7f96e3bca5d535c9523961b321988daa022e" Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=debug msg="pause track at 540ms" Aug 29 12:34:05 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:05.257+02:00 level=INFO msg="player pause request" component=server type=REQUEST_TYPE_PLAYER_PAUSE peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-477.780859ms timeout=10s Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPause Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreStateMachine::pause Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreStateMachine::stPlaybackTimer Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreStateMachine::servicePause Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePause Aug 29 12:34:05 volumio-miro volumio[1192]: info: Spotify Received pause Aug 29 12:34:05 volumio-miro volumio[1192]: info: Sending Spotify command to local API: /player/pause Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:05 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:05 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:05 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:05.386+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PLAYING positionMs=1 volume=100 Aug 29 12:34:05 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:05.386+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:3YivDvApPFQzPpF4T6d2CL title="Kingdom - Booka Shade Club Remix" Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=trace msg="emitting websocket event: paused" Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=debug msg="pause track at 1039ms" Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:05 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:05 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:05 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:05.439+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=1 volume=100 Aug 29 12:34:05 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:05.439+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:3YivDvApPFQzPpF4T6d2CL title="Kingdom - Booka Shade Club Remix" Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:05 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:05+02:00" level=trace msg="emitting websocket event: paused" Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:05 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:05 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:05 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:05 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:05.612+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=1 volume=100 Aug 29 12:34:05 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:05.612+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:3YivDvApPFQzPpF4T6d2CL title="Kingdom - Booka Shade Club Remix" Aug 29 12:34:06 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:06 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:06 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:06 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:07 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:07 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:07 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:07 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:07 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:07+02:00" level=debug msg="handling play player command from 27ed7f96e3bca5d535c9523961b321988daa022e" Aug 29 12:34:07 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:07+02:00" level=debug msg="resolved context of track" uri="spotify:album:4AOoCQTYGwd81uWjmwGSp9" Aug 29 12:34:07 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:07+02:00" level=trace msg="fetched new page 0 with 11 items (list: 11)" uri="spotify:album:4AOoCQTYGwd81uWjmwGSp9" Aug 29 12:34:07 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:07+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7wj7sfoOB2lbQArn6jQ6Nb" Aug 29 12:34:07 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:07+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:07 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:07+02:00" level=trace msg="emitting websocket event: will_play" Aug 29 12:34:07 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:07+02:00" level=debug msg="selected format OGG_VORBIS_320 (c452589456a986ce4c1232af2c491e93c4c5f47c)" uri="spotify:track:7wj7sfoOB2lbQArn6jQ6Nb" Aug 29 12:34:07 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:07+02:00" level=debug msg="requested aes key for file c452589456a986ce4c1232af2c491e93c4c5f47c, gid: 7wj7sfoOB2lbQArn6jQ6Nb" Aug 29 12:34:07 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:07+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7wj7sfoOB2lbQArn6jQ6Nb" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="fetched first chunk of 26, total size is 13275984 bytes" uri="spotify:track:7wj7sfoOB2lbQArn6jQ6Nb" Aug 29 12:34:08 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate, raw: Aug 29 12:34:08 volumio-miro volumio[1192]: error: FusionDsp - invalid sample rate Aug 29 12:34:08 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 29 12:34:08 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 29 12:34:08 volumio-miro volumio[1192]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 29 12:34:08 volumio-miro volumio[1192]: info: FusionDsp - Effects disabled Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=info msg="loaded track \"Deeper and Deeper - The Juan Maclean Club Mix\" (paused: false, position: 0ms, duration: 308533ms, prefetched: false)" uri="spotify:track:7wj7sfoOB2lbQArn6jQ6Nb" Aug 29 12:34:08 volumio-miro volumio[1192]: info: FusionDsp - {"Reload":{"result":"Ok"}} Aug 29 12:34:08 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:08 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:08 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:08 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="fetched chunk 1/25, size: 524288" uri="spotify:track:7wj7sfoOB2lbQArn6jQ6Nb" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="fetched chunk 2/25, size: 524288" uri="spotify:track:7wj7sfoOB2lbQArn6jQ6Nb" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=trace msg="scheduling prefetch in 278s" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=trace msg="emitting websocket event: metadata" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="fetched chunk 3/25, size: 524288" uri="spotify:track:7wj7sfoOB2lbQArn6jQ6Nb" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=trace msg="emitting websocket event: playing" Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:08 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:08 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:08 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:08.457+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 12:34:08 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:08.458+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="handling pause player command from 27ed7f96e3bca5d535c9523961b321988daa022e" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="pause track at 679ms" Aug 29 12:34:08 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:08.628+02:00 level=INFO msg="player pause request" component=server type=REQUEST_TYPE_PLAYER_PAUSE peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-475.77887ms timeout=10s Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPause Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreStateMachine::pause Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreStateMachine::stPlaybackTimer Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreStateMachine::servicePause Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePause Aug 29 12:34:08 volumio-miro volumio[1192]: info: Spotify Received pause Aug 29 12:34:08 volumio-miro volumio[1192]: info: Sending Spotify command to local API: /player/pause Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="pause track at 1178ms" Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:08 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:08 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:08 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:08.735+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 12:34:08 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:08.736+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=trace msg="emitting websocket event: paused" Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:08 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:08 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:08 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:08.883+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:08 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:08.883+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:08 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:08+02:00" level=trace msg="emitting websocket event: paused" Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:08 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:08 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:08 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:08 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:08.982+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:08 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:08.982+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:09 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:09 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:09 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:09 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:10 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:10 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:10 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:10 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=debug msg="handling resume player command from 27ed7f96e3bca5d535c9523961b321988daa022e" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=trace msg="seek to 1178ms (diff: 189ms, samples: 51949, bytes: 18992)" uri="spotify:track:7wj7sfoOB2lbQArn6jQ6Nb" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=debug msg="resume track at 989ms" Aug 29 12:34:10 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 29 12:34:10 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 29 12:34:10 volumio-miro volumio[1192]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 29 12:34:10 volumio-miro volumio[1192]: info: FusionDsp - Effects disabled Aug 29 12:34:10 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 29 12:34:10 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 29 12:34:10 volumio-miro volumio[1192]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 29 12:34:10 volumio-miro volumio[1192]: info: FusionDsp - Effects disabled Aug 29 12:34:10 volumio-miro volumio[1192]: info: FusionDsp - {"Reload":{"result":"Ok"}} Aug 29 12:34:10 volumio-miro volumio[1192]: info: FusionDsp - {"Reload":{"result":"Ok"}} Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=trace msg="scheduling prefetch in 278s" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=trace msg="emitting websocket event: playing" Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:10 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:10 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:10 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:10.639+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 12:34:10 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:10.640+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=debug msg="handling pause player command from 27ed7f96e3bca5d535c9523961b321988daa022e" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=debug msg="pause track at 1448ms" Aug 29 12:34:10 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:10.845+02:00 level=INFO msg="player pause request" component=server type=REQUEST_TYPE_PLAYER_PAUSE peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.312489ms timeout=10s Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPause Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreStateMachine::pause Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreStateMachine::stPlaybackTimer Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreStateMachine::servicePause Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePause Aug 29 12:34:10 volumio-miro volumio[1192]: info: Spotify Received pause Aug 29 12:34:10 volumio-miro volumio[1192]: info: Sending Spotify command to local API: /player/pause Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:10 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:10 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:10 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:10.932+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 12:34:10 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:10.932+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=trace msg="emitting websocket event: paused" Aug 29 12:34:10 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:10+02:00" level=debug msg="pause track at 1947ms" Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:10 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:10 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:10 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:10 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:10.970+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:10 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:10.971+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:11 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:11+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:11 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:11+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:11 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:11+02:00" level=trace msg="emitting websocket event: paused" Aug 29 12:34:11 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:11 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:11 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:11 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:11 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:11 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:11 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:11.144+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:11 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:11.145+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:11 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:11 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:11 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:11 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:12 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:12 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:12 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:12 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:13 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:13 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:13 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:13 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:14 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:14 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:14 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:14 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:15 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:15 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:15 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:15 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.376+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.407+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=http://pushupdates.volumio.org duration=30.263587ms Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.417+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=40.945969ms Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.418+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=41.938227ms Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.490+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=https://www.googleapis.com duration=114.318544ms Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.510+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=https://securetoken.googleapis.com duration=132.937825ms Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.526+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=https://functions.volumio.cloud duration=149.720467ms Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.526+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=https://functions.volumio.cloud duration=148.811334ms Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.607+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=231.142817ms Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.663+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=https://database.volumio.cloud duration=286.167363ms Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.699+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=322.834546ms Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.749+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=https://google.com duration=372.848215ms Aug 29 12:34:15 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:15.799+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=http://cddb.volumio.org duration=423.199055ms Aug 29 12:34:16 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:16.092+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-467.743468ms timeout=10s endpoint=http://plugins.volumio.org duration=715.87064ms Aug 29 12:34:16 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:16 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:16 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:16 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:16 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:16+02:00" level=trace msg="sent dealer ping" Aug 29 12:34:16 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:16+02:00" level=trace msg="received dealer pong" Aug 29 12:34:17 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:17 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:17 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:17 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:18 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:18 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:18 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:18 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:18 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:18 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:18 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:18 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:18 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:18 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.113:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:18 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:18 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:19 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:19 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:19 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:19 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:20 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:20 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:20 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:20 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:20 volumio-miro volumio[1192]: info: CALLMETHOD: audio_interface alsa_controller saveVolumeOptions [object Object] Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveVolumeOptions Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:20 volumio-miro volumio[1192]: info: Restoring Previous Volume level: 100 false true Aug 29 12:34:20 volumio-miro volumio[1192]: info: VolumeController::SetAlsaVolume100 Aug 29 12:34:20 volumio-miro volumio[1192]: info: Enable softmixer device for audio device number 1,1 Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioStop Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreStateMachine::stop Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreStateMachine::serviceStop Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::serviceStop Aug 29 12:34:20 volumio-miro volumio[1192]: info: Spotify Stop Aug 29 12:34:20 volumio-miro volumio[1192]: info: Sending Spotify command to local API: /player/pause Aug 29 12:34:20 volumio-miro volumio[1192]: info: Enable softmixer device for audio device undefined Aug 29 12:34:20 volumio-miro volumio[1192]: info: Output device has changed, restarting MPD Aug 29 12:34:20 volumio-miro volumio[1192]: info: Output device has changed, restarting Shairport Sync Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 12:34:20 volumio-miro sudo[22328]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 29 12:34:20 volumio-miro sudo[22328]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:20 volumio-miro sudo[22331]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 12:34:20 volumio-miro sudo[22328]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:20 volumio-miro sudo[22331]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:20 volumio-miro volumio[1192]: No protocol specified Aug 29 12:34:20 volumio-miro volumio[1192]: xcb_connection_has_error() returned true Aug 29 12:34:20 volumio-miro volumio[1192]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:20 volumio-miro systemd[1]: Stopping Music Player Daemon... Aug 29 12:34:20 volumio-miro volumio[1192]: info: QobuzConnect: setDeactiveState invoked Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:20 volumio-miro vtcs[21982]: [2026-08-29 12:34:20.635] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE Aug 29 12:34:20 volumio-miro vtcs[21982]: [2026-08-29 12:34:20.635] [tisoc] [error] [SpkconServer.cpp:378] recv error. socket disconnected Aug 29 12:34:20 volumio-miro volumio[1192]: info: Volume configurations have been set Aug 29 12:34:20 volumio-miro volumio[1192]: info: QobuzConnect: setDeactiveState invoked Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:20 volumio-miro systemd[1]: mpd.service: Succeeded. Aug 29 12:34:20 volumio-miro systemd[1]: Stopped Music Player Daemon. Aug 29 12:34:20 volumio-miro sudo[22350]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 29 12:34:20 volumio-miro systemd[1]: Starting Music Player Daemon... Aug 29 12:34:20 volumio-miro sudo[22350]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:20 volumio-miro sudo[22355]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 29 12:34:20 volumio-miro sudo[22355]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:20 volumio-miro systemd[1]: Stopping Volumio Tidal Connect Service... Aug 29 12:34:20 volumio-miro systemd[1]: vtcs.service: Main process exited, code=killed, status=15/TERM Aug 29 12:34:20 volumio-miro systemd[1]: vtcs.service: Succeeded. Aug 29 12:34:20 volumio-miro systemd[1]: Stopped Volumio Tidal Connect Service. Aug 29 12:34:20 volumio-miro sudo[22350]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:20 volumio-miro volumio[1192]: No protocol specified Aug 29 12:34:20 volumio-miro volumio[1192]: xcb_connection_has_error() returned true Aug 29 12:34:20 volumio-miro sudo[22353]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 29 12:34:20 volumio-miro sudo[22355]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:20 volumio-miro sudo[22353]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioUpdateVolumeSettings Aug 29 12:34:20 volumio-miro volumio[1192]: info: Updating Volume Controller Parameters: Device: 1,1 Name: SPDIF Mixer: Headphone Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Aug 29 12:34:20 volumio-miro volumio[1192]: info: Disabling external Volume Control Aug 29 12:34:20 volumio-miro sudo[22353]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:20 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:20 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:20 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:20 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:20.867+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:20 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:20.867+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:20 volumio-miro sudo[22393]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 29 12:34:20 volumio-miro sudo[22396]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 29 12:34:20 volumio-miro sudo[22393]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:20 volumio-miro sudo[22396]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:20 volumio-miro sudo[22393]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:21 volumio-miro sudo[22410]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 29 12:34:21 volumio-miro sudo[22396]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:21 volumio-miro sudo[22410]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:21 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:21 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:21 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:21 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:21 volumio-miro sudo[22410]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:21 volumio-miro sudo[22428]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 29 12:34:21 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:21+02:00" level=debug msg="pause track at 1947ms" Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:21 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:21 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:21 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:21.149+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:21 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:21.149+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:21 volumio-miro sudo[22435]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 29 12:34:21 volumio-miro volumio[1192]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read property 'split' of undefined Aug 29 12:34:21 volumio-miro volumio[1192]: info: MPD Permissions set Aug 29 12:34:21 volumio-miro sudo[22428]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:21 volumio-miro sudo[22435]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:21 volumio-miro volumio[1192]: info: Software Volume ALSA configuration written Aug 29 12:34:21 volumio-miro volumio[1192]: info: Preparing to generate the ALSA configuration file Aug 29 12:34:21 volumio-miro sudo[22428]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:21 volumio-miro systemd[1]: Stopping Volumio Qobuz Connect Service... Aug 29 12:34:21 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:21 volumio-miro qobuz-connect[21931]: 20260829 12:34:21.228 [21931.21931] INFO SampleApp: Stopping Local configuration server Aug 29 12:34:21 volumio-miro qobuz-connect[21931]: 20260829 12:34:21.240 [21931.21931] INFO SampleApp: shat down connection on UNIX socket Aug 29 12:34:21 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:21 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:21 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:21 volumio-miro systemd[1]: qobuz-connect.service: Succeeded. Aug 29 12:34:21 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:21 volumio-miro systemd[1]: Stopped Volumio Qobuz Connect Service. Aug 29 12:34:21 volumio-miro volumio[1192]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Aug 29 12:34:21 volumio-miro volumio[1192]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Aug 29 12:34:21 volumio-miro volumio[1192]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Aug 29 12:34:21 volumio-miro systemd[1]: Started Volumio Qobuz Connect Service. Aug 29 12:34:21 volumio-miro volumio[1192]: info: Reading ALSA contributions from plugins. Aug 29 12:34:21 volumio-miro sudo[22435]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:21 volumio-miro sudo[22447]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 29 12:34:21 volumio-miro sudo[22447]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:21 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:21+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:21 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:21+02:00" level=trace msg="emitting websocket event: paused" Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:21 volumio-miro systemd[1]: Stopping Volumio Qobuz Connect Service... Aug 29 12:34:21 volumio-miro systemd[1]: qobuz-connect.service: Main process exited, code=killed, status=2/INT Aug 29 12:34:21 volumio-miro systemd[1]: qobuz-connect.service: Succeeded. Aug 29 12:34:21 volumio-miro systemd[1]: Stopped Volumio Qobuz Connect Service. Aug 29 12:34:21 volumio-miro systemd[1]: Started Volumio Qobuz Connect Service. Aug 29 12:34:21 volumio-miro sudo[22447]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:21 volumio-miro volumio[1192]: No protocol specified Aug 29 12:34:21 volumio-miro volumio[1192]: xcb_connection_has_error() returned true Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 29 12:34:21 volumio-miro volumio[1192]: No protocol specified Aug 29 12:34:21 volumio-miro volumio[1192]: xcb_connection_has_error() returned true Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Aug 29 12:34:21 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:21 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:21 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:21 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:21 volumio-miro volumio[1192]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Aug 29 12:34:21 volumio-miro volumio[1192]: info: QobuzConnect: setDeactiveState invoked Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:21 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:21 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:21 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:21.597+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:21 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:21.598+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:21 volumio-miro volumio[1192]: info: Executing endpoint qc_getconfig Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Aug 29 12:34:21 volumio-miro volumio[1192]: info: Executing endpoint qc_getconfig Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Aug 29 12:34:21 volumio-miro qobuz-connect[22464]: 20260829 12:34:21.700 [22464.22464] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Aug 29 12:34:21 volumio-miro volumio[1192]: info: Starting Shairport Sync Aug 29 12:34:21 volumio-miro qobuz-connect[22464]: 20260829 12:34:21.706 [22464.22464] INFO VolumeManager: [0x7ffa0630]: Setting new playback volume: 75 Aug 29 12:34:21 volumio-miro qobuz-connect[22464]: 20260829 12:34:21.706 [22464.22464] INFO VolumeManager: [0x7ffa0630]: Setting new mute state: 0 Aug 29 12:34:21 volumio-miro qobuz-connect[22464]: 20260829 12:34:21.706 [22464.22464] INFO AudioStreamManager: [0x7ffa0388]: Setting new audio download buffer size: 1048576 Aug 29 12:34:21 volumio-miro qobuz-connect[22464]: 20260829 12:34:21.707 [22464.22464] INFO QobuzConnect: [0x7ffa0ef8]: Client initialized! Aug 29 12:34:21 volumio-miro qobuz-connect[22464]: 20260829 12:34:21.707 [22464.22464] INFO SampleApp: Starting Avahi advertising, name: Volumio Miro, service name: _qobuz-connect._tcp Aug 29 12:34:21 volumio-miro qobuz-connect[22464]: 20260829 12:34:21.718 [22464.22464] INFO LocalConfigManager: [0x7ffa00b0]: Starting Local Configuration server Aug 29 12:34:21 volumio-miro qobuz-connect[22464]: 20260829 12:34:21.718 [22464.22464] INFO SampleApp: Starting Local configuration server Aug 29 12:34:21 volumio-miro qobuz-connect[22464]: 20260829 12:34:21.719 [22464.22464] INFO SampleApp: Connected to UNIX socket client 0x7ff95ed8 Aug 29 12:34:21 volumio-miro volumio[1192]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Aug 29 12:34:21 volumio-miro volumio[1192]: info: QobuzConnect: QOBUZ Connect daemon connected Aug 29 12:34:21 volumio-miro volumio[1192]: info: Asound.conf file written Aug 29 12:34:21 volumio-miro sudo[22483]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 12:34:21 volumio-miro sudo[22483]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:21 volumio-miro sudo[22486]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 29 12:34:21 volumio-miro systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Aug 29 12:34:21 volumio-miro systemd[1]: shairport-sync.service: Succeeded. Aug 29 12:34:21 volumio-miro systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Aug 29 12:34:21 volumio-miro systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Aug 29 12:34:21 volumio-miro sudo[22483]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:21 volumio-miro sudo[22486]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:21 volumio-miro sudo[22486]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:21 volumio-miro qobuz-connect[22464]: 20260829 12:34:21.849 [22464.22464] INFO SampleApp: Playback volume changed: 75 Aug 29 12:34:21 volumio-miro volumio[1192]: No protocol specified Aug 29 12:34:21 volumio-miro volumio[1192]: xcb_connection_has_error() returned true Aug 29 12:34:21 volumio-miro volumio[1192]: info: Output device has changed, restarting MPD Aug 29 12:34:21 volumio-miro sudo[22508]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 29 12:34:21 volumio-miro volumio[1192]: info: Output device has changed, restarting Shairport Sync Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:21 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 12:34:21 volumio-miro sudo[22508]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:22 volumio-miro sudo[22512]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 12:34:22 volumio-miro sudo[22508]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:22 volumio-miro sudo[22512]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:22 volumio-miro volumio[1192]: No protocol specified Aug 29 12:34:22 volumio-miro volumio[1192]: xcb_connection_has_error() returned true Aug 29 12:34:22 volumio-miro volumio[1192]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 29 12:34:22 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:22 volumio-miro volumio[1192]: info: QobuzConnect: setDeactiveState invoked Aug 29 12:34:22 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:22 volumio-miro sudo[22530]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 29 12:34:22 volumio-miro systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Aug 29 12:34:22 volumio-miro systemd[1]: mpd.service: Succeeded. Aug 29 12:34:22 volumio-miro systemd[1]: Stopped Music Player Daemon. Aug 29 12:34:22 volumio-miro systemd[1]: Starting Music Player Daemon... Aug 29 12:34:22 volumio-miro sudo[22530]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:22 volumio-miro sudo[22530]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:22 volumio-miro sudo[22535]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 29 12:34:22 volumio-miro sudo[22535]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:22 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:22 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:22 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:22 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:22 volumio-miro sudo[22535]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:22 volumio-miro volumio[1192]: No protocol specified Aug 29 12:34:22 volumio-miro volumio[1192]: xcb_connection_has_error() returned true Aug 29 12:34:22 volumio-miro volumio[1192]: Playing WAVE '/volumio/app/silence.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo Aug 29 12:34:22 volumio-miro volumio[1192]: No protocol specified Aug 29 12:34:22 volumio-miro volumio[1192]: xcb_connection_has_error() returned true Aug 29 12:34:22 volumio-miro volumio[1192]: info: QobuzConnect: setDeactiveState invoked Aug 29 12:34:22 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:22 volumio-miro volumio[1192]: info: Output device has changed, restarting MPD Aug 29 12:34:22 volumio-miro sudo[22556]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 29 12:34:22 volumio-miro volumio[1192]: info: Output device has changed, restarting Shairport Sync Aug 29 12:34:22 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:22 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 12:34:22 volumio-miro sudo[22556]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro sudo[22558]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 29 12:34:23 volumio-miro sudo[22563]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 12:34:23 volumio-miro sudo[22563]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro sudo[22558]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro sudo[22556]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro sudo[22558]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro volumio[1192]: No protocol specified Aug 29 12:34:23 volumio-miro volumio[1192]: xcb_connection_has_error() returned true Aug 29 12:34:23 volumio-miro volumio[1192]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:23 volumio-miro volumio[1192]: info: QobuzConnect: setDeactiveState invoked Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:23 volumio-miro sudo[22590]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 29 12:34:23 volumio-miro systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Aug 29 12:34:23 volumio-miro systemd[1]: mpd.service: Succeeded. Aug 29 12:34:23 volumio-miro systemd[1]: Stopped Music Player Daemon. Aug 29 12:34:23 volumio-miro systemd[1]: Starting Music Player Daemon... Aug 29 12:34:23 volumio-miro volumio[1192]: No protocol specified Aug 29 12:34:23 volumio-miro volumio[1192]: xcb_connection_has_error() returned true Aug 29 12:34:23 volumio-miro sudo[22590]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioUpdateVolumeSettings Aug 29 12:34:23 volumio-miro volumio[1192]: info: Updating Volume Controller Parameters: Device: 1,1 Name: softvolume Mixer: SoftMaster Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Aug 29 12:34:23 volumio-miro sudo[22590]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Aug 29 12:34:23 volumio-miro volumio[1192]: info: Disabling external Volume Control Aug 29 12:34:23 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:23 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:23 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:23 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:23 volumio-miro sudo[22595]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 29 12:34:23 volumio-miro sudo[22595]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro sudo[22616]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 29 12:34:23 volumio-miro sudo[22595]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro sudo[22621]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 29 12:34:23 volumio-miro sudo[22616]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro sudo[22621]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro sudo[22631]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 29 12:34:23 volumio-miro sudo[22631]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro sudo[22616]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro sudo[22645]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 29 12:34:23 volumio-miro sudo[22621]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro sudo[22645]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro sudo[22662]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 29 12:34:23 volumio-miro sudo[22631]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro sudo[22662]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro sudo[22645]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:23 volumio-miro sudo[22662]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:23 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 29 12:34:23 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 29 12:34:23 volumio-miro volumio[1192]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 29 12:34:23 volumio-miro volumio[1192]: info: FusionDsp - Effects disabled Aug 29 12:34:23 volumio-miro sudo[22689]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:23 volumio-miro sudo[22682]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 29 12:34:23 volumio-miro sudo[22686]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 29 12:34:23 volumio-miro sudo[22689]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:23 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:23 volumio-miro sudo[22682]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro sudo[22686]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:23.664+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:23 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:23.664+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:23 volumio-miro volumio[1192]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: No protocol specified Aug 29 12:34:23 volumio-miro volumio[1192]: xcb_connection_has_error() returned true Aug 29 12:34:23 volumio-miro volumio[1192]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read property 'split' of undefined Aug 29 12:34:23 volumio-miro volumio[1192]: info: MPD Permissions set Aug 29 12:34:23 volumio-miro systemd[1]: Stopping Volumio Qobuz Connect Service... Aug 29 12:34:23 volumio-miro qobuz-connect[22464]: 20260829 12:34:23.680 [22464.22464] INFO SampleApp: Stopping Local configuration server Aug 29 12:34:23 volumio-miro volumio[1192]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read property 'split' of undefined Aug 29 12:34:23 volumio-miro volumio[1192]: info: MPD Permissions set Aug 29 12:34:23 volumio-miro volumio[1192]: info: Shairport-Sync Started Aug 29 12:34:23 volumio-miro qobuz-connect[22464]: 20260829 12:34:23.691 [22464.22464] INFO SampleApp: shat down connection on UNIX socket Aug 29 12:34:23 volumio-miro systemd[1]: qobuz-connect.service: Succeeded. Aug 29 12:34:23 volumio-miro systemd[1]: Stopped Volumio Qobuz Connect Service. Aug 29 12:34:23 volumio-miro sudo[22682]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro systemd[1]: Started Volumio Qobuz Connect Service. Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:23 volumio-miro sudo[22686]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro sudo[22689]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro volumio[1192]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Aug 29 12:34:23 volumio-miro volumio[1192]: info: QobuzConnect: setDeactiveState invoked Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:23 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:23 volumio-miro volumio[1192]: error: FusionDsp - WebSocket error: [object Object] Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:23 volumio-miro sudo[22721]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 29 12:34:23 volumio-miro sudo[22721]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 29 12:34:23 volumio-miro systemd[1]: Stopping Volumio Qobuz Connect Service... Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:23 volumio-miro systemd[1]: qobuz-connect.service: Main process exited, code=killed, status=2/INT Aug 29 12:34:23 volumio-miro systemd[1]: qobuz-connect.service: Succeeded. Aug 29 12:34:23 volumio-miro systemd[1]: Stopped Volumio Qobuz Connect Service. Aug 29 12:34:23 volumio-miro systemd[1]: Started Volumio Qobuz Connect Service. Aug 29 12:34:23 volumio-miro sudo[22721]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:23 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:23 volumio-miro volumio[1192]: info: TidalConnect service stoped! Aug 29 12:34:23 volumio-miro volumio[1192]: info: TidalConnect service stoped! Aug 29 12:34:23 volumio-miro volumio[1192]: info: Executing endpoint qc_getconfig Aug 29 12:34:23 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Aug 29 12:34:24 volumio-miro volumio[1192]: info: Starting Shairport Sync Aug 29 12:34:24 volumio-miro volumio[1192]: info: Starting Shairport Sync Aug 29 12:34:24 volumio-miro volumio[1192]: info: Executing endpoint qc_getconfig Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Aug 29 12:34:24 volumio-miro sudo[22750]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 12:34:24 volumio-miro qobuz-connect[22736]: 20260829 12:34:24.145 [22736.22736] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Aug 29 12:34:24 volumio-miro volumio[1192]: info: TidalConnect service stoped! Aug 29 12:34:24 volumio-miro qobuz-connect[22736]: 20260829 12:34:24.150 [22736.22736] INFO VolumeManager: [0x7fd0f630]: Setting new playback volume: 75 Aug 29 12:34:24 volumio-miro qobuz-connect[22736]: 20260829 12:34:24.150 [22736.22736] INFO VolumeManager: [0x7fd0f630]: Setting new mute state: 0 Aug 29 12:34:24 volumio-miro qobuz-connect[22736]: 20260829 12:34:24.150 [22736.22736] INFO AudioStreamManager: [0x7fd0f388]: Setting new audio download buffer size: 1048576 Aug 29 12:34:24 volumio-miro qobuz-connect[22736]: 20260829 12:34:24.150 [22736.22736] INFO QobuzConnect: [0x7fd0fef8]: Client initialized! Aug 29 12:34:24 volumio-miro qobuz-connect[22736]: 20260829 12:34:24.150 [22736.22736] INFO SampleApp: Starting Avahi advertising, name: Volumio Miro, service name: _qobuz-connect._tcp Aug 29 12:34:24 volumio-miro sudo[22753]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 29 12:34:24 volumio-miro sudo[22750]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:24 volumio-miro qobuz-connect[22736]: 20260829 12:34:24.175 [22736.22736] INFO LocalConfigManager: [0x7fd0f0b0]: Starting Local Configuration server Aug 29 12:34:24 volumio-miro qobuz-connect[22736]: 20260829 12:34:24.175 [22736.22736] INFO SampleApp: Starting Local configuration server Aug 29 12:34:24 volumio-miro qobuz-connect[22736]: 20260829 12:34:24.175 [22736.22736] INFO SampleApp: Connected to UNIX socket client 0x7fd04ed8 Aug 29 12:34:24 volumio-miro volumio[1192]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Aug 29 12:34:24 volumio-miro volumio[1192]: info: QobuzConnect: QOBUZ Connect daemon connected Aug 29 12:34:24 volumio-miro volumio[1192]: info: TidalConnect service stoped! Aug 29 12:34:24 volumio-miro sudo[22753]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:24 volumio-miro systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Aug 29 12:34:24 volumio-miro systemd[1]: shairport-sync.service: Succeeded. Aug 29 12:34:24 volumio-miro systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Aug 29 12:34:24 volumio-miro systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Aug 29 12:34:24 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:24 volumio-miro sudo[22750]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:24 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:24 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:24 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:24 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:24 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:24 volumio-miro qobuz-connect[22736]: 20260829 12:34:24.294 [22736.22736] INFO SampleApp: Playback volume changed: 75 Aug 29 12:34:24 volumio-miro systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:24 volumio-miro systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Aug 29 12:34:24 volumio-miro systemd[1]: shairport-sync.service: Succeeded. Aug 29 12:34:24 volumio-miro systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Aug 29 12:34:24 volumio-miro systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Aug 29 12:34:24 volumio-miro sudo[22753]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:24 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:24 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:24 volumio-miro volumio[1192]: info: Shairport-Sync Started Aug 29 12:34:24 volumio-miro volumio[1192]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Aug 29 12:34:24 volumio-miro volumio[1192]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Aug 29 12:34:24 volumio-miro volumio[1192]: info: Shairport-Sync Started Aug 29 12:34:24 volumio-miro volumio[1192]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Aug 29 12:34:24 volumio-miro volumio[1192]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Aug 29 12:34:24 volumio-miro sudo[22796]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Aug 29 12:34:24 volumio-miro sudo[22796]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:24 volumio-miro sudo[22800]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Aug 29 12:34:24 volumio-miro sudo[22800]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:24 volumio-miro systemd[1]: Started Volumio Tidal Connect Service. Aug 29 12:34:24 volumio-miro sudo[22796]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:24 volumio-miro sudo[22800]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: mpd , restartMpd Aug 29 12:34:24 volumio-miro sudo[22820]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 12:34:24 volumio-miro sudo[22820]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:24 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:24 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:24 volumio-miro volumio[1192]: info: Executing endpoint tc_getconfig Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Aug 29 12:34:24 volumio-miro vtcs[22808]: STARTING TidalConnect services, version: 1.6.1 Aug 29 12:34:24 volumio-miro vtcs[22808]: STARTED TidalConnect services. Aug 29 12:34:24 volumio-miro volumio[1192]: info: Executing endpoint tc_connect Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Aug 29 12:34:24 volumio-miro volumio[1192]: info: Connecting to TidalConnect Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:24 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:24 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:24 volumio-miro systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Aug 29 12:34:24 volumio-miro systemd[1]: mpd.service: Succeeded. Aug 29 12:34:24 volumio-miro systemd[1]: Stopped Music Player Daemon. Aug 29 12:34:24 volumio-miro systemd[1]: Starting Music Player Daemon... Aug 29 12:34:24 volumio-miro volumio[1192]: info: CorePlayQueue::getTrack 0 Aug 29 12:34:24 volumio-miro volumio[1192]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received tidalconnect Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:24 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:24 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:24 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:24 volumio-miro volumio[1192]: info: CorePlayQueue::getTrack 0 Aug 29 12:34:24 volumio-miro volumio[1192]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received tidalconnect Aug 29 12:34:24 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:24.950+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:24 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:24.950+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:24 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:24.950+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:24 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:24 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:25 volumio-miro volumio[1192]: info: VolumeController::SetAlsaVolume100 Aug 29 12:34:25 volumio-miro sudo[22850]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 29 12:34:25 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:25 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 12:34:25 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:25 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:25 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:25 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:25 volumio-miro sudo[22850]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:25 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:25.076+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:25 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:25.077+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:25 volumio-miro sudo[22850]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:25 volumio-miro volumio[1192]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: No protocol specified Aug 29 12:34:25 volumio-miro volumio[1192]: xcb_connection_has_error() returned true Aug 29 12:34:25 volumio-miro volumio[1192]: info: TidalConnect service stoped! Aug 29 12:34:25 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:25 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:25 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:25 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:25 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:26 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.110:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:26 volumio-miro volumio[1192]: info: TidalConnect service stoped! Aug 29 12:34:26 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:26 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:26 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:26 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:26 volumio-miro volumio[1192]: info: TidalConnect service stoped! Aug 29 12:34:26 volumio-miro mpd[22866]: Aug 29 12:34 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 29 12:34:26 volumio-miro systemd[1]: Started Music Player Daemon. Aug 29 12:34:26 volumio-miro sudo[22512]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:26 volumio-miro sudo[22820]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:26 volumio-miro sudo[22331]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:26 volumio-miro sudo[22563]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:26 volumio-miro volumio[1192]: error: MPD error: The expression evaluated to a falsy value: Aug 29 12:34:26 volumio-miro volumio[1192]: assert.ok(self.idling) Aug 29 12:34:26 volumio-miro volumio[1192]: error: The expression evaluated to a falsy value: Aug 29 12:34:26 volumio-miro volumio[1192]: assert.ok(self.idling) Aug 29 12:34:26 volumio-miro volumio[1192]: error: MPD error: The expression evaluated to a falsy value: Aug 29 12:34:26 volumio-miro volumio[1192]: assert.ok(self.idling) Aug 29 12:34:26 volumio-miro volumio[1192]: error: The expression evaluated to a falsy value: Aug 29 12:34:26 volumio-miro volumio[1192]: assert.ok(self.idling) Aug 29 12:34:26 volumio-miro volumio[1192]: error: MPD error: The expression evaluated to a falsy value: Aug 29 12:34:26 volumio-miro volumio[1192]: assert.ok(self.idling) Aug 29 12:34:26 volumio-miro volumio[1192]: error: The expression evaluated to a falsy value: Aug 29 12:34:26 volumio-miro volumio[1192]: assert.ok(self.idling) Aug 29 12:34:26 volumio-miro volumio[1192]: error: updateQueue error: null Aug 29 12:34:26 volumio-miro volumio[1192]: info: TidalConnect service stoped! Aug 29 12:34:26 volumio-miro volumio[1192]: info: TidalConnect service stoped! Aug 29 12:34:26 volumio-miro volumio[1192]: info: TidalConnect service stoped! Aug 29 12:34:26 volumio-miro volumio[1192]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Aug 29 12:34:26 volumio-miro volumio[1192]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Aug 29 12:34:26 volumio-miro volumio[1192]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Aug 29 12:34:26 volumio-miro volumio[1192]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Aug 29 12:34:26 volumio-miro sudo[22906]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Aug 29 12:34:26 volumio-miro sudo[22908]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Aug 29 12:34:26 volumio-miro sudo[22906]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:26 volumio-miro sudo[22908]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:26 volumio-miro volumio[1192]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Aug 29 12:34:26 volumio-miro volumio[1192]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect Aug 29 12:34:26 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:26 volumio-miro sudo[22906]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:26 volumio-miro sudo[22908]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:26 volumio-miro sudo[22924]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Aug 29 12:34:26 volumio-miro sudo[22924]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:26 volumio-miro sudo[22924]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:27 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:27 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:27 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:27 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:27 volumio-miro volumio[1192]: info: TidalConnect service started! Aug 29 12:34:27 volumio-miro volumio[1192]: info: TidalConnect service started! Aug 29 12:34:27 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:27 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:28 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:28 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:28 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:28 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:28 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:28 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:28 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:28 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:28 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:28 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.113:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:28 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:28 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:28 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:28 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:28 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:28 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:28 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:28 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.110:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:28 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:28 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:28 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:28+02:00" level=debug msg="handling resume player command from 27ed7f96e3bca5d535c9523961b321988daa022e" Aug 29 12:34:28 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:28+02:00" level=trace msg="seek to 1947ms (diff: 191ms, samples: 85862, bytes: 69459)" uri="spotify:track:7wj7sfoOB2lbQArn6jQ6Nb" Aug 29 12:34:29 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate, raw: Aug 29 12:34:29 volumio-miro volumio[1192]: error: FusionDsp - invalid sample rate Aug 29 12:34:29 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 29 12:34:29 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 29 12:34:29 volumio-miro volumio[1192]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 29 12:34:29 volumio-miro volumio[1192]: info: FusionDsp - Effects disabled Aug 29 12:34:29 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:29+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Aug 29 12:34:29 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:29+02:00" level=debug msg="resume track at 1756ms" Aug 29 12:34:29 volumio-miro volumio[1192]: info: FusionDsp - {"Reload":{"result":"Ok"}} Aug 29 12:34:29 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:29 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:29+02:00" level=trace msg="scheduling prefetch in 277s" Aug 29 12:34:29 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:29+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 12:34:29 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:29 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:29+02:00" level=trace msg="emitting websocket event: playing" Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:29 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:29 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:29 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:29.233+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 12:34:29 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:29.233+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:29 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:29 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:29 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:29 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:29 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:29 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:29 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:29 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:29 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:29.523+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 12:34:29 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:29.523+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:29 volumio-miro volumio[1192]: info: TidalConnect service started! Aug 29 12:34:29 volumio-miro volumio[1192]: info: TidalConnect service started! Aug 29 12:34:29 volumio-miro volumio[1192]: info: TidalConnect service started! Aug 29 12:34:29 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:29+02:00" level=debug msg="handling pause player command from 27ed7f96e3bca5d535c9523961b321988daa022e" Aug 29 12:34:29 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:29+02:00" level=debug msg="pause track at 3306ms" Aug 29 12:34:30 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:30+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:30 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:30+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 12:34:30 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:30+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:30 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:30+02:00" level=trace msg="emitting websocket event: paused" Aug 29 12:34:30 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:30 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:30 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 12:34:30 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:30 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:30 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:30 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:30 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:30.210+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:30 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:30.211+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:30 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:30 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:30 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:30 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:30 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.113:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:30 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:30 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:30 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:30 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:30 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:30 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:30 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:31 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:31 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:31 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:31 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:31 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.110:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:31 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:31 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.113:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:31 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:31 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.110:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:31 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:31 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.113:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:31 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:31 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=debug msg="handling resume player command from 27ed7f96e3bca5d535c9523961b321988daa022e" Aug 29 12:34:32 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:32 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:32 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=trace msg="seek to 3306ms (diff: 108ms, samples: 145794, bytes: 158646)" uri="spotify:track:7wj7sfoOB2lbQArn6jQ6Nb" Aug 29 12:34:32 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:32 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=debug msg="resume track at 3198ms" Aug 29 12:34:32 volumio-miro volumio[1192]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 29 12:34:32 volumio-miro volumio[1192]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 29 12:34:32 volumio-miro volumio[1192]: info: FusionDsp - Effects disabled Aug 29 12:34:32 volumio-miro volumio[1192]: info: FusionDsp - {"Reload":{"result":"Ok"}} Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=trace msg="scheduling prefetch in 275s" Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=debug msg="sending successful reply for dealer request" Aug 29 12:34:32 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.110:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=trace msg="emitting websocket event: playing" Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:32 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:32 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:32 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:32.491+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 12:34:32 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:32.492+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:32 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:32.722+02:00 level=INFO msg="player pause request" component=server type=REQUEST_TYPE_PLAYER_PAUSE peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-419.703047ms timeout=10s Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPause Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreStateMachine::pause Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreStateMachine::stPlaybackTimer Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreStateMachine::servicePause Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePause Aug 29 12:34:32 volumio-miro volumio[1192]: info: Spotify Received pause Aug 29 12:34:32 volumio-miro volumio[1192]: info: Sending Spotify command to local API: /player/pause Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=debug msg="pause track at 3903ms" Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:32 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:32 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:32 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:32.778+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PLAYING positionMs=0 volume=100 Aug 29 12:34:32 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:32.779+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 29 12:34:32 volumio-miro go-librespot[21353]: time="2026-08-29T12:34:32+02:00" level=trace msg="emitting websocket event: paused" Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::servicePushState Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreStateMachine::pushState Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioPushState Aug 29 12:34:32 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output update for this device Aug 29 12:34:32 volumio-miro volumio[1192]: info: MRS: Pushing multiroomSync output Aug 29 12:34:32 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:32 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:32.909+02:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" state=STATUS_PAUSED positionMs=0 volume=100 Aug 29 12:34:32 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:32.910+02:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" id=spotify:track:7wj7sfoOB2lbQArn6jQ6Nb title="Deeper and Deeper - The Juan Maclean Club Mix" Aug 29 12:34:33 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:33 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:33 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:33 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:34 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:34 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:34 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:34 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:35 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:35 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:35 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:35 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:36 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:36 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:36 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:36 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:36 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:36.695+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s Aug 29 12:34:36 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:36.725+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=30.239087ms Aug 29 12:34:36 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:36.726+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=http://pushupdates.volumio.org duration=30.323963ms Aug 29 12:34:36 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:36.737+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=41.814559ms Aug 29 12:34:36 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:36.803+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=107.497569ms Aug 29 12:34:36 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:36.806+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=https://www.googleapis.com duration=110.617554ms Aug 29 12:34:36 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:36.835+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=139.739257ms Aug 29 12:34:36 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:36.842+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=https://database.volumio.cloud duration=146.575981ms Aug 29 12:34:36 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:36.843+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=https://functions.volumio.cloud duration=147.721658ms Aug 29 12:34:36 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:36.845+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=https://securetoken.googleapis.com duration=150.040719ms Aug 29 12:34:36 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:36.853+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=https://functions.volumio.cloud duration=156.989444ms Aug 29 12:34:37 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:37.067+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=https://google.com duration=371.529579ms Aug 29 12:34:37 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:37 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:37 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:37 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:37 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:37.613+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=http://cddb.volumio.org duration=918.267713ms Aug 29 12:34:37 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:34:37.859+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-452.806552ms timeout=10s endpoint=http://plugins.volumio.org duration=1.163336563s Aug 29 12:34:38 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:38 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:38 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:38 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:38 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:38 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.113:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:38 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:38 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.110:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 29 12:34:38 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 29 12:34:39 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:39 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:39 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:39 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:40 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:40 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:40 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:40 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:41 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:41 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:41 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:41 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:41 volumio-miro volumio[1192]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 29 12:34:42 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:42 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:42 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:42 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:43 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:43 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:43 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:43 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:44 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:44 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:44 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:44 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:45 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:45 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:45 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:45 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:45 volumio-miro volumio[1192]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Aug 29 12:34:45 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Aug 29 12:34:45 volumio-miro volumio[1192]: info: Creating Spotify config file Aug 29 12:34:45 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:45 volumio-miro volumio[1192]: info: Spotify config file written Aug 29 12:34:45 volumio-miro sudo[22990]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 29 12:34:45 volumio-miro sudo[22990]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:45 volumio-miro systemd[1]: Stopping go-librespot Daemon... Aug 29 12:34:45 volumio-miro systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Aug 29 12:34:45 volumio-miro systemd[1]: go-librespot-daemon.service: Succeeded. Aug 29 12:34:45 volumio-miro systemd[1]: Stopped go-librespot Daemon. Aug 29 12:34:45 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:45 volumio-miro volumio[1192]: info: Connection to go-librespot Websocket closed Aug 29 12:34:45 volumio-miro systemd[1]: Started go-librespot Daemon. Aug 29 12:34:45 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:45 volumio-miro sudo[22990]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:45 volumio-miro go-librespot[22996]: go-librespot daemon starting... Aug 29 12:34:45 volumio-miro go-librespot[22996]: time="2026-08-29T12:34:45+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 12:34:45 volumio-miro go-librespot[22996]: time="2026-08-29T12:34:45+02:00" level=debug msg="app state loaded" Aug 29 12:34:45 volumio-miro go-librespot[22996]: time="2026-08-29T12:34:45+02:00" level=debug msg="stored credentials not found" Aug 29 12:34:45 volumio-miro go-librespot[22996]: time="2026-08-29T12:34:45+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 12:34:45 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:45 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:45 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:45 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:45 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:45 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.113:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:45 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:45 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:45 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:45 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:45 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:45 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:45 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:46 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.110:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:46 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:46 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:46 volumio-miro go-librespot[22996]: time="2026-08-29T12:34:46+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 29 12:34:46 volumio-miro go-librespot[22996]: time="2026-08-29T12:34:46+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 29 12:34:46 volumio-miro go-librespot[22996]: time="2026-08-29T12:34:46+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 29 12:34:46 volumio-miro go-librespot[22996]: time="2026-08-29T12:34:46+02:00" level=info msg="zeroconf server listening on port 35165" Aug 29 12:34:46 volumio-miro go-librespot[22996]: time="2026-08-29T12:34:46+02:00" level=info msg="using avahi-daemon avahi 0.7 for mDNS service registration" Aug 29 12:34:46 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:46 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:46 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:46 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:47 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:47 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.113:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:34:47 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:34:47 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.110:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:34:47 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:47 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:47 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:47 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:47 volumio-miro volumio[1192]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Aug 29 12:34:47 volumio-miro volumio[1192]: info: Creating Spotify config file Aug 29 12:34:47 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:47 volumio-miro volumio[1192]: info: Spotify config file written Aug 29 12:34:47 volumio-miro sudo[23008]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 29 12:34:47 volumio-miro sudo[23008]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:47 volumio-miro systemd[1]: Stopping go-librespot Daemon... Aug 29 12:34:47 volumio-miro systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Aug 29 12:34:47 volumio-miro systemd[1]: go-librespot-daemon.service: Succeeded. Aug 29 12:34:47 volumio-miro systemd[1]: Stopped go-librespot Daemon. Aug 29 12:34:47 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:47 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Aug 29 12:34:47 volumio-miro systemd[1]: Started go-librespot Daemon. Aug 29 12:34:47 volumio-miro sudo[23008]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:47 volumio-miro go-librespot[23014]: go-librespot daemon starting... Aug 29 12:34:47 volumio-miro go-librespot[23014]: time="2026-08-29T12:34:47+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 12:34:47 volumio-miro go-librespot[23014]: time="2026-08-29T12:34:47+02:00" level=debug msg="app state loaded" Aug 29 12:34:47 volumio-miro go-librespot[23014]: time="2026-08-29T12:34:47+02:00" level=debug msg="stored credentials not found" Aug 29 12:34:47 volumio-miro go-librespot[23014]: time="2026-08-29T12:34:47+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 12:34:48 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:48 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:48 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:48 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:48 volumio-miro volumio[1192]: info: Initializing connection to go-librespot Websocket Aug 29 12:34:48 volumio-miro go-librespot[23014]: time="2026-08-29T12:34:48+02:00" level=debug msg="new websocket client" Aug 29 12:34:48 volumio-miro volumio[1192]: info: Connection to go-librespot Websocket established Aug 29 12:34:48 volumio-miro volumio[1192]: info: go-librespot daemon successfully initialized Aug 29 12:34:49 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 29 12:34:49 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 29 12:34:49 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:49 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:49 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:49 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:50 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:50 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:50 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:50 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:50 volumio-miro volumio[1192]: info: go-librespot daemon successfully initialized Aug 29 12:34:51 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:51 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:51 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:51 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:51 volumio-miro volumio[1192]: info: Getting Spotify volume Aug 29 12:34:51 volumio-miro volumio[1192]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12 Aug 29 12:34:51 volumio-miro volumio[1192]: info: Initializing connection to go-librespot Websocket Aug 29 12:34:51 volumio-miro go-librespot[23014]: time="2026-08-29T12:34:51+02:00" level=debug msg="new websocket client" Aug 29 12:34:51 volumio-miro volumio[1192]: info: Connection to go-librespot Websocket established Aug 29 12:34:51 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:52 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:52 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:52 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:52 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:52 volumio-miro go-librespot[23014]: time="2026-08-29T12:34:52+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 29 12:34:52 volumio-miro go-librespot[23014]: time="2026-08-29T12:34:52+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Aug 29 12:34:52 volumio-miro go-librespot[23014]: time="2026-08-29T12:34:52+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Aug 29 12:34:52 volumio-miro go-librespot[23014]: time="2026-08-29T12:34:52+02:00" level=info msg="zeroconf server listening on port 38751" Aug 29 12:34:52 volumio-miro go-librespot[23014]: time="2026-08-29T12:34:52+02:00" level=info msg="using avahi-daemon avahi 0.7 for mDNS service registration" Aug 29 12:34:52 volumio-miro go-librespot[23014]: time="2026-08-29T12:34:52+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Aug 29 12:34:52 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify Aug 29 12:34:52 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 12:34:52 volumio-miro volumio[1192]: Cannot find translation for source TIDAL Aug 29 12:34:52 volumio-miro volumio[1192]: info: Disabling plugin spop Aug 29 12:34:52 volumio-miro volumio[1192]: info: Done. Aug 29 12:34:52 volumio-miro volumio[1192]: info: Connection to go-librespot Websocket closed Aug 29 12:34:52 volumio-miro sudo[23026]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service Aug 29 12:34:52 volumio-miro sudo[23026]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:52 volumio-miro systemd[1]: Stopping go-librespot Daemon... Aug 29 12:34:52 volumio-miro systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Aug 29 12:34:52 volumio-miro systemd[1]: go-librespot-daemon.service: Succeeded. Aug 29 12:34:52 volumio-miro systemd[1]: Stopped go-librespot Daemon. Aug 29 12:34:52 volumio-miro volumio[1192]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 29 12:34:52 volumio-miro volumio[1192]: info: Connection to go-librespot Websocket closed Aug 29 12:34:52 volumio-miro sudo[23026]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:53 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:53 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:53 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:53 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:53 volumio-miro volumio[1192]: info: Initializing connection to go-librespot Websocket Aug 29 12:34:53 volumio-miro volumio[1192]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 29 12:34:54 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:54 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:54 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:54 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:54 volumio-miro volumio[1192]: info: Enabling plugin spop Aug 29 12:34:54 volumio-miro volumio[1192]: info: Loading plugin "spop"... Aug 29 12:34:54 volumio-miro volumio[1192]: info: PLUGIN START: spop Aug 29 12:34:54 volumio-miro volumio[1192]: info: Creating Spotify config file Aug 29 12:34:54 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 12:34:54 volumio-miro volumio[1192]: info: Done. Aug 29 12:34:54 volumio-miro volumio[1192]: info: Spotify config file written Aug 29 12:34:54 volumio-miro volumio[1192]: info: No need to fix Spotify hosts Aug 29 12:34:54 volumio-miro sudo[23036]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Aug 29 12:34:54 volumio-miro sudo[23036]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 12:34:54 volumio-miro systemd[1]: Started go-librespot Daemon. Aug 29 12:34:54 volumio-miro go-librespot[23042]: go-librespot daemon starting... Aug 29 12:34:54 volumio-miro sudo[23036]: pam_unix(sudo:session): session closed for user root Aug 29 12:34:54 volumio-miro go-librespot[23042]: time="2026-08-29T12:34:54+02:00" level=info msg="running go-librespot 0.7.1" Aug 29 12:34:54 volumio-miro go-librespot[23042]: time="2026-08-29T12:34:54+02:00" level=debug msg="app state loaded" Aug 29 12:34:54 volumio-miro go-librespot[23042]: time="2026-08-29T12:34:54+02:00" level=debug msg="stored credentials not found" Aug 29 12:34:54 volumio-miro go-librespot[23042]: time="2026-08-29T12:34:54+02:00" level=info msg="api server listening on 127.0.0.1:9879" Aug 29 12:34:54 volumio-miro volumio[1192]: info: New Spotify access tokenBQA6umA-V4... Aug 29 12:34:54 volumio-miro volumio[1192]: info: Spotify credentials grant success - running version from March 24, 2019 Aug 29 12:34:54 volumio-miro volumio[1192]: info: Getting Spotify volume Aug 29 12:34:54 volumio-miro volumio[1192]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Aug 29 12:34:54 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:34:54 volumio-miro go-librespot[23042]: time="2026-08-29T12:34:54+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 29 12:34:54 volumio-miro go-librespot[23042]: time="2026-08-29T12:34:54+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 29 12:34:54 volumio-miro go-librespot[23042]: time="2026-08-29T12:34:54+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 29 12:34:54 volumio-miro volumio[1192]: info: Spotify Successfully logged in Aug 29 12:34:54 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 29 12:34:54 volumio-miro volumio[1192]: info: [1787999694877] CoreMusicLibrary::Adding element Spotify Aug 29 12:34:54 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 12:34:54 volumio-miro volumio[1192]: Cannot find translation for source TIDAL Aug 29 12:34:54 volumio-miro volumio[1192]: Cannot find translation for source Spotify Aug 29 12:34:54 volumio-miro go-librespot[23042]: time="2026-08-29T12:34:54+02:00" level=info msg="zeroconf server listening on port 39330" Aug 29 12:34:54 volumio-miro go-librespot[23042]: time="2026-08-29T12:34:54+02:00" level=info msg="using avahi-daemon avahi 0.7 for mDNS service registration" Aug 29 12:34:55 volumio-miro volumiologrotate[551]: ls: cannot access '/var/log/samba/log.wb-VOLUMIO': No such file or directory Aug 29 12:34:55 volumio-miro volumiologrotate[551]: ls: cannot access 'MIRO': No such file or directory Aug 29 12:34:55 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:55 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:55 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:55 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:56 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:56 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:56 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:56 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:56 volumio-miro volumio[1192]: info: Initializing connection to go-librespot Websocket Aug 29 12:34:56 volumio-miro go-librespot[23042]: time="2026-08-29T12:34:56+02:00" level=debug msg="new websocket client" Aug 29 12:34:56 volumio-miro volumio[1192]: info: Connection to go-librespot Websocket established Aug 29 12:34:57 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:57 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:57 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:57 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:57 volumio-miro volumio[1192]: info: go-librespot daemon successfully initialized Aug 29 12:34:58 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:58 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:58 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:58 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:59 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:59 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:59 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:34:59 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:34:59 volumio-miro volumio[1192]: info: Getting Spotify volume Aug 29 12:34:59 volumio-miro volumio[1192]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12 Aug 29 12:34:59 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:35:00 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:35:00 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:35:00 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:35:00 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:35:00 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:00.547+02:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s Aug 29 12:35:00 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:00.579+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=31.559765ms Aug 29 12:35:00 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:00.587+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=40.29963ms Aug 29 12:35:00 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:00.589+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=42.107979ms Aug 29 12:35:00 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:00.657+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=https://www.googleapis.com duration=109.119833ms Aug 29 12:35:00 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:00.658+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=http://pushupdates.volumio.org duration=109.702296ms Aug 29 12:35:00 volumio-miro volumio[1192]: info: Initializing connection to go-librespot Websocket Aug 29 12:35:00 volumio-miro go-librespot[23042]: time="2026-08-29T12:35:00+02:00" level=debug msg="new websocket client" Aug 29 12:35:00 volumio-miro volumio[1192]: info: Connection to go-librespot Websocket established Aug 29 12:35:00 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:00.682+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=https://securetoken.googleapis.com duration=134.339003ms Aug 29 12:35:00 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:00.689+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=141.226186ms Aug 29 12:35:00 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:00.697+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=https://functions.volumio.cloud duration=149.556839ms Aug 29 12:35:00 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:00.700+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=https://database.volumio.cloud duration=151.999277ms Aug 29 12:35:00 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:00.703+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=https://functions.volumio.cloud duration=155.146969ms Aug 29 12:35:00 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:00.918+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=https://google.com duration=370.475777ms Aug 29 12:35:00 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 12:35:00 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 12:35:00 volumio-miro volumio[1192]: info: Discovery: Getting this device information Aug 29 12:35:00 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:35:00 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 12:35:01 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:35:01 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:35:01 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:35:01 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:35:01 volumio-miro volumio[1192]: verbose: New Socket.io Connection to 192.168.68.110:3000 from 192.168.68.109 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Aug 29 12:35:01 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:01.472+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=http://cddb.volumio.org duration=924.184219ms Aug 29 12:35:01 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 29 12:35:01 volumio-miro volumio[1192]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 29 12:35:01 volumio-miro volumio5-onboarding[2473]: time=2026-08-29T12:35:01.727+02:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.68.109:55972,192.168.68.109:58098 @ 0x2282c30" latency=-472.639112ms timeout=10s endpoint=http://plugins.volumio.org duration=1.178655314s Aug 29 12:35:02 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:35:02 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:35:02 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:35:02 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:35:03 volumio-miro volumio[1192]: info: Enabling plugin ampswitch Aug 29 12:35:03 volumio-miro volumio[1192]: info: Loading plugin "ampswitch"... Aug 29 12:35:03 volumio-miro volumio[1192]: info: Applying required configuration parameters for plugin ampswitch Aug 29 12:35:03 volumio-miro volumio[1192]: info: PLUGIN START: ampswitch Aug 29 12:35:03 volumio-miro kernel: rockchip-pinctrl pinctrl: pin 0 is unrouted Aug 29 12:35:03 volumio-miro volumio[1192]: info: Done. Aug 29 12:35:03 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:35:03 volumio-miro volumio[1192]: info: [ASDebug] CurState: pause PrevState: na Aug 29 12:35:03 volumio-miro volumio[1192]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Aug 29 12:35:03 volumio-miro volumio[1192]: info: [ASDebug] CurState: pause PrevState: na Aug 29 12:35:03 volumio-miro volumio[1192]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Aug 29 12:35:03 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:35:03 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:35:03 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:35:03 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:35:03 volumio-miro volumio[1192]: info: Getting Spotify volume Aug 29 12:35:03 volumio-miro volumio[1192]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12 Aug 29 12:35:03 volumio-miro volumio[1192]: info: CoreCommandRouter::volumioGetState Aug 29 12:35:03 volumio-miro volumio[1192]: info: [ASDebug] Pulsing GPIO for 500ms Aug 29 12:35:03 volumio-miro volumio[1192]: info: [ASDebug] Togle GPIO: ON Aug 29 12:35:03 volumio-miro volumio[1192]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 12:35:03 volumio-miro volumio[1192]: Error: EPERM: operation not permitted, write Aug 29 12:35:03 volumio-miro volumio[1192]: at Object.writeSync (fs.js:737:3) Aug 29 12:35:03 volumio-miro volumio[1192]: at Gpio.writeSync (/data/plugins/system_controller/ampswitch/node_modules/onoff/onoff.js:243:8) Aug 29 12:35:03 volumio-miro volumio[1192]: at AmpSwitchController.on (/data/plugins/system_controller/ampswitch/index.js:209:23) Aug 29 12:35:03 volumio-miro volumio[1192]: at AmpSwitchController.pulse (/data/plugins/system_controller/ampswitch/index.js:231:8) Aug 29 12:35:03 volumio-miro volumio[1192]: at Timeout._onTimeout (/data/plugins/system_controller/ampswitch/index.js:195:39) Aug 29 12:35:03 volumio-miro volumio[1192]: at listOnTimeout (internal/timers.js:557:17) Aug 29 12:35:03 volumio-miro volumio[1192]: at processTimers (internal/timers.js:500:7) { Aug 29 12:35:03 volumio-miro volumio[1192]: errno: -1, Aug 29 12:35:03 volumio-miro volumio[1192]: syscall: 'write', Aug 29 12:35:03 volumio-miro volumio[1192]: code: 'EPERM' Aug 29 12:35:03 volumio-miro volumio[1192]: } Aug 29 12:35:03 volumio-miro volumio[1192]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 12:35:04 volumio-miro lircd[1850]: lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:35:04 volumio-miro lircd[1850]: lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:35:04 volumio-miro lircd-0.10.1[1850]: Error: could not get file information for /dev/lirc0 Aug 29 12:35:04 volumio-miro lircd-0.10.1[1850]: default_init(): No such file or directory Aug 29 12:35:04 volumio-miro sudo[23126]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-08-29 12:34 Aug 29 12:35:04 volumio-miro sudo[23126]: 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="3dada8b1e619a5feb94867e0865ace17474d7bce" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="30045b259d1a704a832ca7c1460c1fdfa4b723f9" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 05 Mar 2026 12:25:22 AM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="tinkerboard" VOLUMIO_DEVICENAME="Asus Tinkerboard" VOLUMIO_HASH="cf5455596c5328b0cbc691c04ff0184a"