Apr 15 10:32:00 volumio go-librespot[1849]: time="2026-04-15T10:32:00+09:00" level=trace msg="received accesspoint ping" Apr 15 10:32:00 volumio go-librespot[1849]: time="2026-04-15T10:32:00+09:00" level=trace msg="received accesspoint pong ack" Apr 15 10:32:00 volumio go-librespot[1849]: time="2026-04-15T10:32:00+09:00" level=trace msg="sent dealer ping" Apr 15 10:32:00 volumio go-librespot[1849]: time="2026-04-15T10:32:00+09:00" level=trace msg="received dealer pong" Apr 15 10:32:26 volumio volumio[1395]: info: Airplay started streaming, receiving metadatas Apr 15 10:32:26 volumio volumio[1395]: info: CorePlayQueue::getTrack 0 Apr 15 10:32:26 volumio volumio[1395]: info: CoreCommandRouter::volumioStop Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::stop Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 15 10:32:26 volumio volumio[1395]: info: Airplay started streaming, receiving metadatas Apr 15 10:32:26 volumio volumio[1395]: info: CorePlayQueue::getTrack 0 Apr 15 10:32:26 volumio volumio[1395]: info: CoreCommandRouter::volumioStop Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::stop Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 15 10:32:26 volumio volumio[1395]: info: Airplay started streaming, receiving metadatas Apr 15 10:32:26 volumio volumio[1395]: info: CorePlayQueue::getTrack 0 Apr 15 10:32:26 volumio volumio[1395]: info: CoreCommandRouter::volumioStop Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::stop Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 15 10:32:26 volumio volumio[1395]: info: Airplay started streaming, receiving metadatas Apr 15 10:32:26 volumio volumio[1395]: info: CorePlayQueue::getTrack 0 Apr 15 10:32:26 volumio volumio[1395]: info: CoreCommandRouter::volumioStop Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::stop Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 15 10:32:26 volumio shairport-sync[3303]: % Total Apr 15 10:32:26 volumio shairport-sync[3302]: % Total % Received % Xferd Average Speed Time Time Time Current Apr 15 10:32:26 volumio shairport-sync[3302]: Dload Upload Total Spent Left Speed Apr 15 10:32:26 volumio volumio[1395]: info: Apr 15 10:32:26 volumio volumio[1395]: ---------------------------- Client requests Start Airplay PlaybackRoutine Apr 15 10:32:26 volumio volumio[1395]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startAirplayPlayback Apr 15 10:32:26 volumio volumio[1395]: info: Airplay playback start Apr 15 10:32:26 volumio volumio[1395]: info: CorePlayQueue::getTrack 0 Apr 15 10:32:26 volumio volumio[1395]: info: CoreCommandRouter::volumioStop Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::stop Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 15 10:32:26 volumio shairport-sync[3302]: [79B blob data] Apr 15 10:32:26 volumio shairport-sync[3303]: % Received % Xferd Average Speed Time Time Time Current Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 1 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 0 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 0 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 6 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 4 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 1 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 0 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 0 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 6 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 4 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 0 Apr 15 10:32:26 volumio volumio[1395]: info: Apr 15 10:32:26 volumio volumio[1395]: ---------------------------- Client requests AirplayActive Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio volumio[1395]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , setAirplayActive Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: D Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: l Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: o Apr 15 10:32:26 volumio shairport-sync[3302]: 0 Apr 15 10:32:26 volumio shairport-sync[3303]: ad U Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: p Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: l Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: o Apr 15 10:32:26 volumio shairport-sync[3302]: 8 Apr 15 10:32:26 volumio shairport-sync[3303]: a Apr 15 10:32:26 volumio shairport-sync[3302]: 674 Apr 15 10:32:26 volumio shairport-sync[3303]: d Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: T Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: o Apr 15 10:32:26 volumio shairport-sync[3302]: 0 Apr 15 10:32:26 volumio shairport-sync[3303]: t Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: a Apr 15 10:32:26 volumio shairport-sync[3302]: - Apr 15 10:32:26 volumio shairport-sync[3303]: l S Apr 15 10:32:26 volumio shairport-sync[3302]: - Apr 15 10:32:26 volumio shairport-sync[3303]: pen Apr 15 10:32:26 volumio shairport-sync[3302]: :--: Apr 15 10:32:26 volumio shairport-sync[3303]: t Apr 15 10:32:26 volumio shairport-sync[3302]: - Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: - Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: - Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: - Apr 15 10:32:26 volumio shairport-sync[3303]: L Apr 15 10:32:26 volumio shairport-sync[3302]: : Apr 15 10:32:26 volumio shairport-sync[3303]: e Apr 15 10:32:26 volumio shairport-sync[3302]: - Apr 15 10:32:26 volumio shairport-sync[3303]: f Apr 15 10:32:26 volumio shairport-sync[3302]: - Apr 15 10:32:26 volumio shairport-sync[3303]: t Apr 15 10:32:26 volumio shairport-sync[3302]: : Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: - Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: - Apr 15 10:32:26 volumio shairport-sync[3303]: Speed Apr 15 10:32:26 volumio shairport-sync[3302]: --: Apr 15 10:32:26 volumio shairport-sync[3302]: --:-- 9 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 1 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 4 Apr 15 10:32:26 volumio shairport-sync[3303]: Apr 15 10:32:26 volumio shairport-sync[3302]: 2 Apr 15 10:32:26 volumio shairport-sync[3303]: 0 Apr 15 10:32:26 volumio shairport-sync[3303]: 0 0 Apr 15 10:32:26 volumio shairport-sync[3302]: {"time":1776216746126,"response":"startAirplayPlayback Success"} Apr 15 10:32:26 volumio shairport-sync[3303]: [138B blob data] Apr 15 10:32:26 volumio volumio[1395]: info: Updating volume from AirPlay: -18; 40% Apr 15 10:32:26 volumio volumio[1395]: info: VolumeController::SetAlsaVolume40 Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:26 volumio volumio[1395]: info: CorePlayQueue::getTrack 0 Apr 15 10:32:26 volumio volumio[1395]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 10:32:26 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:26 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:26.183+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_STOPPED positionMs=63766 volume=100 Apr 15 10:32:26 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:26.183+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id=spotify:track:2ezqQeBiC72gwMJoO4w1hA title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:26 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status stop Apr 15 10:32:26 volumio sudo[3325]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Apr 15 10:32:26 volumio sudo[3325]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:26 volumio sudo[3325]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:26 volumio volumio[1395]: info: peppymeterbasic Daemon Stop Apr 15 10:32:26 volumio volumio[1395]: info: Updating volume from AirPlay: -20; 33% Apr 15 10:32:26 volumio volumio[1395]: info: VolumeController::SetAlsaVolume33 Apr 15 10:32:26 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:26 volumio volumio[1395]: info: CorePlayQueue::getTrack 0 Apr 15 10:32:26 volumio volumio[1395]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 10:32:26 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:26 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:26.403+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_STOPPED positionMs=63988 volume=100 Apr 15 10:32:26 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:26.403+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id=spotify:track:2ezqQeBiC72gwMJoO4w1hA title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:26 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status stop Apr 15 10:32:26 volumio sudo[3328]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Apr 15 10:32:26 volumio sudo[3328]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:26 volumio sudo[3328]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:26 volumio volumio[1395]: info: peppymeterbasic Daemon Stop Apr 15 10:32:27 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:27 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:27 volumio volumio[1395]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 10:32:27 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:27 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:27.128+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs=0 volume=100 Apr 15 10:32:27 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:27.129+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title= Apr 15 10:32:27 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:27 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:27 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:27 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:27 volumio sudo[3333]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:27 volumio sudo[3333]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:27 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:27.162+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs=0 volume=100 Apr 15 10:32:27 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:27.162+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title= Apr 15 10:32:27 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:27 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:27 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:27 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:27.170+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs=0 volume=100 Apr 15 10:32:27 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:27.170+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title= Apr 15 10:32:27 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:27 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:27 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:27 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:27.177+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs=0 volume=100 Apr 15 10:32:27 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:27.177+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title= Apr 15 10:32:27 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:27 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:27 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:27 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:27.197+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs=0 volume=100 Apr 15 10:32:27 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:27.197+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title= Apr 15 10:32:27 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:27 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:27 volumio systemd[1]: Started peppymeterbasic.service - peppymeterbasic Daemon. Apr 15 10:32:27 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:27 volumio sudo[3333]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:27 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:27 volumio sudo[3339]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:27 volumio sudo[3339]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:27 volumio sudo[3343]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:27 volumio sudo[3337]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:27 volumio sudo[3337]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:27 volumio sudo[3343]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:27 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=info msg="playback was transferred to iPad" Apr 15 10:32:27 volumio sudo[3346]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:27 volumio sudo[3346]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:27 volumio volumio[1395]: info: touch_display: Setting screensaver timeout to 0 seconds. Apr 15 10:32:27 volumio sudo[3339]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:27 volumio sudo[3337]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:27 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:27 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 15 10:32:27 volumio sudo[3343]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1190" Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 492" Apr 15 10:32:27 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:27 volumio sudo[3346]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:27 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=debug msg="put connect state inactive" Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=trace msg="emitting websocket event: inactive" Apr 15 10:32:27 volumio volumio[1395]: SPOTIFY: received: {"type":"inactive","data":null} Apr 15 10:32:27 volumio volumio[1395]: error: Failed to decode event: inactive Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=debug msg="dealer connection closed" Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=debug msg="dealer recv loop stopped" Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=debug msg="obtained new client token: AACNoNcm+OL6XS7ozWL6ySRGhVAePJDh5q4DEINTSq5xBo6Dqow5RDQ8BudK1nHSQFbTrCesPcysAh0eXBjkUhkV31SE4u9yXyoSrlMdDx+D6cJK2dDQp7chBEwtJqGdmT7eeO64zbPuzNv0xgIgsIvBl7oOqJvMBocgK5BZSX80nFjJnQevDmCUdzcnzqqIQQ/lHT/p82uXG3iijKtHHAlJAfMsApdzRVXlgVIOaQQknajvM+LkVpw=" Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=debug msg="completed keyexchange" Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=debug msg="completed challenge" Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=info msg="authenticated AP" username="31************************4y" Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=info msg="authenticated Login5" username="31************************4y" Apr 15 10:32:27 volumio go-librespot[1849]: time="2026-04-15T10:32:27+09:00" level=debug msg="restored session after logout" username="31************************4y" Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=debug msg="dealer connection opened" Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=trace msg="starting accesspoint recv loop" Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=trace msg="starting dealer recv loop" Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=trace msg="received accesspoint ping" Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=debug msg="received connection id: ZDhjZmZlNjMtZjBm...NzVGNUI2QjdENQ==" Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.132+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs= volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.132+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title= Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.132+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs= volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.133+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title= Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.133+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs= volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.133+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs= volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.133+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title= Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.133+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title= Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio sudo[3359]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3359]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio sudo[3361]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3361]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio sudo[3359]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=trace msg="received accesspoint pong ack" Apr 15 10:32:28 volumio sudo[3365]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3366]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3366]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio sudo[3365]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio sudo[3361]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=debug msg="put connect state because NEW_DEVICE" Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=debug msg="update volume requested to 65535/65535" Apr 15 10:32:28 volumio sudo[3365]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio sudo[3366]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.256+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs= volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.256+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.256+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs= volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.257+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.257+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs= volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.257+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.258+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs= volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.258+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio sudo[3372]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3372]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio sudo[3374]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3375]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3374]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio sudo[3375]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio sudo[3378]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3378]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.320+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs= volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.321+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.321+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs= volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.321+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.322+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs= volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.322+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.323+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs= volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.323+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::servicePushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio sudo[3374]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio sudo[3378]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio sudo[3372]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio sudo[3375]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.347+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs=1000 volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.348+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs=1000 volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.348+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.348+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.348+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs=1000 volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.349+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.349+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs=1000 volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.349+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Apr 15 10:32:28 volumio go-librespot[1849]: time="2026-04-15T10:32:28+09:00" level=trace msg="emitting websocket event: volume" Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio sudo[3384]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3384]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio sudo[3386]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3386]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio sudo[3388]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio sudo[3388]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio sudo[3392]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio sudo[3396]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3396]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio sudo[3398]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3398]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio volumio[1395]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Apr 15 10:32:28 volumio volumio[1395]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Apr 15 10:32:28 volumio volumio[1395]: info: Setting Volumio Volume from Spotify: 100 Apr 15 10:32:28 volumio volumio[1395]: info: VolumeController::SetAlsaVolume100 Apr 15 10:32:28 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:28 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:28 volumio sudo[3386]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.439+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs=1000 volume=100 Apr 15 10:32:28 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:28.440+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:28 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:28 volumio sudo[3388]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio sudo[3403]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3384]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio sudo[3404]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio sudo[3404]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio sudo[3392]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio sudo[3403]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio sudo[3406]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:28 volumio sudo[3406]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio sudo[3404]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio sudo[3403]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio sudo[3398]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio sudo[3406]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio sudo[3396]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:28 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:41 volumio volumio[1395]: info: Updating volume from AirPlay: 0; 100% Apr 15 10:32:41 volumio volumio[1395]: info: VolumeController::SetAlsaVolume100 Apr 15 10:32:41 volumio volumio[1395]: info: CoreStateMachine::pushState Apr 15 10:32:41 volumio volumio[1395]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 15 10:32:41 volumio volumio[1395]: info: CoreCommandRouter::volumioPushState Apr 15 10:32:41 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:41.199+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" state=STATUS_PLAYING positionMs=14000 volume=100 Apr 15 10:32:41 volumio volumio5-onboarding[2233]: time=2026-04-15T10:32:41.199+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.7:49725,00:00:00:00:00:00%01 @ 0x2136810" id= title="Every Time I Close My Eyes (with Kenny G)" Apr 15 10:32:41 volumio volumio[1395]: info: PeppyMeterBasic ---peppymeterbasic status play Apr 15 10:32:41 volumio sudo[3426]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Apr 15 10:32:41 volumio sudo[3426]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 15 10:32:41 volumio sudo[3426]: pam_unix(sudo:session): session closed for user root Apr 15 10:32:41 volumio volumio[1395]: info: peppymeterbasic Daemon Started Apr 15 10:32:51 volumio systemd[1]: peppymeterbasic.service: Deactivated successfully. Apr 15 10:32:51 volumio systemd[1]: peppymeterbasic.service: Consumed 9.109s CPU time. Apr 15 10:32:58 volumio go-librespot[1849]: time="2026-04-15T10:32:58+09:00" level=trace msg="sent dealer ping" Apr 15 10:32:58 volumio go-librespot[1849]: time="2026-04-15T10:32:58+09:00" level=trace msg="received dealer pong" Apr 15 10:33:28 volumio go-librespot[1849]: time="2026-04-15T10:33:28+09:00" level=trace msg="sent dealer ping" Apr 15 10:33:28 volumio go-librespot[1849]: time="2026-04-15T10:33:28+09:00" level=trace msg="received dealer pong" Apr 15 10:33:48 volumio volumio[1395]: info: [1776216828320] [80s80s] Pushing the next song state Duran Duran - A View to a Kill and getting next track. Apr 15 10:33:48 volumio volumio[1395]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 15 10:33:48 volumio volumio[1395]: TypeError: Cannot set properties of undefined (setting 'name') Apr 15 10:33:48 volumio volumio[1395]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Apr 15 10:33:48 volumio volumio[1395]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Apr 15 10:33:48 volumio volumio[1395]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Apr 15 10:33:48 volumio volumio[1395]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Apr 15 10:33:48 volumio volumio[1395]: at process.processImmediate (node:internal/timers:478:21) Apr 15 10:33:48 volumio volumio[1395]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 15 10:33:48 volumio sudo[3546]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-04-15 10:32' Apr 15 10:33:48 volumio sudo[3546]: 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="dc61260dec5515dafd2b634881860b4c46c919ff" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026" VOLUMIO_VERSION="4.103" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"