Feb 24 20:14:00 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:04 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:06 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:06-06:00" level=trace msg="sent dealer ping" Feb 24 20:14:06 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:06-06:00" level=trace msg="received dealer pong" Feb 24 20:14:08 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:12 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:12 bathroommusic volumio[1268]: info: CorePlayQueue::getTrack 675 Feb 24 20:14:12 bathroommusic volumio[1268]: info: CorePlayQueue::getTrack 429 Feb 24 20:14:12 bathroommusic volumio[1268]: info: Prefetching next song Feb 24 20:14:12 bathroommusic volumio[1268]: info: [1771985652202] ControllerSpotify::prefetch Feb 24 20:14:12 bathroommusic volumio[1268]: info: Sending Spotify command with payload to local API: /player/add_to_queue Feb 24 20:14:12 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:12-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 20:14:12 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:12-06:00" level=trace msg="prefetch as soon as possible" Feb 24 20:14:12 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:12-06:00" level=debug msg="prefetching next track" uri="spotify:track:75MKHk9JSlu8MOixmQ982v" Feb 24 20:14:12 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:12-06:00" level=debug msg="selected format OGG_VORBIS_160 (b5b37a8c7f63ac751ba84d22d0525beb2f4fca95)" uri="spotify:track:75MKHk9JSlu8MOixmQ982v" Feb 24 20:14:12 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:12-06:00" level=debug msg="requested aes key for file b5b37a8c7f63ac751ba84d22d0525beb2f4fca95, gid: 75MKHk9JSlu8MOixmQ982v" Feb 24 20:14:12 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:12-06:00" level=trace msg="found 2 cdn urls" uri="spotify:track:75MKHk9JSlu8MOixmQ982v" Feb 24 20:14:13 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:13-06:00" level=debug msg="fetched first chunk of 5, total size is 2315800 bytes" uri="spotify:track:75MKHk9JSlu8MOixmQ982v" Feb 24 20:14:13 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:13-06:00" level=info msg="prefetched track \"A Little More\" (duration: 144720ms)" uri="spotify:track:75MKHk9JSlu8MOixmQ982v" Feb 24 20:14:13 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:13-06:00" level=debug msg="fetched chunk 1/4, size: 524288" uri="spotify:track:75MKHk9JSlu8MOixmQ982v" Feb 24 20:14:14 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:14-06:00" level=debug msg="fetched chunk 2/4, size: 524288" uri="spotify:track:75MKHk9JSlu8MOixmQ982v" Feb 24 20:14:14 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:14-06:00" level=debug msg="fetched chunk 3/4, size: 524288" uri="spotify:track:75MKHk9JSlu8MOixmQ982v" Feb 24 20:14:16 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:16-06:00" level=trace msg="emitting websocket event: not_playing" Feb 24 20:14:16 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:16-06:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:75MKHk9JSlu8MOixmQ982v" Feb 24 20:14:16 bathroommusic volumio[1268]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:2M67EF4tYfK3CsGgMLjl7l","uri":"spotify:track:2M67EF4tYfK3CsGgMLjl7l","play_origin":"go-librespot"}} Feb 24 20:14:16 bathroommusic volumio[1268]: error: Failed to decode event: not_playing Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:16 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:16-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 20:14:16 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:16-06:00" level=trace msg="emitting websocket event: will_play" Feb 24 20:14:16 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:16-06:00" level=info msg="loaded track \"A Little More\" (paused: false, position: 0ms, duration: 144720ms, prefetched: true)" uri="spotify:track:75MKHk9JSlu8MOixmQ982v" Feb 24 20:14:16 bathroommusic volumio[1268]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:2M67EF4tYfK3CsGgMLjl7l","uri":"spotify:track:75MKHk9JSlu8MOixmQ982v","play_origin":"go-librespot"}} Feb 24 20:14:16 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:16-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 20:14:16 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:16-06:00" level=trace msg="scheduling prefetch in 115s" Feb 24 20:14:16 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:16-06:00" level=trace msg="emitting websocket event: metadata" Feb 24 20:14:16 bathroommusic volumio[1268]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:75MKHk9JSlu8MOixmQ982v","name":"A Little More","artist_names":["Alessia Cara"],"album_name":"A Little More","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b308df04ba9683e0cceece37","position":0,"duration":144720,"release_date":"year:2018 month:7 day:11","track_number":1,"disc_number":1}} Feb 24 20:14:16 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:16-06:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 24 20:14:16 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:16-06:00" level=trace msg="emitting websocket event: playing" Feb 24 20:14:16 bathroommusic volumio[1268]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:2M67EF4tYfK3CsGgMLjl7l","uri":"spotify:track:75MKHk9JSlu8MOixmQ982v","resume":false,"play_origin":"go-librespot"}} Feb 24 20:14:16 bathroommusic volumio[1268]: SPOTIFY: PUSH STATE SPOTIFY Feb 24 20:14:16 bathroommusic volumio[1268]: SPOTIFY: {"status":"play","service":"spop","title":"A Little More","artist":"Alessia Cara","album":"A Little More","albumart":"https://i.scdn.co/image/ab67616d00001e02b308df04ba9683e0cceece37","uri":"spotify:track:75MKHk9JSlu8MOixmQ982v","trackType":"spotify","seek":0,"duration":144,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreCommandRouter::servicePushState Feb 24 20:14:16 bathroommusic volumio[1268]: info: CorePlayQueue::getTrack 675 Feb 24 20:14:16 bathroommusic volumio[1268]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"A Little More","artist":"Alessia Cara","album":"A Little More","albumart":"https://i.scdn.co/image/ab67616d00001e02b308df04ba9683e0cceece37","uri":"spotify:track:75MKHk9JSlu8MOixmQ982v","trackType":"spotify","seek":0,"duration":144,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 24 20:14:16 bathroommusic volumio[1268]: verbose: CURRENT POSITION 675 Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreStateMachine::syncState stateService play Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreStateMachine::syncState currentStatus play Feb 24 20:14:16 bathroommusic volumio[1268]: info: Received an update from plugin. extracting info from payload Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreStateMachine::pushState Feb 24 20:14:16 bathroommusic volumio[1268]: info: CorePlayQueue::getTrack 675 Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreCommandRouter::volumioPushState Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreStateMachine::pushState Feb 24 20:14:16 bathroommusic volumio[1268]: info: CorePlayQueue::getTrack 675 Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreCommandRouter::volumioPushState Feb 24 20:14:16 bathroommusic volumio5-onboarding[6838]: time=2026-02-24T20:14:16.396-06:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.12.104:34316 @ 0x19d4900" state=STATUS_PLAYING positionMs=196167 volume=88 Feb 24 20:14:16 bathroommusic volumio5-onboarding[6838]: time=2026-02-24T20:14:16.397-06:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.12.104:34316 @ 0x19d4900" id=spotify:track:2M67EF4tYfK3CsGgMLjl7l title="Stolen Cars" Feb 24 20:14:16 bathroommusic volumio5-onboarding[6838]: time=2026-02-24T20:14:16.396-06:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.12.104:34316 @ 0x19d4900" state=STATUS_PLAYING positionMs=196167 volume=88 Feb 24 20:14:16 bathroommusic volumio5-onboarding[6838]: time=2026-02-24T20:14:16.398-06:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.12.104:34316 @ 0x19d4900" id=spotify:track:2M67EF4tYfK3CsGgMLjl7l title="Stolen Cars" Feb 24 20:14:16 bathroommusic volumio[1268]: SPOTIFY: RECEIVED VOLUMIO VOLUME 88 Feb 24 20:14:16 bathroommusic volumio[1268]: SPOTIFY: RECEIVED VOLUMIO VOLUME 88 Feb 24 20:14:16 bathroommusic volumio[1268]: SPOTIFY: PUSH STATE SPOTIFY Feb 24 20:14:16 bathroommusic volumio[1268]: SPOTIFY: {"status":"play","service":"spop","title":"A Little More","artist":"Alessia Cara","album":"A Little More","albumart":"https://i.scdn.co/image/ab67616d00001e02b308df04ba9683e0cceece37","uri":"spotify:track:75MKHk9JSlu8MOixmQ982v","trackType":"spotify","seek":0,"duration":144,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreCommandRouter::servicePushState Feb 24 20:14:16 bathroommusic volumio[1268]: info: CorePlayQueue::getTrack 675 Feb 24 20:14:16 bathroommusic volumio[1268]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"A Little More","artist":"Alessia Cara","album":"A Little More","albumart":"https://i.scdn.co/image/ab67616d00001e02b308df04ba9683e0cceece37","uri":"spotify:track:75MKHk9JSlu8MOixmQ982v","trackType":"spotify","seek":0,"duration":144,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 24 20:14:16 bathroommusic volumio[1268]: verbose: CURRENT POSITION 675 Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreStateMachine::syncState stateService play Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreStateMachine::syncState currentStatus play Feb 24 20:14:16 bathroommusic volumio[1268]: info: Received an update from plugin. extracting info from payload Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreStateMachine::pushState Feb 24 20:14:16 bathroommusic volumio[1268]: info: CorePlayQueue::getTrack 675 Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreCommandRouter::volumioPushState Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreStateMachine::pushState Feb 24 20:14:16 bathroommusic volumio[1268]: info: CorePlayQueue::getTrack 675 Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreCommandRouter::volumioPushState Feb 24 20:14:16 bathroommusic volumio5-onboarding[6838]: time=2026-02-24T20:14:16.699-06:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.12.104:34316 @ 0x19d4900" state=STATUS_PLAYING positionMs=196418 volume=88 Feb 24 20:14:16 bathroommusic volumio5-onboarding[6838]: time=2026-02-24T20:14:16.699-06:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.12.104:34316 @ 0x19d4900" id=spotify:track:2M67EF4tYfK3CsGgMLjl7l title="Stolen Cars" Feb 24 20:14:16 bathroommusic volumio5-onboarding[6838]: time=2026-02-24T20:14:16.700-06:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.12.104:34316 @ 0x19d4900" state=STATUS_PLAYING positionMs=196418 volume=88 Feb 24 20:14:16 bathroommusic volumio5-onboarding[6838]: time=2026-02-24T20:14:16.700-06:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.12.104:34316 @ 0x19d4900" id=spotify:track:2M67EF4tYfK3CsGgMLjl7l title="Stolen Cars" Feb 24 20:14:16 bathroommusic volumio[1268]: SPOTIFY: RECEIVED VOLUMIO VOLUME 88 Feb 24 20:14:16 bathroommusic volumio[1268]: SPOTIFY: RECEIVED VOLUMIO VOLUME 88 Feb 24 20:14:16 bathroommusic volumio[1268]: info: CoreStateMachine::startPlaybackTimer Feb 24 20:14:16 bathroommusic volumio[1268]: info: CorePlayQueue::getTrack 429 Feb 24 20:14:17 bathroommusic volumio[1268]: info: CoreStateMachine::pushState Feb 24 20:14:17 bathroommusic volumio[1268]: info: CorePlayQueue::getTrack 429 Feb 24 20:14:17 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 20:14:17 bathroommusic volumio[1268]: info: CoreCommandRouter::volumioPushState Feb 24 20:14:17 bathroommusic volumio5-onboarding[6838]: time=2026-02-24T20:14:17.104-06:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.12.104:34316 @ 0x19d4900" state=STATUS_PLAYING positionMs=250 volume=88 Feb 24 20:14:17 bathroommusic volumio5-onboarding[6838]: time=2026-02-24T20:14:17.105-06:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.12.104:34316 @ 0x19d4900" id=spotify:track:75MKHk9JSlu8MOixmQ982v title="A Little More" Feb 24 20:14:17 bathroommusic volumio[1268]: SPOTIFY: RECEIVED VOLUMIO VOLUME 88 Feb 24 20:14:20 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:24 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:28 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:32 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:36 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:36 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:36-06:00" level=trace msg="sent dealer ping" Feb 24 20:14:36 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:36-06:00" level=trace msg="received dealer pong" Feb 24 20:14:36 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087/desc0089, ...) Feb 24 20:14:36 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087/desc008a, ...) Feb 24 20:14:36 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087, ...) Feb 24 20:14:36 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086, ...) Feb 24 20:14:37 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086, ...) Feb 24 20:14:37 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087, ...) Feb 24 20:14:37 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087/desc0089, ...) Feb 24 20:14:37 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087/desc008a, ...) Feb 24 20:14:37 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service008b, ...) Feb 24 20:14:37 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service008b/char008c, ...) Feb 24 20:14:37 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service008b/char008e, ...) Feb 24 20:14:37 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service008b/char0090, ...) Feb 24 20:14:40 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:44 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:48 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:50 bathroommusic go-librespot[5964]: time="2026-02-24T20:14:50-06:00" level=debug msg="fetched chunk 4/4, size: 218648" uri="spotify:track:75MKHk9JSlu8MOixmQ982v" Feb 24 20:14:52 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:14:53 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087/desc0089, ...) Feb 24 20:14:53 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087/desc008a, ...) Feb 24 20:14:53 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087, ...) Feb 24 20:14:53 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086, ...) Feb 24 20:14:53 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service008b/char008c, ...) Feb 24 20:14:53 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service008b/char008e, ...) Feb 24 20:14:53 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service008b/char0090, ...) Feb 24 20:14:53 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service008b, ...) Feb 24 20:14:54 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086, ...) Feb 24 20:14:54 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087, ...) Feb 24 20:14:54 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087/desc0089, ...) Feb 24 20:14:54 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087/desc008a, ...) Feb 24 20:14:56 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:15:00 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:15:01 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087/desc0089, ...) Feb 24 20:15:01 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087/desc008a, ...) Feb 24 20:15:01 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087, ...) Feb 24 20:15:01 bathroommusic bluealsa[1048]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086, ...) Feb 24 20:15:02 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086, ...) Feb 24 20:15:02 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087, ...) Feb 24 20:15:02 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087/desc0089, ...) Feb 24 20:15:02 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service0086/char0087/desc008a, ...) Feb 24 20:15:02 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service008b, ...) Feb 24 20:15:02 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service008b/char008c, ...) Feb 24 20:15:02 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service008b/char008e, ...) Feb 24 20:15:02 bathroommusic bluealsa[1048]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_6A_02_E7_DD_39_1E/service008b/char0090, ...) Feb 24 20:15:04 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:15:06 bathroommusic go-librespot[5964]: time="2026-02-24T20:15:06-06:00" level=trace msg="sent dealer ping" Feb 24 20:15:06 bathroommusic go-librespot[5964]: time="2026-02-24T20:15:06-06:00" level=trace msg="received dealer pong" Feb 24 20:15:06 bathroommusic go-librespot[5964]: time="2026-02-24T20:15:06-06:00" level=trace msg="received accesspoint ping" Feb 24 20:15:06 bathroommusic go-librespot[5964]: time="2026-02-24T20:15:06-06:00" level=trace msg="received accesspoint pong ack" Feb 24 20:15:08 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:15:10 bathroommusic volumio[1268]: info: Enabling MyMusic plugin multiroom Feb 24 20:15:10 bathroommusic volumio[1268]: info: [MyVolumio PluginManager] Enabling and starting plugin audio_interface multiroom Feb 24 20:15:10 bathroommusic volumio[1268]: info: [MyVolumio PluginManager] Plugin audio_interface multiroom not in user plan, not enabling Feb 24 20:15:10 bathroommusic volumio[1268]: info: Error: Plugin audio_interface multiroom not in user plan, not enabling Feb 24 20:15:10 bathroommusic volumio[1268]: error: Could not Enable MyMusic Plugin: Error Feb 24 20:15:12 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:15:15 bathroommusic volumio[1268]: info: Enabling MyMusic plugin bluetooth Feb 24 20:15:15 bathroommusic volumio[1268]: info: [MyVolumio PluginManager] Enabling and starting plugin audio_interface bluetooth Feb 24 20:15:15 bathroommusic volumio[1268]: info: [MyVolumio PluginManager] Plugin audio_interface bluetooth not in user plan, not enabling Feb 24 20:15:15 bathroommusic volumio[1268]: info: Error: Plugin audio_interface bluetooth not in user plan, not enabling Feb 24 20:15:15 bathroommusic volumio[1268]: error: Could not Enable MyMusic Plugin: Error Feb 24 20:15:16 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:15:20 bathroommusic volumio[1268]: info: Enabling MyMusic plugin airplay_emulation Feb 24 20:15:20 bathroommusic volumio[1268]: info: Enabling plugin airplay_emulation Feb 24 20:15:20 bathroommusic volumio[1268]: info: Loading plugin "airplay_emulation"... Feb 24 20:15:20 bathroommusic volumio[1268]: info: Starting Shairport Sync Feb 24 20:15:20 bathroommusic volumio[1268]: info: PLUGIN START: airplay_emulation Feb 24 20:15:20 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 20:15:20 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 20:15:20 bathroommusic volumio[1268]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 24 20:15:20 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 24 20:15:20 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 24 20:15:20 bathroommusic volumio[1268]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 24 20:15:20 bathroommusic volumio[1268]: info: Done. Feb 24 20:15:20 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:15:20 bathroommusic volumio[1268]: info: Starting Shairport Sync Feb 24 20:15:20 bathroommusic volumio[1268]: info: Starting Shairport Sync Feb 24 20:15:20 bathroommusic sudo[8571]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 24 20:15:20 bathroommusic sudo[8571]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 24 20:15:20 bathroommusic sudo[8573]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 24 20:15:20 bathroommusic sudo[8573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 24 20:15:20 bathroommusic systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 24 20:15:20 bathroommusic systemd[1]: shairport-sync.service: Deactivated successfully. Feb 24 20:15:20 bathroommusic systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 24 20:15:20 bathroommusic systemd[1]: shairport-sync.service: Consumed 3.894s CPU time. Feb 24 20:15:20 bathroommusic systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 24 20:15:20 bathroommusic sudo[8571]: pam_unix(sudo:session): session closed for user root Feb 24 20:15:20 bathroommusic volumio[1268]: info: Shairport-Sync Started Feb 24 20:15:20 bathroommusic volumio[1268]: (node:1268) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 pbeg listeners added to [ShairportSyncReaderUDP]. Use emitter.setMaxListeners() to increase limit Feb 24 20:15:20 bathroommusic volumio[1268]: (Use `node --trace-warnings ...` to show where the warning was created) Feb 24 20:15:20 bathroommusic volumio[1268]: (node:1268) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 meta listeners added to [ShairportSyncReaderUDP]. Use emitter.setMaxListeners() to increase limit Feb 24 20:15:20 bathroommusic volumio[1268]: (node:1268) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 prgr listeners added to [ShairportSyncReaderUDP]. Use emitter.setMaxListeners() to increase limit Feb 24 20:15:20 bathroommusic volumio[1268]: (node:1268) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 pvol listeners added to [ShairportSyncReaderUDP]. Use emitter.setMaxListeners() to increase limit Feb 24 20:15:20 bathroommusic volumio[1268]: (node:1268) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 pend listeners added to [ShairportSyncReaderUDP]. Use emitter.setMaxListeners() to increase limit Feb 24 20:15:20 bathroommusic systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Feb 24 20:15:20 bathroommusic systemd[1]: shairport-sync.service: Deactivated successfully. Feb 24 20:15:20 bathroommusic systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 24 20:15:20 bathroommusic systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Feb 24 20:15:20 bathroommusic sudo[8573]: pam_unix(sudo:session): session closed for user root Feb 24 20:15:20 bathroommusic volumio[1268]: info: Shairport-Sync Started Feb 24 20:15:24 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:15:25 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: networkfs , discoverShares Feb 24 20:15:25 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , browseForService Feb 24 20:15:28 bathroommusic volumio[1268]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 24 20:15:30 bathroommusic volumio[1268]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 20:15:30 bathroommusic volumio[1268]: Error: dns service error: unknown Feb 24 20:15:30 bathroommusic volumio[1268]: at MDNSService.on_resolver_done (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:19:30) Feb 24 20:15:30 bathroommusic volumio[1268]: at MDNSService.self.watcher.callback (/volumio/node_modules/mdns/lib/mdns_service.js:18:40) { Feb 24 20:15:30 bathroommusic volumio[1268]: errorCode: -65537 Feb 24 20:15:30 bathroommusic volumio[1268]: } Feb 24 20:15:30 bathroommusic volumio[1268]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 20:15:31 bathroommusic sudo[8624]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-24 20:14' Feb 24 20:15:31 bathroommusic sudo[8624]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"