-- Logs begin at Thu 2025-05-29 01:36:38 CDT, end at Thu 2025-05-29 02:55:54 CDT. --
May 29 01:54:00 volumio go-librespot[1678]: time="2025-05-29T01:54:00-05:00" level=trace msg="received dealer pong"
May 29 01:54:29 volumio go-librespot[1678]: time="2025-05-29T01:54:29-05:00" level=trace msg="sent dealer ping"
May 29 01:54:30 volumio go-librespot[1678]: time="2025-05-29T01:54:30-05:00" level=trace msg="received dealer pong"
May 29 01:54:59 volumio go-librespot[1678]: time="2025-05-29T01:54:59-05:00" level=trace msg="received accesspoint ping"
May 29 01:54:59 volumio go-librespot[1678]: time="2025-05-29T01:54:59-05:00" level=trace msg="received accesspoint pong ack"
May 29 01:54:59 volumio go-librespot[1678]: time="2025-05-29T01:54:59-05:00" level=trace msg="sent dealer ping"
May 29 01:54:59 volumio go-librespot[1678]: time="2025-05-29T01:54:59-05:00" level=trace msg="received dealer pong"
May 29 01:55:29 volumio go-librespot[1678]: time="2025-05-29T01:55:29-05:00" level=trace msg="sent dealer ping"
May 29 01:55:32 volumio go-librespot[1678]: time="2025-05-29T01:55:32-05:00" level=trace msg="received dealer pong"
May 29 01:55:59 volumio go-librespot[1678]: time="2025-05-29T01:55:59-05:00" level=trace msg="sent dealer ping"
May 29 01:56:00 volumio go-librespot[1678]: time="2025-05-29T01:56:00-05:00" level=trace msg="received dealer pong"
May 29 01:56:26 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:26 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 01:56:26 volumio volumio[1159]: info: Prefetching next song
May 29 01:56:26 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/8. Be Thou My Vision.flac"
May 29 01:56:26 volumio volumio[1159]: info:
May 29 01:56:26 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 01:56:26 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 01:56:26 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/8. Be Thou My Vision.flac" took 1 milliseconds
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 01:56:26 volumio volumio[1159]: info:
May 29 01:56:26 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 01:56:26 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 01:56:26 volumio volumio[1159]: info:
May 29 01:56:26 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 01:56:26 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 01:56:26 volumio volumio[1159]: info:
May 29 01:56:26 volumio volumio[1159]: ---------------------------- MPD announces state update: options
May 29 01:56:26 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 01:56:26 volumio volumio[1159]: info: sendMpdCommand consume 1 took 1 milliseconds
May 29 01:56:26 volumio volumio[1159]: info: ControllerMpd::getState
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 01:56:26 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 01:56:26 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 01:56:26 volumio volumio[1159]: info:
May 29 01:56:26 volumio volumio[1159]: ---------------------------- MPD announces state update: options
May 29 01:56:26 volumio volumio[1159]: info: ControllerMpd::getState
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 01:56:26 volumio volumio[1159]: info:
May 29 01:56:26 volumio volumio[1159]: ---------------------------- MPD announces state update: options
May 29 01:56:26 volumio volumio[1159]: info: ControllerMpd::getState
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 01:56:26 volumio volumio[1159]: info: sendMpdCommand status took 0 milliseconds
May 29 01:56:26 volumio volumio[1159]: info: sendMpdCommand status took 0 milliseconds
May 29 01:56:26 volumio volumio[1159]: info: sendMpdCommand status took 0 milliseconds
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 01:56:26 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 01:56:26 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 01:56:26 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 01:56:26 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 01:56:26 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 01:56:26 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 01:56:26 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:26 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":239736,"duration":243,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1062 Kbps","isStreaming":false,"title":"Speak Softly Love","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/1. Speak Softly Love.flac","trackType":"flac"}
May 29 01:56:26 volumio volumio[1159]: verbose: CURRENT POSITION 0
May 29 01:56:26 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 01:56:26 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 01:56:26 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 01:56:26 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:26 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:26 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 01:56:26 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:26 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:26 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:26 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:26 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 01:56:26 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 01:56:26 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:26 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":239736,"duration":243,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1062 Kbps","isStreaming":false,"title":"Speak Softly Love","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/1. Speak Softly Love.flac","trackType":"flac"}
May 29 01:56:26 volumio volumio[1159]: verbose: CURRENT POSITION 0
May 29 01:56:26 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 01:56:26 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 01:56:26 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 01:56:26 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:26 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:26 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:26 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:26 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:26 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:26 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 01:56:26 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 01:56:26 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:26 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":239736,"duration":243,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1062 Kbps","isStreaming":false,"title":"Speak Softly Love","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/1. Speak Softly Love.flac","trackType":"flac"}
May 29 01:56:26 volumio volumio[1159]: verbose: CURRENT POSITION 0
May 29 01:56:26 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 01:56:26 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 01:56:26 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 01:56:26 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:26 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:26 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:26 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:26 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:26 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:26 volumio volumio[1159]: info: ------------------------------ 18ms
May 29 01:56:26 volumio volumio[1159]: info: ------------------------------ 17ms
May 29 01:56:26 volumio volumio[1159]: info: ------------------------------ 17ms
May 29 01:56:26 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:26 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:26 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:26 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:26 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:26 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:29 volumio go-librespot[1678]: time="2025-05-29T01:56:29-05:00" level=trace msg="sent dealer ping"
May 29 01:56:30 volumio volumio[1159]: info:
May 29 01:56:30 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 01:56:30 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 01:56:30 volumio volumio[1159]: info:
May 29 01:56:30 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 01:56:30 volumio volumio[1159]: info: ControllerMpd::getState
May 29 01:56:30 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 01:56:30 volumio volumio[1159]: info:
May 29 01:56:30 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 01:56:30 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 01:56:30 volumio volumio[1159]: info:
May 29 01:56:30 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 01:56:30 volumio volumio[1159]: info: ControllerMpd::getState
May 29 01:56:30 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 01:56:30 volumio volumio[1159]: info:
May 29 01:56:30 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 01:56:30 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 01:56:30 volumio volumio[1159]: info:
May 29 01:56:30 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 01:56:30 volumio volumio[1159]: info: ControllerMpd::getState
May 29 01:56:30 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 01:56:30 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 01:56:30 volumio volumio[1159]: info: sendMpdCommand status took 2 milliseconds
May 29 01:56:30 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 01:56:30 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 01:56:30 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 01:56:30 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 01:56:30 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 01:56:30 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 01:56:30 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 01:56:30 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 01:56:30 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 01:56:30 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 01:56:30 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 01:56:30 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 01:56:30 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 01:56:30 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 01:56:30 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 01:56:30 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 01:56:30 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 01:56:30 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 01:56:30 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:30 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":83,"duration":254,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1247 Kbps","isStreaming":false,"title":"Be Thou My Vision","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/8. Be Thou My Vision.flac","trackType":"flac"}
May 29 01:56:30 volumio volumio[1159]: verbose: CURRENT POSITION 0
May 29 01:56:30 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 01:56:30 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 01:56:30 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 01:56:30 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:30 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:30 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 01:56:30 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:30 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:30 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:30 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:30 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 01:56:30 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 01:56:30 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:30 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":83,"duration":254,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1247 Kbps","isStreaming":false,"title":"Be Thou My Vision","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/8. Be Thou My Vision.flac","trackType":"flac"}
May 29 01:56:30 volumio volumio[1159]: verbose: CURRENT POSITION 0
May 29 01:56:30 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 01:56:30 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 01:56:30 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 01:56:30 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:30 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:30 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:30 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:30 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:30 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:30 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 01:56:30 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 01:56:30 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:30 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":83,"duration":254,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1247 Kbps","isStreaming":false,"title":"Be Thou My Vision","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/8. Be Thou My Vision.flac","trackType":"flac"}
May 29 01:56:30 volumio volumio[1159]: verbose: CURRENT POSITION 0
May 29 01:56:30 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 01:56:30 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 01:56:30 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 01:56:30 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:30 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:30 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:30 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:30 volumio volumio[1159]: info: CorePlayQueue::getTrack 0
May 29 01:56:30 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:30 volumio volumio[1159]: info: ------------------------------ 15ms
May 29 01:56:30 volumio volumio[1159]: info: ------------------------------ 14ms
May 29 01:56:30 volumio volumio[1159]: info: ------------------------------ 14ms
May 29 01:56:30 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:30 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:30 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:30 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:30 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:30 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:31 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 01:56:31 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 01:56:31 volumio go-librespot[1678]: time="2025-05-29T01:56:31-05:00" level=trace msg="received dealer pong"
May 29 01:56:31 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 01:56:31 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 01:56:31 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 01:56:31 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 01:56:31 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 01:56:59 volumio go-librespot[1678]: time="2025-05-29T01:56:59-05:00" level=trace msg="received accesspoint ping"
May 29 01:56:59 volumio go-librespot[1678]: time="2025-05-29T01:56:59-05:00" level=error msg="did not receive last pong ack from accesspoint, 120s passed"
May 29 01:56:59 volumio go-librespot[1678]: time="2025-05-29T01:56:59-05:00" level=trace msg="sent dealer ping"
May 29 01:56:59 volumio go-librespot[1678]: time="2025-05-29T01:56:59-05:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.1.65:51946->104.154.127.247:4070: use of closed network connection"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=trace msg="received dealer pong"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=debug msg="connected to ap-guc3.spotify.com:443"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=debug msg="completed keyexchange"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=debug msg="completed challenge"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=info msg="authenticated AP as txqeumjpo0e2sqzbg8ea9kho7"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=debug msg="re-established accesspoint connection"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=trace msg="received accesspoint ping"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481"
May 29 01:57:00 volumio go-librespot[1678]: time="2025-05-29T01:57:00-05:00" level=trace msg="received accesspoint pong ack"
May 29 01:57:29 volumio go-librespot[1678]: time="2025-05-29T01:57:29-05:00" level=trace msg="sent dealer ping"
May 29 01:57:31 volumio go-librespot[1678]: time="2025-05-29T01:57:31-05:00" level=trace msg="received dealer pong"
May 29 01:57:59 volumio go-librespot[1678]: time="2025-05-29T01:57:59-05:00" level=trace msg="sent dealer ping"
May 29 01:57:59 volumio go-librespot[1678]: time="2025-05-29T01:57:59-05:00" level=trace msg="received dealer pong"
May 29 01:58:29 volumio go-librespot[1678]: time="2025-05-29T01:58:29-05:00" level=trace msg="sent dealer ping"
May 29 01:58:31 volumio go-librespot[1678]: time="2025-05-29T01:58:31-05:00" level=trace msg="received dealer pong"
May 29 01:58:59 volumio go-librespot[1678]: time="2025-05-29T01:58:59-05:00" level=trace msg="sent dealer ping"
May 29 01:59:00 volumio go-librespot[1678]: time="2025-05-29T01:59:00-05:00" level=trace msg="received dealer pong"
May 29 01:59:00 volumio go-librespot[1678]: time="2025-05-29T01:59:00-05:00" level=trace msg="received accesspoint ping"
May 29 01:59:01 volumio go-librespot[1678]: time="2025-05-29T01:59:01-05:00" level=trace msg="received accesspoint pong ack"
May 29 01:59:29 volumio go-librespot[1678]: time="2025-05-29T01:59:29-05:00" level=trace msg="sent dealer ping"
May 29 01:59:31 volumio go-librespot[1678]: time="2025-05-29T01:59:31-05:00" level=trace msg="received dealer pong"
May 29 01:59:59 volumio go-librespot[1678]: time="2025-05-29T01:59:59-05:00" level=trace msg="sent dealer ping"
May 29 01:59:59 volumio go-librespot[1678]: time="2025-05-29T01:59:59-05:00" level=trace msg="received dealer pong"
May 29 02:00:29 volumio go-librespot[1678]: time="2025-05-29T02:00:29-05:00" level=trace msg="sent dealer ping"
May 29 02:00:31 volumio go-librespot[1678]: time="2025-05-29T02:00:31-05:00" level=trace msg="received dealer pong"
May 29 02:00:40 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 02:00:40 volumio volumio[1159]: info: CorePlayQueue::getTrack 21
May 29 02:00:40 volumio volumio[1159]: info: Prefetching next song
May 29 02:00:40 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:00:40 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/5. I Cry.flac"
May 29 02:00:40 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/5. I Cry.flac" took 0 milliseconds
May 29 02:00:40 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:00:40 volumio volumio[1159]: info:
May 29 02:00:40 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:00:40 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:00:40 volumio volumio[1159]: info: sendMpdCommand consume 1 took 1 milliseconds
May 29 02:00:40 volumio volumio[1159]: info:
May 29 02:00:40 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:00:40 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:00:40 volumio volumio[1159]: info:
May 29 02:00:40 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:00:40 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:00:40 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:00:40 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:00:40 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:00:44 volumio volumio[1159]: info:
May 29 02:00:44 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:00:44 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:00:44 volumio volumio[1159]: info:
May 29 02:00:44 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:00:44 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:00:44 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:00:44 volumio volumio[1159]: info:
May 29 02:00:44 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:00:44 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:00:44 volumio volumio[1159]: info:
May 29 02:00:44 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:00:44 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:00:44 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:00:44 volumio volumio[1159]: info:
May 29 02:00:44 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:00:44 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:00:44 volumio volumio[1159]: info:
May 29 02:00:44 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:00:44 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:00:44 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:00:44 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:00:44 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:00:44 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:00:44 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:00:44 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:00:44 volumio volumio[1159]: info: sendMpdCommand status took 0 milliseconds
May 29 02:00:44 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:00:44 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:00:44 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:00:44 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:00:44 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:00:44 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:00:44 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 2 milliseconds
May 29 02:00:44 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:00:44 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:00:44 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:00:44 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 02:00:44 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":104,"duration":246,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1 Kbps","isStreaming":false,"title":"I Cry","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/5. I Cry.flac","trackType":"flac"}
May 29 02:00:44 volumio volumio[1159]: verbose: CURRENT POSITION 11
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:00:44 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:00:44 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 02:00:44 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:00:44 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:00:44 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 02:00:44 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:00:44 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:00:44 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:00:44 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 02:00:44 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":104,"duration":246,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1 Kbps","isStreaming":false,"title":"I Cry","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/5. I Cry.flac","trackType":"flac"}
May 29 02:00:44 volumio volumio[1159]: verbose: CURRENT POSITION 11
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:00:44 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:00:44 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 02:00:44 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:00:44 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 02:00:44 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:00:44 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:00:44 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:00:44 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 02:00:44 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":104,"duration":246,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1 Kbps","isStreaming":false,"title":"I Cry","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/5. I Cry.flac","trackType":"flac"}
May 29 02:00:44 volumio volumio[1159]: verbose: CURRENT POSITION 11
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:00:44 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:00:44 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 02:00:44 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:00:44 volumio volumio[1159]: info: CorePlayQueue::getTrack 11
May 29 02:00:44 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:00:44 volumio volumio[1159]: info: ------------------------------ 23ms
May 29 02:00:44 volumio volumio[1159]: info: ------------------------------ 23ms
May 29 02:00:44 volumio volumio[1159]: info: ------------------------------ 22ms
May 29 02:00:44 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:00:44 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:00:44 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:00:44 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:00:44 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:00:44 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:00:44 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:00:44 volumio volumio[1159]: info: CorePlayQueue::getTrack 21
May 29 02:00:45 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:00:45 volumio volumio[1159]: info: CorePlayQueue::getTrack 21
May 29 02:00:45 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:00:45 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:00:45 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:00:59 volumio go-librespot[1678]: time="2025-05-29T02:00:59-05:00" level=trace msg="sent dealer ping"
May 29 02:00:59 volumio go-librespot[1678]: time="2025-05-29T02:00:59-05:00" level=trace msg="received dealer pong"
May 29 02:01:00 volumio go-librespot[1678]: time="2025-05-29T02:01:00-05:00" level=trace msg="received accesspoint ping"
May 29 02:01:00 volumio go-librespot[1678]: time="2025-05-29T02:01:00-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:01:29 volumio go-librespot[1678]: time="2025-05-29T02:01:29-05:00" level=trace msg="sent dealer ping"
May 29 02:01:31 volumio go-librespot[1678]: time="2025-05-29T02:01:31-05:00" level=trace msg="received dealer pong"
May 29 02:01:59 volumio go-librespot[1678]: time="2025-05-29T02:01:59-05:00" level=trace msg="sent dealer ping"
May 29 02:01:59 volumio go-librespot[1678]: time="2025-05-29T02:01:59-05:00" level=trace msg="received dealer pong"
May 29 02:02:29 volumio go-librespot[1678]: time="2025-05-29T02:02:29-05:00" level=trace msg="sent dealer ping"
May 29 02:02:31 volumio go-librespot[1678]: time="2025-05-29T02:02:31-05:00" level=trace msg="received dealer pong"
May 29 02:02:59 volumio go-librespot[1678]: time="2025-05-29T02:02:59-05:00" level=trace msg="sent dealer ping"
May 29 02:02:59 volumio go-librespot[1678]: time="2025-05-29T02:02:59-05:00" level=trace msg="received dealer pong"
May 29 02:03:00 volumio go-librespot[1678]: time="2025-05-29T02:03:00-05:00" level=trace msg="received accesspoint ping"
May 29 02:03:00 volumio go-librespot[1678]: time="2025-05-29T02:03:00-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:03:29 volumio go-librespot[1678]: time="2025-05-29T02:03:29-05:00" level=trace msg="sent dealer ping"
May 29 02:03:31 volumio go-librespot[1678]: time="2025-05-29T02:03:31-05:00" level=trace msg="received dealer pong"
May 29 02:03:59 volumio go-librespot[1678]: time="2025-05-29T02:03:59-05:00" level=trace msg="sent dealer ping"
May 29 02:03:59 volumio go-librespot[1678]: time="2025-05-29T02:03:59-05:00" level=trace msg="received dealer pong"
May 29 02:04:29 volumio go-librespot[1678]: time="2025-05-29T02:04:29-05:00" level=trace msg="sent dealer ping"
May 29 02:04:30 volumio go-librespot[1678]: time="2025-05-29T02:04:30-05:00" level=trace msg="received dealer pong"
May 29 02:04:45 volumio volumio[1159]: info: CorePlayQueue::getTrack 21
May 29 02:04:45 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:04:45 volumio volumio[1159]: info: Prefetching next song
May 29 02:04:45 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:04:45 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/13. The Sound Of Silence.flac"
May 29 02:04:45 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/13. The Sound Of Silence.flac" took 1 milliseconds
May 29 02:04:45 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:04:45 volumio volumio[1159]: info:
May 29 02:04:45 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:04:45 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:04:45 volumio volumio[1159]: info: sendMpdCommand consume 1 took 0 milliseconds
May 29 02:04:45 volumio volumio[1159]: info:
May 29 02:04:45 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:04:45 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:04:45 volumio volumio[1159]: info:
May 29 02:04:45 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:04:45 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:04:45 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:04:45 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:04:45 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:04:50 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:04:50 volumio volumio[1159]: info:
May 29 02:04:50 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:04:50 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:04:50 volumio volumio[1159]: info:
May 29 02:04:50 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:04:50 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:04:50 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:04:50 volumio volumio[1159]: info:
May 29 02:04:50 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:04:50 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:04:50 volumio volumio[1159]: info:
May 29 02:04:50 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:04:50 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:04:50 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:04:50 volumio volumio[1159]: info:
May 29 02:04:50 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:04:50 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:04:50 volumio volumio[1159]: info:
May 29 02:04:50 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:04:50 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:04:50 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:04:50 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:04:50 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:04:50 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:04:50 volumio volumio[1159]: info: sendMpdCommand status took 0 milliseconds
May 29 02:04:50 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:04:50 volumio volumio[1159]: info: sendMpdCommand status took 0 milliseconds
May 29 02:04:50 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:04:50 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:04:50 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:04:50 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:04:50 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:04:50 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:04:50 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:04:50 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:04:50 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:04:50 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:04:50 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:04:50 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:04:50 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:04:50 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:04:50 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:04:50 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":41,"duration":214,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1419 Kbps","isStreaming":false,"title":"The Sound Of Silence","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/13. The Sound Of Silence.flac","trackType":"flac"}
May 29 02:04:50 volumio volumio[1159]: verbose: CURRENT POSITION 17
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:04:50 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:04:50 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:04:50 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:04:50 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:04:50 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:04:50 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:04:50 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:04:50 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:04:50 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:04:50 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":41,"duration":214,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1419 Kbps","isStreaming":false,"title":"The Sound Of Silence","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/13. The Sound Of Silence.flac","trackType":"flac"}
May 29 02:04:50 volumio volumio[1159]: verbose: CURRENT POSITION 17
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:04:50 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:04:50 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:04:50 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:04:50 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:04:50 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:04:50 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:04:50 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:04:50 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:04:50 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":41,"duration":214,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1419 Kbps","isStreaming":false,"title":"The Sound Of Silence","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/13. The Sound Of Silence.flac","trackType":"flac"}
May 29 02:04:50 volumio volumio[1159]: verbose: CURRENT POSITION 17
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:04:50 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:04:50 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:04:50 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:04:50 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:04:50 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:04:50 volumio volumio[1159]: info: ------------------------------ 22ms
May 29 02:04:50 volumio volumio[1159]: info: ------------------------------ 22ms
May 29 02:04:50 volumio volumio[1159]: info: ------------------------------ 21ms
May 29 02:04:50 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:04:50 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:04:50 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:04:50 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:04:50 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:04:50 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:04:50 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:04:50 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:04:50 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:04:50 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:04:50 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:04:59 volumio go-librespot[1678]: time="2025-05-29T02:04:59-05:00" level=trace msg="sent dealer ping"
May 29 02:04:59 volumio go-librespot[1678]: time="2025-05-29T02:04:59-05:00" level=trace msg="received dealer pong"
May 29 02:05:00 volumio go-librespot[1678]: time="2025-05-29T02:05:00-05:00" level=trace msg="received accesspoint ping"
May 29 02:05:00 volumio go-librespot[1678]: time="2025-05-29T02:05:00-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:05:29 volumio go-librespot[1678]: time="2025-05-29T02:05:29-05:00" level=trace msg="sent dealer ping"
May 29 02:05:31 volumio go-librespot[1678]: time="2025-05-29T02:05:31-05:00" level=trace msg="received dealer pong"
May 29 02:05:59 volumio go-librespot[1678]: time="2025-05-29T02:05:59-05:00" level=trace msg="sent dealer ping"
May 29 02:05:59 volumio go-librespot[1678]: time="2025-05-29T02:05:59-05:00" level=trace msg="received dealer pong"
May 29 02:06:29 volumio go-librespot[1678]: time="2025-05-29T02:06:29-05:00" level=trace msg="sent dealer ping"
May 29 02:06:31 volumio go-librespot[1678]: time="2025-05-29T02:06:31-05:00" level=trace msg="received dealer pong"
May 29 02:06:59 volumio go-librespot[1678]: time="2025-05-29T02:06:59-05:00" level=trace msg="sent dealer ping"
May 29 02:06:59 volumio go-librespot[1678]: time="2025-05-29T02:06:59-05:00" level=trace msg="received dealer pong"
May 29 02:07:00 volumio go-librespot[1678]: time="2025-05-29T02:07:00-05:00" level=trace msg="received accesspoint ping"
May 29 02:07:00 volumio go-librespot[1678]: time="2025-05-29T02:07:00-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:07:29 volumio go-librespot[1678]: time="2025-05-29T02:07:29-05:00" level=trace msg="sent dealer ping"
May 29 02:07:30 volumio go-librespot[1678]: time="2025-05-29T02:07:30-05:00" level=trace msg="received dealer pong"
May 29 02:07:59 volumio go-librespot[1678]: time="2025-05-29T02:07:59-05:00" level=trace msg="sent dealer ping"
May 29 02:07:59 volumio go-librespot[1678]: time="2025-05-29T02:07:59-05:00" level=trace msg="received dealer pong"
May 29 02:08:19 volumio volumio[1159]: info: CorePlayQueue::getTrack 17
May 29 02:08:19 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:08:19 volumio volumio[1159]: info: Prefetching next song
May 29 02:08:19 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:08:19 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/6. You've Got A Way.flac"
May 29 02:08:19 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/6. You've Got A Way.flac" took 1 milliseconds
May 29 02:08:19 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:08:19 volumio volumio[1159]: info:
May 29 02:08:19 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:08:19 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:08:19 volumio volumio[1159]: info: sendMpdCommand consume 1 took 0 milliseconds
May 29 02:08:19 volumio volumio[1159]: info:
May 29 02:08:19 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:08:19 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:08:19 volumio volumio[1159]: info:
May 29 02:08:19 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:08:19 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:08:19 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:08:19 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:08:19 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:08:23 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:08:23 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:08:24 volumio volumio[1159]: info:
May 29 02:08:24 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:08:24 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:08:24 volumio volumio[1159]: info:
May 29 02:08:24 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:08:24 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:08:24 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:08:24 volumio volumio[1159]: info:
May 29 02:08:24 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:08:24 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:08:24 volumio volumio[1159]: info:
May 29 02:08:24 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:08:24 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:08:24 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:08:24 volumio volumio[1159]: info:
May 29 02:08:24 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:08:24 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:08:24 volumio volumio[1159]: info:
May 29 02:08:24 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:08:24 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:08:24 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:08:24 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:08:24 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:08:24 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:08:24 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:08:24 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:08:24 volumio volumio[1159]: info: sendMpdCommand status took 0 milliseconds
May 29 02:08:24 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:08:24 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:08:24 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:08:24 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:08:24 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:08:24 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:08:24 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:08:24 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:08:24 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:08:24 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:08:24 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:08:24 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:08:24 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:08:24 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:08:24 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:08:24 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":31,"duration":299,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1337 Kbps","isStreaming":false,"title":"You've Got A Way","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/6. You've Got A Way.flac","trackType":"flac"}
May 29 02:08:24 volumio volumio[1159]: verbose: CURRENT POSITION 9
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:08:24 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:08:24 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:08:24 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:08:24 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:08:24 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:08:24 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:08:24 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:08:24 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:08:24 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:08:24 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":31,"duration":299,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1337 Kbps","isStreaming":false,"title":"You've Got A Way","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/6. You've Got A Way.flac","trackType":"flac"}
May 29 02:08:24 volumio volumio[1159]: verbose: CURRENT POSITION 9
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:08:24 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:08:24 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:08:24 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:08:24 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:08:24 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:08:24 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:08:24 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:08:24 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:08:24 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":31,"duration":299,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1337 Kbps","isStreaming":false,"title":"You've Got A Way","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/6. You've Got A Way.flac","trackType":"flac"}
May 29 02:08:24 volumio volumio[1159]: verbose: CURRENT POSITION 9
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:08:24 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:08:24 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:08:24 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:08:24 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:08:24 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:08:24 volumio volumio[1159]: info: ------------------------------ 19ms
May 29 02:08:24 volumio volumio[1159]: info: ------------------------------ 19ms
May 29 02:08:24 volumio volumio[1159]: info: ------------------------------ 18ms
May 29 02:08:24 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:08:24 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:08:24 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:08:24 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:08:24 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:08:24 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:08:24 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:08:24 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:08:24 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:08:24 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:08:24 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:08:29 volumio go-librespot[1678]: time="2025-05-29T02:08:29-05:00" level=trace msg="sent dealer ping"
May 29 02:08:30 volumio go-librespot[1678]: time="2025-05-29T02:08:30-05:00" level=trace msg="received dealer pong"
May 29 02:08:59 volumio go-librespot[1678]: time="2025-05-29T02:08:59-05:00" level=trace msg="sent dealer ping"
May 29 02:08:59 volumio go-librespot[1678]: time="2025-05-29T02:08:59-05:00" level=trace msg="received dealer pong"
May 29 02:09:00 volumio go-librespot[1678]: time="2025-05-29T02:09:00-05:00" level=trace msg="received accesspoint ping"
May 29 02:09:00 volumio go-librespot[1678]: time="2025-05-29T02:09:00-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:09:29 volumio go-librespot[1678]: time="2025-05-29T02:09:29-05:00" level=trace msg="sent dealer ping"
May 29 02:09:30 volumio go-librespot[1678]: time="2025-05-29T02:09:30-05:00" level=trace msg="received dealer pong"
May 29 02:09:59 volumio go-librespot[1678]: time="2025-05-29T02:09:59-05:00" level=trace msg="sent dealer ping"
May 29 02:09:59 volumio go-librespot[1678]: time="2025-05-29T02:09:59-05:00" level=trace msg="received dealer pong"
May 29 02:10:29 volumio go-librespot[1678]: time="2025-05-29T02:10:29-05:00" level=trace msg="sent dealer ping"
May 29 02:10:30 volumio go-librespot[1678]: time="2025-05-29T02:10:30-05:00" level=trace msg="received dealer pong"
May 29 02:10:31 volumio go-librespot[1678]: time="2025-05-29T02:10:31-05:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.1.65:46814->104.154.127.247:443: read: connection reset by peer"
May 29 02:10:31 volumio go-librespot[1678]: time="2025-05-29T02:10:31-05:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:80, retrying with a different AP" error="dial tcp 104.154.127.247:80: connect: connection refused"
May 29 02:10:31 volumio go-librespot[1678]: time="2025-05-29T02:10:31-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070"
May 29 02:10:31 volumio go-librespot[1678]: time="2025-05-29T02:10:31-05:00" level=debug msg="completed keyexchange"
May 29 02:10:31 volumio go-librespot[1678]: time="2025-05-29T02:10:31-05:00" level=debug msg="completed challenge"
May 29 02:10:32 volumio go-librespot[1678]: time="2025-05-29T02:10:32-05:00" level=info msg="authenticated AP as txqeumjpo0e2sqzbg8ea9kho7"
May 29 02:10:32 volumio go-librespot[1678]: time="2025-05-29T02:10:32-05:00" level=debug msg="re-established accesspoint connection"
May 29 02:10:32 volumio go-librespot[1678]: time="2025-05-29T02:10:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:10:32 volumio go-librespot[1678]: time="2025-05-29T02:10:32-05:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336"
May 29 02:10:32 volumio go-librespot[1678]: time="2025-05-29T02:10:32-05:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2"
May 29 02:10:32 volumio go-librespot[1678]: time="2025-05-29T02:10:32-05:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17"
May 29 02:10:32 volumio go-librespot[1678]: time="2025-05-29T02:10:32-05:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0"
May 29 02:10:32 volumio go-librespot[1678]: time="2025-05-29T02:10:32-05:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481"
May 29 02:10:32 volumio go-librespot[1678]: time="2025-05-29T02:10:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:10:59 volumio go-librespot[1678]: time="2025-05-29T02:10:59-05:00" level=trace msg="sent dealer ping"
May 29 02:10:59 volumio go-librespot[1678]: time="2025-05-29T02:10:59-05:00" level=trace msg="received dealer pong"
May 29 02:11:29 volumio go-librespot[1678]: time="2025-05-29T02:11:29-05:00" level=trace msg="sent dealer ping"
May 29 02:11:30 volumio go-librespot[1678]: time="2025-05-29T02:11:30-05:00" level=trace msg="received dealer pong"
May 29 02:11:59 volumio go-librespot[1678]: time="2025-05-29T02:11:59-05:00" level=trace msg="sent dealer ping"
May 29 02:11:59 volumio go-librespot[1678]: time="2025-05-29T02:11:59-05:00" level=trace msg="received dealer pong"
May 29 02:12:29 volumio go-librespot[1678]: time="2025-05-29T02:12:29-05:00" level=trace msg="sent dealer ping"
May 29 02:12:30 volumio go-librespot[1678]: time="2025-05-29T02:12:30-05:00" level=trace msg="received dealer pong"
May 29 02:12:32 volumio go-librespot[1678]: time="2025-05-29T02:12:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:12:32 volumio go-librespot[1678]: time="2025-05-29T02:12:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:12:59 volumio go-librespot[1678]: time="2025-05-29T02:12:59-05:00" level=trace msg="sent dealer ping"
May 29 02:12:59 volumio go-librespot[1678]: time="2025-05-29T02:12:59-05:00" level=trace msg="received dealer pong"
May 29 02:13:17 volumio volumio[1159]: info: CorePlayQueue::getTrack 9
May 29 02:13:17 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:13:17 volumio volumio[1159]: info: Prefetching next song
May 29 02:13:17 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:13:17 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/10. A Living Prayer.flac"
May 29 02:13:17 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/10. A Living Prayer.flac" took 0 milliseconds
May 29 02:13:17 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:13:17 volumio volumio[1159]: info:
May 29 02:13:17 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:13:17 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:13:17 volumio volumio[1159]: info: sendMpdCommand consume 1 took 0 milliseconds
May 29 02:13:17 volumio volumio[1159]: info:
May 29 02:13:17 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:13:17 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:13:17 volumio volumio[1159]: info:
May 29 02:13:17 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:13:17 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:13:17 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:13:17 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:13:17 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:13:22 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:13:22 volumio volumio[1159]: info:
May 29 02:13:22 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:13:22 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:13:22 volumio volumio[1159]: info:
May 29 02:13:22 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:13:22 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:13:22 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:13:22 volumio volumio[1159]: info:
May 29 02:13:22 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:13:22 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:13:22 volumio volumio[1159]: info:
May 29 02:13:22 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:13:22 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:13:22 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:13:22 volumio volumio[1159]: info:
May 29 02:13:22 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:13:22 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:13:22 volumio volumio[1159]: info:
May 29 02:13:22 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:13:22 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:13:22 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:13:22 volumio volumio[1159]: info: ------------------------------ 3ms
May 29 02:13:22 volumio volumio[1159]: info: sendMpdCommand status took 2 milliseconds
May 29 02:13:22 volumio volumio[1159]: info: ------------------------------ 2ms
May 29 02:13:22 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:13:22 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:13:22 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:13:22 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:13:22 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:13:22 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:13:22 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:13:22 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:13:22 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:13:22 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:13:22 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:13:22 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:13:22 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:13:22 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:13:22 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:13:22 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:13:22 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:13:22 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:13:22 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":83,"duration":255,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1280 Kbps","isStreaming":false,"title":"A Living Prayer","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/10. A Living Prayer.flac","trackType":"flac"}
May 29 02:13:22 volumio volumio[1159]: verbose: CURRENT POSITION 1
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:13:22 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:13:22 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:13:22 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:13:22 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:13:22 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:13:22 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:13:22 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:13:22 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:13:22 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:13:22 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":83,"duration":255,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1280 Kbps","isStreaming":false,"title":"A Living Prayer","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/10. A Living Prayer.flac","trackType":"flac"}
May 29 02:13:22 volumio volumio[1159]: verbose: CURRENT POSITION 1
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:13:22 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:13:22 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:13:22 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:13:22 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:13:22 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:13:22 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:13:22 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:13:22 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:13:22 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":83,"duration":255,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1280 Kbps","isStreaming":false,"title":"A Living Prayer","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/10. A Living Prayer.flac","trackType":"flac"}
May 29 02:13:22 volumio volumio[1159]: verbose: CURRENT POSITION 1
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:13:22 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:13:22 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:13:22 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:13:22 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:13:22 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:13:22 volumio volumio[1159]: info: ------------------------------ 21ms
May 29 02:13:22 volumio volumio[1159]: info: ------------------------------ 20ms
May 29 02:13:22 volumio volumio[1159]: info: ------------------------------ 20ms
May 29 02:13:22 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:13:22 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:13:22 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:13:22 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:13:22 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:13:22 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:13:22 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:13:22 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:13:22 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:13:22 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:13:22 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:13:29 volumio go-librespot[1678]: time="2025-05-29T02:13:29-05:00" level=trace msg="sent dealer ping"
May 29 02:13:30 volumio go-librespot[1678]: time="2025-05-29T02:13:30-05:00" level=trace msg="received dealer pong"
May 29 02:13:59 volumio go-librespot[1678]: time="2025-05-29T02:13:59-05:00" level=trace msg="sent dealer ping"
May 29 02:13:59 volumio go-librespot[1678]: time="2025-05-29T02:13:59-05:00" level=trace msg="received dealer pong"
May 29 02:14:29 volumio go-librespot[1678]: time="2025-05-29T02:14:29-05:00" level=trace msg="sent dealer ping"
May 29 02:14:30 volumio go-librespot[1678]: time="2025-05-29T02:14:30-05:00" level=trace msg="received dealer pong"
May 29 02:14:32 volumio go-librespot[1678]: time="2025-05-29T02:14:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:14:32 volumio go-librespot[1678]: time="2025-05-29T02:14:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:14:59 volumio go-librespot[1678]: time="2025-05-29T02:14:59-05:00" level=trace msg="sent dealer ping"
May 29 02:14:59 volumio go-librespot[1678]: time="2025-05-29T02:14:59-05:00" level=trace msg="received dealer pong"
May 29 02:15:29 volumio go-librespot[1678]: time="2025-05-29T02:15:29-05:00" level=trace msg="sent dealer ping"
May 29 02:15:30 volumio go-librespot[1678]: time="2025-05-29T02:15:30-05:00" level=trace msg="received dealer pong"
May 29 02:15:59 volumio go-librespot[1678]: time="2025-05-29T02:15:59-05:00" level=trace msg="sent dealer ping"
May 29 02:15:59 volumio go-librespot[1678]: time="2025-05-29T02:15:59-05:00" level=trace msg="received dealer pong"
May 29 02:16:29 volumio go-librespot[1678]: time="2025-05-29T02:16:29-05:00" level=trace msg="sent dealer ping"
May 29 02:16:30 volumio go-librespot[1678]: time="2025-05-29T02:16:30-05:00" level=trace msg="received dealer pong"
May 29 02:16:32 volumio go-librespot[1678]: time="2025-05-29T02:16:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:16:32 volumio go-librespot[1678]: time="2025-05-29T02:16:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:16:59 volumio go-librespot[1678]: time="2025-05-29T02:16:59-05:00" level=trace msg="sent dealer ping"
May 29 02:16:59 volumio go-librespot[1678]: time="2025-05-29T02:16:59-05:00" level=trace msg="received dealer pong"
May 29 02:17:29 volumio go-librespot[1678]: time="2025-05-29T02:17:29-05:00" level=trace msg="sent dealer ping"
May 29 02:17:30 volumio go-librespot[1678]: time="2025-05-29T02:17:30-05:00" level=trace msg="received dealer pong"
May 29 02:17:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 1
May 29 02:17:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:17:32 volumio volumio[1159]: info: Prefetching next song
May 29 02:17:32 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:17:32 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/9. When I Fall In Love.flac"
May 29 02:17:32 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/9. When I Fall In Love.flac" took 0 milliseconds
May 29 02:17:32 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:17:32 volumio volumio[1159]: info:
May 29 02:17:32 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:17:32 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:17:32 volumio volumio[1159]: info: sendMpdCommand consume 1 took 0 milliseconds
May 29 02:17:32 volumio volumio[1159]: info:
May 29 02:17:32 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:17:32 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:17:32 volumio volumio[1159]: info:
May 29 02:17:32 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:17:32 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:17:32 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:17:32 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:17:32 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:17:37 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:17:37 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:17:37 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:17:37 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:17:37 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:17:37 volumio volumio[1159]: info:
May 29 02:17:37 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:17:37 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:17:37 volumio volumio[1159]: info:
May 29 02:17:37 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:17:37 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:17:37 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:17:37 volumio volumio[1159]: info:
May 29 02:17:37 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:17:37 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:17:37 volumio volumio[1159]: info:
May 29 02:17:37 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:17:37 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:17:37 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:17:37 volumio volumio[1159]: info:
May 29 02:17:37 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:17:37 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:17:37 volumio volumio[1159]: info:
May 29 02:17:37 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:17:37 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:17:37 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:17:37 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:17:37 volumio volumio[1159]: info: sendMpdCommand status took 2 milliseconds
May 29 02:17:37 volumio volumio[1159]: info: ------------------------------ 2ms
May 29 02:17:37 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:17:37 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:17:37 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:17:37 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:17:37 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:17:37 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:17:37 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:17:37 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:17:37 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:17:37 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:17:37 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:17:37 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:17:37 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:17:37 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:17:37 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:17:37 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:17:37 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:17:37 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:17:37 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":104,"duration":221,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1557 Kbps","isStreaming":false,"title":"When I Fall In Love","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/9. When I Fall In Love.flac","trackType":"flac"}
May 29 02:17:37 volumio volumio[1159]: verbose: CURRENT POSITION 12
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:17:37 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:17:37 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:17:37 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:17:37 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:17:37 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:17:37 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:17:37 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:17:37 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:17:37 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:17:37 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":104,"duration":221,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1554 Kbps","isStreaming":false,"title":"When I Fall In Love","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/9. When I Fall In Love.flac","trackType":"flac"}
May 29 02:17:37 volumio volumio[1159]: verbose: CURRENT POSITION 12
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:17:37 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:17:37 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:17:37 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:17:37 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:17:37 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:17:37 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:17:37 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:17:37 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:17:37 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":104,"duration":221,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1554 Kbps","isStreaming":false,"title":"When I Fall In Love","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/9. When I Fall In Love.flac","trackType":"flac"}
May 29 02:17:37 volumio volumio[1159]: verbose: CURRENT POSITION 12
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:17:37 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:17:37 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:17:37 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:17:37 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:17:37 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:17:37 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:17:37 volumio volumio[1159]: info: ------------------------------ 22ms
May 29 02:17:37 volumio volumio[1159]: info: ------------------------------ 22ms
May 29 02:17:37 volumio volumio[1159]: info: ------------------------------ 22ms
May 29 02:17:37 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:17:37 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:17:59 volumio go-librespot[1678]: time="2025-05-29T02:17:59-05:00" level=trace msg="sent dealer ping"
May 29 02:17:59 volumio go-librespot[1678]: time="2025-05-29T02:17:59-05:00" level=trace msg="received dealer pong"
May 29 02:18:29 volumio go-librespot[1678]: time="2025-05-29T02:18:29-05:00" level=trace msg="sent dealer ping"
May 29 02:18:30 volumio go-librespot[1678]: time="2025-05-29T02:18:30-05:00" level=trace msg="received dealer pong"
May 29 02:18:32 volumio go-librespot[1678]: time="2025-05-29T02:18:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:18:32 volumio go-librespot[1678]: time="2025-05-29T02:18:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:18:59 volumio go-librespot[1678]: time="2025-05-29T02:18:59-05:00" level=trace msg="sent dealer ping"
May 29 02:18:59 volumio go-librespot[1678]: time="2025-05-29T02:18:59-05:00" level=trace msg="received dealer pong"
May 29 02:19:29 volumio go-librespot[1678]: time="2025-05-29T02:19:29-05:00" level=trace msg="sent dealer ping"
May 29 02:19:29 volumio go-librespot[1678]: time="2025-05-29T02:19:29-05:00" level=trace msg="received dealer pong"
May 29 02:19:59 volumio go-librespot[1678]: time="2025-05-29T02:19:59-05:00" level=trace msg="sent dealer ping"
May 29 02:19:59 volumio go-librespot[1678]: time="2025-05-29T02:19:59-05:00" level=trace msg="received dealer pong"
May 29 02:20:29 volumio go-librespot[1678]: time="2025-05-29T02:20:29-05:00" level=trace msg="sent dealer ping"
May 29 02:20:29 volumio go-librespot[1678]: time="2025-05-29T02:20:29-05:00" level=trace msg="received dealer pong"
May 29 02:20:32 volumio go-librespot[1678]: time="2025-05-29T02:20:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:20:32 volumio go-librespot[1678]: time="2025-05-29T02:20:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:20:59 volumio go-librespot[1678]: time="2025-05-29T02:20:59-05:00" level=trace msg="sent dealer ping"
May 29 02:20:59 volumio go-librespot[1678]: time="2025-05-29T02:20:59-05:00" level=trace msg="received dealer pong"
May 29 02:21:13 volumio volumio[1159]: info: CorePlayQueue::getTrack 12
May 29 02:21:13 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:21:13 volumio volumio[1159]: info: Prefetching next song
May 29 02:21:13 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:21:13 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love V/11. I Swear.flac"
May 29 02:21:13 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love V/11. I Swear.flac" took 0 milliseconds
May 29 02:21:13 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:21:13 volumio volumio[1159]: info:
May 29 02:21:13 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:21:13 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:21:13 volumio volumio[1159]: info: sendMpdCommand consume 1 took 1 milliseconds
May 29 02:21:13 volumio volumio[1159]: info:
May 29 02:21:13 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:21:13 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:21:13 volumio volumio[1159]: info:
May 29 02:21:13 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:21:13 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:21:13 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:21:13 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:21:13 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:21:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:21:18 volumio volumio[1159]: info:
May 29 02:21:18 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:21:18 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:21:18 volumio volumio[1159]: info:
May 29 02:21:18 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:21:18 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:21:18 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:21:18 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:21:18 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:21:18 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:21:18 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:21:18 volumio volumio[1159]: info:
May 29 02:21:18 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:21:18 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:21:18 volumio volumio[1159]: info:
May 29 02:21:18 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:21:18 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:21:18 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:21:18 volumio volumio[1159]: info:
May 29 02:21:18 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:21:18 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:21:18 volumio volumio[1159]: info:
May 29 02:21:18 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:21:18 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:21:18 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:21:18 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:21:18 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:21:18 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:21:18 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:21:18 volumio volumio[1159]: info: sendMpdCommand status took 0 milliseconds
May 29 02:21:18 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:21:18 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:21:18 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:21:18 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:21:18 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:21:18 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:21:18 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:21:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:21:18 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":10,"duration":263,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"I Swear","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/11. I Swear.flac","trackType":"flac"}
May 29 02:21:18 volumio volumio[1159]: verbose: CURRENT POSITION 28
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:21:18 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:21:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:21:18 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:21:18 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:21:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:21:18 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:21:18 volumio volumio[1159]: info: ------------------------------ 8ms
May 29 02:21:18 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 6 milliseconds
May 29 02:21:18 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:21:18 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:21:18 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:21:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:21:18 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":10,"duration":263,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"I Swear","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/11. I Swear.flac","trackType":"flac"}
May 29 02:21:18 volumio volumio[1159]: verbose: CURRENT POSITION 28
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:21:18 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:21:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:21:18 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:21:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:21:18 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:21:18 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:21:18 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:21:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:21:18 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":10,"duration":263,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"I Swear","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/11. I Swear.flac","trackType":"flac"}
May 29 02:21:18 volumio volumio[1159]: verbose: CURRENT POSITION 28
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:21:18 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:21:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:21:18 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:21:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:21:18 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:21:18 volumio volumio[1159]: info: ------------------------------ 23ms
May 29 02:21:18 volumio volumio[1159]: info: ------------------------------ 23ms
May 29 02:21:18 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:21:18 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:21:18 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:21:18 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:21:18 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:21:18 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:21:18 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:21:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:21:18 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:21:18 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:21:29 volumio go-librespot[1678]: time="2025-05-29T02:21:29-05:00" level=trace msg="sent dealer ping"
May 29 02:21:29 volumio go-librespot[1678]: time="2025-05-29T02:21:29-05:00" level=trace msg="received dealer pong"
May 29 02:21:59 volumio go-librespot[1678]: time="2025-05-29T02:21:59-05:00" level=trace msg="sent dealer ping"
May 29 02:21:59 volumio go-librespot[1678]: time="2025-05-29T02:21:59-05:00" level=trace msg="received dealer pong"
May 29 02:22:29 volumio go-librespot[1678]: time="2025-05-29T02:22:29-05:00" level=trace msg="sent dealer ping"
May 29 02:22:29 volumio go-librespot[1678]: time="2025-05-29T02:22:29-05:00" level=trace msg="received dealer pong"
May 29 02:22:32 volumio go-librespot[1678]: time="2025-05-29T02:22:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:22:32 volumio go-librespot[1678]: time="2025-05-29T02:22:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:22:59 volumio go-librespot[1678]: time="2025-05-29T02:22:59-05:00" level=trace msg="sent dealer ping"
May 29 02:22:59 volumio go-librespot[1678]: time="2025-05-29T02:22:59-05:00" level=trace msg="received dealer pong"
May 29 02:23:29 volumio go-librespot[1678]: time="2025-05-29T02:23:29-05:00" level=trace msg="sent dealer ping"
May 29 02:23:29 volumio go-librespot[1678]: time="2025-05-29T02:23:29-05:00" level=trace msg="received dealer pong"
May 29 02:23:59 volumio go-librespot[1678]: time="2025-05-29T02:23:59-05:00" level=trace msg="sent dealer ping"
May 29 02:23:59 volumio go-librespot[1678]: time="2025-05-29T02:23:59-05:00" level=trace msg="received dealer pong"
May 29 02:24:29 volumio go-librespot[1678]: time="2025-05-29T02:24:29-05:00" level=trace msg="sent dealer ping"
May 29 02:24:29 volumio go-librespot[1678]: time="2025-05-29T02:24:29-05:00" level=trace msg="received dealer pong"
May 29 02:24:32 volumio go-librespot[1678]: time="2025-05-29T02:24:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:24:32 volumio go-librespot[1678]: time="2025-05-29T02:24:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:24:59 volumio go-librespot[1678]: time="2025-05-29T02:24:59-05:00" level=trace msg="sent dealer ping"
May 29 02:24:59 volumio go-librespot[1678]: time="2025-05-29T02:24:59-05:00" level=trace msg="received dealer pong"
May 29 02:25:29 volumio go-librespot[1678]: time="2025-05-29T02:25:29-05:00" level=trace msg="sent dealer ping"
May 29 02:25:30 volumio go-librespot[1678]: time="2025-05-29T02:25:30-05:00" level=trace msg="received dealer pong"
May 29 02:25:36 volumio volumio[1159]: info: CorePlayQueue::getTrack 28
May 29 02:25:36 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:25:36 volumio volumio[1159]: info: Prefetching next song
May 29 02:25:36 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:25:36 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love V/4. First of May.flac"
May 29 02:25:36 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love V/4. First of May.flac" took 1 milliseconds
May 29 02:25:36 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:25:36 volumio volumio[1159]: info:
May 29 02:25:36 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:25:36 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:25:36 volumio volumio[1159]: info: sendMpdCommand consume 1 took 0 milliseconds
May 29 02:25:36 volumio volumio[1159]: info:
May 29 02:25:36 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:25:36 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:25:36 volumio volumio[1159]: info:
May 29 02:25:36 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:25:36 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:25:36 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:25:36 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:25:36 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:25:41 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:25:41 volumio volumio[1159]: info:
May 29 02:25:41 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:25:41 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:25:41 volumio volumio[1159]: info:
May 29 02:25:41 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:25:41 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:25:41 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:25:41 volumio volumio[1159]: info:
May 29 02:25:41 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:25:41 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:25:41 volumio volumio[1159]: info:
May 29 02:25:41 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:25:41 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:25:41 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:25:41 volumio volumio[1159]: info:
May 29 02:25:41 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:25:41 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:25:41 volumio volumio[1159]: info:
May 29 02:25:41 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:25:41 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:25:41 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:25:41 volumio volumio[1159]: info: ------------------------------ 2ms
May 29 02:25:41 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:25:41 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:25:41 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:25:41 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:25:41 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:25:41 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:25:41 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:25:41 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:25:41 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:25:41 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:25:41 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:25:41 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:25:41 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:25:41 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:25:41 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:25:41 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:25:41 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:25:41 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:25:41 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:25:41 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:25:41 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":10,"duration":247,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"820 Kbps","isStreaming":false,"title":"First of May","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/4. First of May.flac","trackType":"flac"}
May 29 02:25:41 volumio volumio[1159]: verbose: CURRENT POSITION 33
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:25:41 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:25:41 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:25:41 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:25:41 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:25:41 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:25:41 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:25:41 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:25:41 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:25:41 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:25:41 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":10,"duration":247,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"820 Kbps","isStreaming":false,"title":"First of May","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/4. First of May.flac","trackType":"flac"}
May 29 02:25:41 volumio volumio[1159]: verbose: CURRENT POSITION 33
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:25:41 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:25:41 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:25:41 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:25:41 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:25:41 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:25:41 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:25:41 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:25:41 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:25:41 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":10,"duration":247,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"820 Kbps","isStreaming":false,"title":"First of May","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/4. First of May.flac","trackType":"flac"}
May 29 02:25:41 volumio volumio[1159]: verbose: CURRENT POSITION 33
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:25:41 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:25:41 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:25:41 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:25:41 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:25:41 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:25:41 volumio volumio[1159]: info: ------------------------------ 23ms
May 29 02:25:41 volumio volumio[1159]: info: ------------------------------ 24ms
May 29 02:25:41 volumio volumio[1159]: info: ------------------------------ 24ms
May 29 02:25:41 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:25:41 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:25:41 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:25:41 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:25:41 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:25:41 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:25:41 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:25:41 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:25:41 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:25:41 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:25:41 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:25:59 volumio go-librespot[1678]: time="2025-05-29T02:25:59-05:00" level=trace msg="sent dealer ping"
May 29 02:25:59 volumio go-librespot[1678]: time="2025-05-29T02:25:59-05:00" level=trace msg="received dealer pong"
May 29 02:26:29 volumio go-librespot[1678]: time="2025-05-29T02:26:29-05:00" level=trace msg="sent dealer ping"
May 29 02:26:29 volumio go-librespot[1678]: time="2025-05-29T02:26:29-05:00" level=trace msg="received dealer pong"
May 29 02:26:32 volumio go-librespot[1678]: time="2025-05-29T02:26:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:26:32 volumio go-librespot[1678]: time="2025-05-29T02:26:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:26:59 volumio go-librespot[1678]: time="2025-05-29T02:26:59-05:00" level=trace msg="sent dealer ping"
May 29 02:26:59 volumio go-librespot[1678]: time="2025-05-29T02:26:59-05:00" level=trace msg="received dealer pong"
May 29 02:27:29 volumio go-librespot[1678]: time="2025-05-29T02:27:29-05:00" level=trace msg="sent dealer ping"
May 29 02:27:29 volumio go-librespot[1678]: time="2025-05-29T02:27:29-05:00" level=trace msg="received dealer pong"
May 29 02:27:59 volumio go-librespot[1678]: time="2025-05-29T02:27:59-05:00" level=trace msg="sent dealer ping"
May 29 02:27:59 volumio go-librespot[1678]: time="2025-05-29T02:27:59-05:00" level=trace msg="received dealer pong"
May 29 02:28:29 volumio go-librespot[1678]: time="2025-05-29T02:28:29-05:00" level=trace msg="sent dealer ping"
May 29 02:28:29 volumio go-librespot[1678]: time="2025-05-29T02:28:29-05:00" level=trace msg="received dealer pong"
May 29 02:28:32 volumio go-librespot[1678]: time="2025-05-29T02:28:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:28:32 volumio go-librespot[1678]: time="2025-05-29T02:28:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:28:59 volumio go-librespot[1678]: time="2025-05-29T02:28:59-05:00" level=trace msg="sent dealer ping"
May 29 02:28:59 volumio go-librespot[1678]: time="2025-05-29T02:28:59-05:00" level=trace msg="received dealer pong"
May 29 02:29:29 volumio go-librespot[1678]: time="2025-05-29T02:29:29-05:00" level=trace msg="sent dealer ping"
May 29 02:29:29 volumio go-librespot[1678]: time="2025-05-29T02:29:29-05:00" level=trace msg="received dealer pong"
May 29 02:29:43 volumio volumio[1159]: info: CorePlayQueue::getTrack 33
May 29 02:29:43 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:29:43 volumio volumio[1159]: info: Prefetching next song
May 29 02:29:43 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:29:43 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/8. Take a Bow.flac"
May 29 02:29:43 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/8. Take a Bow.flac" took 0 milliseconds
May 29 02:29:43 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:29:43 volumio volumio[1159]: info:
May 29 02:29:43 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:29:43 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:29:43 volumio volumio[1159]: info: sendMpdCommand consume 1 took 0 milliseconds
May 29 02:29:43 volumio volumio[1159]: info:
May 29 02:29:43 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:29:43 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:29:43 volumio volumio[1159]: info:
May 29 02:29:43 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:29:43 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:29:43 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:29:43 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:29:43 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:29:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:29:47 volumio volumio[1159]: info:
May 29 02:29:47 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:29:47 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:29:47 volumio volumio[1159]: info:
May 29 02:29:47 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:29:47 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:29:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:29:47 volumio volumio[1159]: info:
May 29 02:29:47 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:29:47 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:29:47 volumio volumio[1159]: info:
May 29 02:29:47 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:29:47 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:29:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:29:47 volumio volumio[1159]: info:
May 29 02:29:47 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:29:47 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:29:47 volumio volumio[1159]: info:
May 29 02:29:47 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:29:47 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:29:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:29:47 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:29:47 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:29:47 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:29:47 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:29:47 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:29:47 volumio volumio[1159]: info: sendMpdCommand status took 0 milliseconds
May 29 02:29:47 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:29:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:29:47 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:29:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:29:47 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:29:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:29:47 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:29:47 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:29:47 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:29:47 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:29:47 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:29:47 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:29:47 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:29:47 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:29:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:29:47 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":62,"duration":271,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1 Kbps","isStreaming":false,"title":"Take a Bow","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/8. Take a Bow.flac","trackType":"flac"}
May 29 02:29:47 volumio volumio[1159]: verbose: CURRENT POSITION 24
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:29:47 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:29:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:29:47 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:29:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:29:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:29:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:29:47 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:29:47 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:29:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:29:47 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":62,"duration":271,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1 Kbps","isStreaming":false,"title":"Take a Bow","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/8. Take a Bow.flac","trackType":"flac"}
May 29 02:29:47 volumio volumio[1159]: verbose: CURRENT POSITION 24
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:29:47 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:29:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:29:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:29:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:29:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:29:47 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:29:47 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:29:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:29:47 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":62,"duration":271,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1 Kbps","isStreaming":false,"title":"Take a Bow","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/8. Take a Bow.flac","trackType":"flac"}
May 29 02:29:47 volumio volumio[1159]: verbose: CURRENT POSITION 24
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:29:47 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:29:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:29:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:29:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:29:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:29:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:29:47 volumio volumio[1159]: info: ------------------------------ 21ms
May 29 02:29:47 volumio volumio[1159]: info: ------------------------------ 22ms
May 29 02:29:47 volumio volumio[1159]: info: ------------------------------ 21ms
May 29 02:29:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:29:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:29:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:29:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:29:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:29:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:29:48 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:29:48 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:29:48 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:29:48 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:29:48 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:29:59 volumio go-librespot[1678]: time="2025-05-29T02:29:59-05:00" level=trace msg="sent dealer ping"
May 29 02:29:59 volumio go-librespot[1678]: time="2025-05-29T02:29:59-05:00" level=trace msg="received dealer pong"
May 29 02:30:29 volumio go-librespot[1678]: time="2025-05-29T02:30:29-05:00" level=trace msg="sent dealer ping"
May 29 02:30:29 volumio go-librespot[1678]: time="2025-05-29T02:30:29-05:00" level=trace msg="received dealer pong"
May 29 02:30:32 volumio go-librespot[1678]: time="2025-05-29T02:30:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:30:32 volumio go-librespot[1678]: time="2025-05-29T02:30:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:30:59 volumio go-librespot[1678]: time="2025-05-29T02:30:59-05:00" level=trace msg="sent dealer ping"
May 29 02:30:59 volumio go-librespot[1678]: time="2025-05-29T02:30:59-05:00" level=trace msg="received dealer pong"
May 29 02:31:29 volumio go-librespot[1678]: time="2025-05-29T02:31:29-05:00" level=trace msg="sent dealer ping"
May 29 02:31:29 volumio go-librespot[1678]: time="2025-05-29T02:31:29-05:00" level=trace msg="received dealer pong"
May 29 02:31:57 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
May 29 02:31:57 volumio volumio[1159]: info: Received Get System Info
May 29 02:31:57 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
May 29 02:31:57 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
May 29 02:31:57 volumio volumio[1159]: info: Discovery: Getting this device information
May 29 02:31:57 volumio volumio[1159]: info: CoreCommandRouter::volumioGetState
May 29 02:31:57 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:31:57 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
May 29 02:31:59 volumio go-librespot[1678]: time="2025-05-29T02:31:59-05:00" level=trace msg="sent dealer ping"
May 29 02:31:59 volumio go-librespot[1678]: time="2025-05-29T02:31:59-05:00" level=trace msg="received dealer pong"
May 29 02:32:29 volumio go-librespot[1678]: time="2025-05-29T02:32:29-05:00" level=trace msg="sent dealer ping"
May 29 02:32:29 volumio go-librespot[1678]: time="2025-05-29T02:32:29-05:00" level=trace msg="received dealer pong"
May 29 02:32:32 volumio go-librespot[1678]: time="2025-05-29T02:32:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:32:32 volumio go-librespot[1678]: time="2025-05-29T02:32:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:32:59 volumio go-librespot[1678]: time="2025-05-29T02:32:59-05:00" level=trace msg="sent dealer ping"
May 29 02:32:59 volumio go-librespot[1678]: time="2025-05-29T02:32:59-05:00" level=trace msg="received dealer pong"
May 29 02:33:29 volumio go-librespot[1678]: time="2025-05-29T02:33:29-05:00" level=trace msg="sent dealer ping"
May 29 02:33:30 volumio go-librespot[1678]: time="2025-05-29T02:33:30-05:00" level=trace msg="received dealer pong"
May 29 02:33:59 volumio go-librespot[1678]: time="2025-05-29T02:33:59-05:00" level=trace msg="sent dealer ping"
May 29 02:33:59 volumio go-librespot[1678]: time="2025-05-29T02:33:59-05:00" level=trace msg="received dealer pong"
May 29 02:34:13 volumio volumio[1159]: info: CorePlayQueue::getTrack 24
May 29 02:34:13 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:34:13 volumio volumio[1159]: info: Prefetching next song
May 29 02:34:13 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:34:13 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/3. Smoke Gets In Your Eyes.flac"
May 29 02:34:13 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/3. Smoke Gets In Your Eyes.flac" took 1 milliseconds
May 29 02:34:13 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:34:13 volumio volumio[1159]: info:
May 29 02:34:13 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:34:13 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:34:13 volumio volumio[1159]: info: sendMpdCommand consume 1 took 0 milliseconds
May 29 02:34:13 volumio volumio[1159]: info:
May 29 02:34:13 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:34:13 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:34:13 volumio volumio[1159]: info:
May 29 02:34:13 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:34:13 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:34:13 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:34:13 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:34:18 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:34:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:34:18 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:34:18 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:34:18 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:34:18 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:34:18 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:34:19 volumio volumio[1159]: info:
May 29 02:34:19 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:34:19 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:34:19 volumio volumio[1159]: info:
May 29 02:34:19 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:34:19 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:34:19 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:34:19 volumio volumio[1159]: info:
May 29 02:34:19 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:34:19 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:34:19 volumio volumio[1159]: info:
May 29 02:34:19 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:34:19 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:34:19 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:34:19 volumio volumio[1159]: info:
May 29 02:34:19 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:34:19 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:34:19 volumio volumio[1159]: info:
May 29 02:34:19 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:34:19 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:34:19 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:34:19 volumio volumio[1159]: info: ------------------------------ 2ms
May 29 02:34:19 volumio volumio[1159]: info: sendMpdCommand status took 3 milliseconds
May 29 02:34:19 volumio volumio[1159]: info: ------------------------------ 3ms
May 29 02:34:19 volumio volumio[1159]: info: sendMpdCommand status took 2 milliseconds
May 29 02:34:19 volumio volumio[1159]: info: ------------------------------ 2ms
May 29 02:34:19 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:34:19 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:34:19 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:34:19 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:34:19 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:34:19 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:34:19 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:34:19 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:34:19 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:34:19 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:34:19 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:34:19 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:34:19 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:34:19 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:34:19 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:34:19 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:34:19 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":20,"duration":256,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1139 Kbps","isStreaming":false,"title":"Smoke Gets In Your Eyes","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/3. Smoke Gets In Your Eyes.flac","trackType":"flac"}
May 29 02:34:19 volumio volumio[1159]: verbose: CURRENT POSITION 6
May 29 02:34:19 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:34:19 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:34:19 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:34:19 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:34:19 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:34:19 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:34:19 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:34:19 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:34:19 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:34:19 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:34:19 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:34:19 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:34:19 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:34:19 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":20,"duration":256,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1139 Kbps","isStreaming":false,"title":"Smoke Gets In Your Eyes","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/3. Smoke Gets In Your Eyes.flac","trackType":"flac"}
May 29 02:34:19 volumio volumio[1159]: verbose: CURRENT POSITION 6
May 29 02:34:19 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:34:19 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:34:19 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:34:19 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:34:19 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:34:19 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:34:19 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:34:19 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:34:19 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:34:19 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:34:19 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:34:19 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:34:19 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":20,"duration":256,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1139 Kbps","isStreaming":false,"title":"Smoke Gets In Your Eyes","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/3. Smoke Gets In Your Eyes.flac","trackType":"flac"}
May 29 02:34:19 volumio volumio[1159]: verbose: CURRENT POSITION 6
May 29 02:34:19 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:34:19 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:34:19 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:34:19 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:34:19 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:34:19 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:34:19 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:34:19 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:34:19 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:34:19 volumio volumio[1159]: info: ------------------------------ 20ms
May 29 02:34:19 volumio volumio[1159]: info: ------------------------------ 19ms
May 29 02:34:19 volumio volumio[1159]: info: ------------------------------ 20ms
May 29 02:34:19 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:34:19 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:34:19 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:34:19 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:34:19 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:34:19 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:34:29 volumio go-librespot[1678]: time="2025-05-29T02:34:29-05:00" level=trace msg="sent dealer ping"
May 29 02:34:30 volumio go-librespot[1678]: time="2025-05-29T02:34:30-05:00" level=trace msg="received dealer pong"
May 29 02:34:32 volumio go-librespot[1678]: time="2025-05-29T02:34:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:34:32 volumio go-librespot[1678]: time="2025-05-29T02:34:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:34:59 volumio go-librespot[1678]: time="2025-05-29T02:34:59-05:00" level=trace msg="sent dealer ping"
May 29 02:34:59 volumio go-librespot[1678]: time="2025-05-29T02:34:59-05:00" level=trace msg="received dealer pong"
May 29 02:35:29 volumio go-librespot[1678]: time="2025-05-29T02:35:29-05:00" level=trace msg="sent dealer ping"
May 29 02:35:30 volumio go-librespot[1678]: time="2025-05-29T02:35:30-05:00" level=trace msg="received dealer pong"
May 29 02:35:59 volumio go-librespot[1678]: time="2025-05-29T02:35:59-05:00" level=trace msg="sent dealer ping"
May 29 02:35:59 volumio go-librespot[1678]: time="2025-05-29T02:35:59-05:00" level=trace msg="received dealer pong"
May 29 02:36:29 volumio go-librespot[1678]: time="2025-05-29T02:36:29-05:00" level=trace msg="sent dealer ping"
May 29 02:36:32 volumio go-librespot[1678]: time="2025-05-29T02:36:32-05:00" level=trace msg="received dealer pong"
May 29 02:36:32 volumio go-librespot[1678]: time="2025-05-29T02:36:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:36:32 volumio go-librespot[1678]: time="2025-05-29T02:36:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:36:59 volumio go-librespot[1678]: time="2025-05-29T02:36:59-05:00" level=trace msg="sent dealer ping"
May 29 02:36:59 volumio go-librespot[1678]: time="2025-05-29T02:36:59-05:00" level=trace msg="received dealer pong"
May 29 02:37:29 volumio go-librespot[1678]: time="2025-05-29T02:37:29-05:00" level=trace msg="sent dealer ping"
May 29 02:37:30 volumio go-librespot[1678]: time="2025-05-29T02:37:30-05:00" level=trace msg="received dealer pong"
May 29 02:37:59 volumio go-librespot[1678]: time="2025-05-29T02:37:59-05:00" level=trace msg="sent dealer ping"
May 29 02:37:59 volumio go-librespot[1678]: time="2025-05-29T02:37:59-05:00" level=trace msg="received dealer pong"
May 29 02:38:29 volumio go-librespot[1678]: time="2025-05-29T02:38:29-05:00" level=trace msg="sent dealer ping"
May 29 02:38:30 volumio volumio[1159]: info: CorePlayQueue::getTrack 6
May 29 02:38:30 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:38:30 volumio volumio[1159]: info: Prefetching next song
May 29 02:38:30 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:38:30 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love V/2. Unchained Melody.flac"
May 29 02:38:30 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love V/2. Unchained Melody.flac" took 0 milliseconds
May 29 02:38:30 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:38:30 volumio volumio[1159]: info:
May 29 02:38:30 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:38:30 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:38:30 volumio volumio[1159]: info: sendMpdCommand consume 1 took 0 milliseconds
May 29 02:38:30 volumio volumio[1159]: info:
May 29 02:38:30 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:38:30 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:38:30 volumio volumio[1159]: info:
May 29 02:38:30 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:38:30 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:38:30 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:38:30 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:38:30 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:38:31 volumio go-librespot[1678]: time="2025-05-29T02:38:31-05:00" level=trace msg="received dealer pong"
May 29 02:38:32 volumio go-librespot[1678]: time="2025-05-29T02:38:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:38:32 volumio go-librespot[1678]: time="2025-05-29T02:38:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:38:34 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:38:34 volumio volumio[1159]: info:
May 29 02:38:34 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:38:34 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:38:34 volumio volumio[1159]: info:
May 29 02:38:34 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:38:34 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:38:34 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:38:34 volumio volumio[1159]: info:
May 29 02:38:34 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:38:34 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:38:34 volumio volumio[1159]: info:
May 29 02:38:34 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:38:34 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:38:34 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:38:34 volumio volumio[1159]: info:
May 29 02:38:34 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:38:34 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:38:34 volumio volumio[1159]: info:
May 29 02:38:34 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:38:34 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:38:34 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:38:34 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:38:34 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:38:34 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:38:34 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:38:34 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:38:34 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:38:34 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:38:34 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:38:34 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:38:34 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:38:34 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:38:34 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:38:34 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:38:34 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:38:34 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:38:34 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:38:34 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:38:34 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:38:34 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:38:34 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:38:34 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:38:34 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":83,"duration":254,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1289 Kbps","isStreaming":false,"title":"Unchained Melody","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/2. Unchained Melody.flac","trackType":"flac"}
May 29 02:38:34 volumio volumio[1159]: verbose: CURRENT POSITION 31
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:38:34 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:38:34 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:38:34 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:38:34 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:38:34 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:38:34 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:38:34 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:38:34 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:38:34 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:38:34 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":83,"duration":254,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1289 Kbps","isStreaming":false,"title":"Unchained Melody","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/2. Unchained Melody.flac","trackType":"flac"}
May 29 02:38:34 volumio volumio[1159]: verbose: CURRENT POSITION 31
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:38:34 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:38:34 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:38:34 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:38:34 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:38:34 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:38:34 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:38:34 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:38:34 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:38:34 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":83,"duration":254,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1289 Kbps","isStreaming":false,"title":"Unchained Melody","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/2. Unchained Melody.flac","trackType":"flac"}
May 29 02:38:34 volumio volumio[1159]: verbose: CURRENT POSITION 31
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:38:34 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:38:34 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:38:34 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:38:34 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:38:34 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:38:34 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:38:34 volumio volumio[1159]: info: ------------------------------ 20ms
May 29 02:38:34 volumio volumio[1159]: info: ------------------------------ 19ms
May 29 02:38:34 volumio volumio[1159]: info: ------------------------------ 19ms
May 29 02:38:34 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:38:34 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:38:34 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:38:34 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:38:34 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:38:34 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:38:35 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:38:35 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:38:35 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:38:35 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:38:59 volumio go-librespot[1678]: time="2025-05-29T02:38:59-05:00" level=trace msg="sent dealer ping"
May 29 02:38:59 volumio go-librespot[1678]: time="2025-05-29T02:38:59-05:00" level=trace msg="received dealer pong"
May 29 02:39:29 volumio go-librespot[1678]: time="2025-05-29T02:39:29-05:00" level=trace msg="sent dealer ping"
May 29 02:39:30 volumio go-librespot[1678]: time="2025-05-29T02:39:30-05:00" level=trace msg="received dealer pong"
May 29 02:39:59 volumio go-librespot[1678]: time="2025-05-29T02:39:59-05:00" level=trace msg="sent dealer ping"
May 29 02:39:59 volumio go-librespot[1678]: time="2025-05-29T02:39:59-05:00" level=trace msg="received dealer pong"
May 29 02:40:29 volumio go-librespot[1678]: time="2025-05-29T02:40:29-05:00" level=trace msg="sent dealer ping"
May 29 02:40:30 volumio go-librespot[1678]: time="2025-05-29T02:40:30-05:00" level=trace msg="received dealer pong"
May 29 02:40:32 volumio go-librespot[1678]: time="2025-05-29T02:40:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:40:32 volumio go-librespot[1678]: time="2025-05-29T02:40:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:40:59 volumio go-librespot[1678]: time="2025-05-29T02:40:59-05:00" level=trace msg="sent dealer ping"
May 29 02:40:59 volumio go-librespot[1678]: time="2025-05-29T02:40:59-05:00" level=trace msg="received dealer pong"
May 29 02:41:29 volumio go-librespot[1678]: time="2025-05-29T02:41:29-05:00" level=trace msg="sent dealer ping"
May 29 02:41:30 volumio go-librespot[1678]: time="2025-05-29T02:41:30-05:00" level=trace msg="received dealer pong"
May 29 02:41:59 volumio go-librespot[1678]: time="2025-05-29T02:41:59-05:00" level=trace msg="sent dealer ping"
May 29 02:41:59 volumio go-librespot[1678]: time="2025-05-29T02:41:59-05:00" level=trace msg="received dealer pong"
May 29 02:42:29 volumio go-librespot[1678]: time="2025-05-29T02:42:29-05:00" level=trace msg="sent dealer ping"
May 29 02:42:30 volumio go-librespot[1678]: time="2025-05-29T02:42:30-05:00" level=trace msg="received dealer pong"
May 29 02:42:32 volumio go-librespot[1678]: time="2025-05-29T02:42:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:42:32 volumio go-librespot[1678]: time="2025-05-29T02:42:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:42:43 volumio volumio[1159]: info: CorePlayQueue::getTrack 31
May 29 02:42:43 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:42:43 volumio volumio[1159]: info: Prefetching next song
May 29 02:42:43 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:42:43 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/5. Because Of You.flac"
May 29 02:42:43 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/5. Because Of You.flac" took 0 milliseconds
May 29 02:42:43 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:42:43 volumio volumio[1159]: info:
May 29 02:42:43 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:42:43 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:42:43 volumio volumio[1159]: info: sendMpdCommand consume 1 took 1 milliseconds
May 29 02:42:43 volumio volumio[1159]: info:
May 29 02:42:43 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:42:43 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:42:43 volumio volumio[1159]: info:
May 29 02:42:43 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:42:43 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:42:43 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:42:43 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:42:43 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:42:48 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:42:48 volumio volumio[1159]: info:
May 29 02:42:48 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:42:48 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:42:48 volumio volumio[1159]: info:
May 29 02:42:48 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:42:48 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:42:48 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:42:48 volumio volumio[1159]: info:
May 29 02:42:48 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:42:48 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:42:48 volumio volumio[1159]: info:
May 29 02:42:48 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:42:48 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:42:48 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:42:48 volumio volumio[1159]: info:
May 29 02:42:48 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:42:48 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:42:48 volumio volumio[1159]: info:
May 29 02:42:48 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:42:48 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:42:48 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:42:48 volumio volumio[1159]: info: ------------------------------ 3ms
May 29 02:42:48 volumio volumio[1159]: info: sendMpdCommand status took 2 milliseconds
May 29 02:42:48 volumio volumio[1159]: info: ------------------------------ 2ms
May 29 02:42:48 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:42:48 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:42:48 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:42:48 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:42:48 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:42:48 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:42:48 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:42:48 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:42:48 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:42:48 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:42:48 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:42:48 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:42:48 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:42:48 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:42:48 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:42:48 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:42:48 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:42:48 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:42:48 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":20,"duration":284,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"826 Kbps","isStreaming":false,"title":"Because Of You","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/5. Because Of You.flac","trackType":"flac"}
May 29 02:42:48 volumio volumio[1159]: verbose: CURRENT POSITION 8
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:42:48 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:42:48 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:42:48 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:42:48 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:42:48 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:42:48 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:42:48 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:42:48 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:42:48 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:42:48 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":20,"duration":284,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"826 Kbps","isStreaming":false,"title":"Because Of You","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/5. Because Of You.flac","trackType":"flac"}
May 29 02:42:48 volumio volumio[1159]: verbose: CURRENT POSITION 8
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:42:48 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:42:48 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:42:48 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:42:48 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:42:48 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:42:48 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:42:48 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:42:48 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:42:48 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":20,"duration":284,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"826 Kbps","isStreaming":false,"title":"Because Of You","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/5. Because Of You.flac","trackType":"flac"}
May 29 02:42:48 volumio volumio[1159]: verbose: CURRENT POSITION 8
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:42:48 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:42:48 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:42:48 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:42:48 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:42:48 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:42:48 volumio volumio[1159]: info: ------------------------------ 19ms
May 29 02:42:48 volumio volumio[1159]: info: ------------------------------ 18ms
May 29 02:42:48 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:42:48 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:42:48 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:42:48 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:42:48 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:42:48 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:42:48 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:42:48 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:42:48 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:42:48 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:42:59 volumio go-librespot[1678]: time="2025-05-29T02:42:59-05:00" level=trace msg="sent dealer ping"
May 29 02:42:59 volumio go-librespot[1678]: time="2025-05-29T02:42:59-05:00" level=trace msg="received dealer pong"
May 29 02:43:29 volumio go-librespot[1678]: time="2025-05-29T02:43:29-05:00" level=trace msg="sent dealer ping"
May 29 02:43:30 volumio go-librespot[1678]: time="2025-05-29T02:43:30-05:00" level=trace msg="received dealer pong"
May 29 02:43:59 volumio go-librespot[1678]: time="2025-05-29T02:43:59-05:00" level=trace msg="sent dealer ping"
May 29 02:43:59 volumio go-librespot[1678]: time="2025-05-29T02:43:59-05:00" level=trace msg="received dealer pong"
May 29 02:44:29 volumio go-librespot[1678]: time="2025-05-29T02:44:29-05:00" level=trace msg="sent dealer ping"
May 29 02:44:30 volumio go-librespot[1678]: time="2025-05-29T02:44:30-05:00" level=trace msg="received dealer pong"
May 29 02:44:32 volumio go-librespot[1678]: time="2025-05-29T02:44:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:44:32 volumio go-librespot[1678]: time="2025-05-29T02:44:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:44:59 volumio go-librespot[1678]: time="2025-05-29T02:44:59-05:00" level=trace msg="sent dealer ping"
May 29 02:44:59 volumio go-librespot[1678]: time="2025-05-29T02:44:59-05:00" level=trace msg="received dealer pong"
May 29 02:45:29 volumio go-librespot[1678]: time="2025-05-29T02:45:29-05:00" level=trace msg="sent dealer ping"
May 29 02:45:30 volumio go-librespot[1678]: time="2025-05-29T02:45:30-05:00" level=trace msg="received dealer pong"
May 29 02:45:59 volumio go-librespot[1678]: time="2025-05-29T02:45:59-05:00" level=trace msg="sent dealer ping"
May 29 02:45:59 volumio go-librespot[1678]: time="2025-05-29T02:45:59-05:00" level=trace msg="received dealer pong"
May 29 02:46:29 volumio go-librespot[1678]: time="2025-05-29T02:46:29-05:00" level=trace msg="sent dealer ping"
May 29 02:46:31 volumio go-librespot[1678]: time="2025-05-29T02:46:31-05:00" level=trace msg="received dealer pong"
May 29 02:46:32 volumio go-librespot[1678]: time="2025-05-29T02:46:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:46:32 volumio go-librespot[1678]: time="2025-05-29T02:46:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:46:59 volumio go-librespot[1678]: time="2025-05-29T02:46:59-05:00" level=trace msg="sent dealer ping"
May 29 02:46:59 volumio go-librespot[1678]: time="2025-05-29T02:46:59-05:00" level=trace msg="received dealer pong"
May 29 02:47:27 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:47:27 volumio volumio[1159]: info: CorePlayQueue::getTrack 3
May 29 02:47:27 volumio volumio[1159]: info: Prefetching next song
May 29 02:47:27 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:47:27 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/12. We Are One.flac"
May 29 02:47:27 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love I/12. We Are One.flac" took 1 milliseconds
May 29 02:47:27 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:47:27 volumio volumio[1159]: info:
May 29 02:47:27 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:47:27 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:47:27 volumio volumio[1159]: info: sendMpdCommand consume 1 took 0 milliseconds
May 29 02:47:27 volumio volumio[1159]: info:
May 29 02:47:27 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:47:27 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:47:27 volumio volumio[1159]: info:
May 29 02:47:27 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:47:27 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:47:27 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:47:27 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:47:27 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:47:29 volumio go-librespot[1678]: time="2025-05-29T02:47:29-05:00" level=trace msg="sent dealer ping"
May 29 02:47:30 volumio go-librespot[1678]: time="2025-05-29T02:47:30-05:00" level=trace msg="received dealer pong"
May 29 02:47:32 volumio volumio[1159]: info:
May 29 02:47:32 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:47:32 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:47:32 volumio volumio[1159]: info:
May 29 02:47:32 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:47:32 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:47:32 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:47:32 volumio volumio[1159]: info:
May 29 02:47:32 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:47:32 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:47:32 volumio volumio[1159]: info:
May 29 02:47:32 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:47:32 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:47:32 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:47:32 volumio volumio[1159]: info:
May 29 02:47:32 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:47:32 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:47:32 volumio volumio[1159]: info:
May 29 02:47:32 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:47:32 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:47:32 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:47:32 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:47:32 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:47:32 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:47:32 volumio volumio[1159]: info: sendMpdCommand status took 0 milliseconds
May 29 02:47:32 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:47:32 volumio volumio[1159]: info: sendMpdCommand status took 0 milliseconds
May 29 02:47:32 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:47:32 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:47:32 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:47:32 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:47:32 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:47:32 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:47:32 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:47:32 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:47:32 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:47:32 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:47:32 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:47:32 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:47:32 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:47:32 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:47:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:47:32 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":212,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1262 Kbps","isStreaming":false,"title":"We Are One","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/12. We Are One.flac","trackType":"flac"}
May 29 02:47:32 volumio volumio[1159]: verbose: CURRENT POSITION 8
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:47:32 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:47:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:47:32 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:47:32 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:47:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:47:32 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:47:32 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:47:32 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:47:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:47:32 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":212,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1262 Kbps","isStreaming":false,"title":"We Are One","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/12. We Are One.flac","trackType":"flac"}
May 29 02:47:32 volumio volumio[1159]: verbose: CURRENT POSITION 8
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:47:32 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:47:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:47:32 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:47:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:47:32 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:47:32 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:47:32 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:47:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:47:32 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":212,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1262 Kbps","isStreaming":false,"title":"We Are One","artist":"Yao Si Ting","album":"Endless Love IV","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love I/12. We Are One.flac","trackType":"flac"}
May 29 02:47:32 volumio volumio[1159]: verbose: CURRENT POSITION 8
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:47:32 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:47:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:47:32 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:47:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 8
May 29 02:47:32 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:47:32 volumio volumio[1159]: info: ------------------------------ 19ms
May 29 02:47:32 volumio volumio[1159]: info: ------------------------------ 20ms
May 29 02:47:32 volumio volumio[1159]: info: ------------------------------ 19ms
May 29 02:47:32 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:47:32 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:47:32 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:47:32 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:47:32 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:47:32 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:47:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 3
May 29 02:47:32 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:47:32 volumio volumio[1159]: info: CorePlayQueue::getTrack 3
May 29 02:47:32 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:47:32 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:47:32 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:47:59 volumio go-librespot[1678]: time="2025-05-29T02:47:59-05:00" level=trace msg="sent dealer ping"
May 29 02:47:59 volumio go-librespot[1678]: time="2025-05-29T02:47:59-05:00" level=trace msg="received dealer pong"
May 29 02:48:29 volumio go-librespot[1678]: time="2025-05-29T02:48:29-05:00" level=trace msg="sent dealer ping"
May 29 02:48:30 volumio go-librespot[1678]: time="2025-05-29T02:48:30-05:00" level=trace msg="received dealer pong"
May 29 02:48:32 volumio go-librespot[1678]: time="2025-05-29T02:48:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:48:32 volumio go-librespot[1678]: time="2025-05-29T02:48:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:48:59 volumio go-librespot[1678]: time="2025-05-29T02:48:59-05:00" level=trace msg="sent dealer ping"
May 29 02:48:59 volumio go-librespot[1678]: time="2025-05-29T02:48:59-05:00" level=trace msg="received dealer pong"
May 29 02:49:29 volumio go-librespot[1678]: time="2025-05-29T02:49:29-05:00" level=trace msg="sent dealer ping"
May 29 02:49:31 volumio go-librespot[1678]: time="2025-05-29T02:49:31-05:00" level=trace msg="received dealer pong"
May 29 02:49:56 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
May 29 02:49:57 volumio volumio[1159]: info: Received Get System Info
May 29 02:49:57 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
May 29 02:49:57 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
May 29 02:49:57 volumio volumio[1159]: info: Discovery: Getting this device information
May 29 02:49:57 volumio volumio[1159]: info: CoreCommandRouter::volumioGetState
May 29 02:49:57 volumio volumio[1159]: info: CorePlayQueue::getTrack 3
May 29 02:49:57 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
May 29 02:49:59 volumio go-librespot[1678]: time="2025-05-29T02:49:59-05:00" level=trace msg="sent dealer ping"
May 29 02:49:59 volumio go-librespot[1678]: time="2025-05-29T02:49:59-05:00" level=trace msg="received dealer pong"
May 29 02:50:29 volumio go-librespot[1678]: time="2025-05-29T02:50:29-05:00" level=trace msg="sent dealer ping"
May 29 02:50:30 volumio go-librespot[1678]: time="2025-05-29T02:50:30-05:00" level=trace msg="received dealer pong"
May 29 02:50:32 volumio go-librespot[1678]: time="2025-05-29T02:50:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:50:32 volumio go-librespot[1678]: time="2025-05-29T02:50:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:50:59 volumio volumio[1159]: info: CorePlayQueue::getTrack 3
May 29 02:50:59 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:50:59 volumio volumio[1159]: info: Prefetching next song
May 29 02:50:59 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:50:59 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love V/9. Hey Jude.flac"
May 29 02:50:59 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love V/9. Hey Jude.flac" took 1 milliseconds
May 29 02:50:59 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:50:59 volumio volumio[1159]: info:
May 29 02:50:59 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:50:59 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:50:59 volumio volumio[1159]: info: sendMpdCommand consume 1 took 0 milliseconds
May 29 02:50:59 volumio volumio[1159]: info:
May 29 02:50:59 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:50:59 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:50:59 volumio volumio[1159]: info:
May 29 02:50:59 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:50:59 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:50:59 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:50:59 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:50:59 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:50:59 volumio go-librespot[1678]: time="2025-05-29T02:50:59-05:00" level=trace msg="sent dealer ping"
May 29 02:50:59 volumio go-librespot[1678]: time="2025-05-29T02:50:59-05:00" level=trace msg="received dealer pong"
May 29 02:51:03 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:51:03 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:51:04 volumio volumio[1159]: info:
May 29 02:51:04 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:51:04 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:51:04 volumio volumio[1159]: info:
May 29 02:51:04 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:51:04 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:51:04 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:51:04 volumio volumio[1159]: info:
May 29 02:51:04 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:51:04 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:51:04 volumio volumio[1159]: info:
May 29 02:51:04 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:51:04 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:51:04 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:51:04 volumio volumio[1159]: info:
May 29 02:51:04 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:51:04 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:51:04 volumio volumio[1159]: info:
May 29 02:51:04 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:51:04 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:51:04 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:51:04 volumio volumio[1159]: info: ------------------------------ 2ms
May 29 02:51:04 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:51:04 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:51:04 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:51:04 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:51:04 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:51:04 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:51:04 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:51:04 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:51:04 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:51:04 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:51:04 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:51:04 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:51:04 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:51:04 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:51:04 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:51:04 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:51:04 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:51:04 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:51:04 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:51:04 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:51:04 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":83,"duration":270,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1101 Kbps","isStreaming":false,"title":"Hey Jude","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/9. Hey Jude.flac","trackType":"flac"}
May 29 02:51:04 volumio volumio[1159]: verbose: CURRENT POSITION 38
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:51:04 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:51:04 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:51:04 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:51:04 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:51:04 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:51:04 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:51:04 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:51:04 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:51:04 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:51:04 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":83,"duration":270,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1101 Kbps","isStreaming":false,"title":"Hey Jude","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/9. Hey Jude.flac","trackType":"flac"}
May 29 02:51:04 volumio volumio[1159]: verbose: CURRENT POSITION 38
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:51:04 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:51:04 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:51:04 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:51:04 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:51:04 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:51:04 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:51:04 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:51:04 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:51:04 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":83,"duration":270,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1101 Kbps","isStreaming":false,"title":"Hey Jude","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/9. Hey Jude.flac","trackType":"flac"}
May 29 02:51:04 volumio volumio[1159]: verbose: CURRENT POSITION 38
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:51:04 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:51:04 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:51:04 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:51:04 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:51:04 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:51:04 volumio volumio[1159]: info: ------------------------------ 20ms
May 29 02:51:04 volumio volumio[1159]: info: ------------------------------ 19ms
May 29 02:51:04 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:51:04 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:51:04 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:51:04 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:51:04 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:51:04 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:51:04 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:51:04 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:51:04 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:51:04 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:51:14 volumio kernel: get_swap_device: Bad swap file entry 2003ffffffffffff
May 29 02:51:14 volumio kernel: BUG: Bad page map in process upmpdcli pte:4000000000000000 pmd:180bb067
May 29 02:51:14 volumio kernel: addr:00007fcafc0e3000 vm_flags:00200070 anon_vma:0000000000000000 mapping:0000000000000000 index:7fcafc0e3
May 29 02:51:14 volumio kernel: file:(null) fault:0x0 mmap:0x0 read_folio:0x0
May 29 02:51:14 volumio kernel: CPU: 0 PID: 19791 Comm: upmpdcli Not tainted 6.6.32-volumio #2
May 29 02:51:14 volumio kernel: Hardware name: Hewlett-Packard HP ProDesk 600 G1 SFF/18E7, BIOS L01 v02.71 05/09/2017
May 29 02:51:14 volumio kernel: Call Trace:
May 29 02:51:14 volumio kernel:
May 29 02:51:14 volumio kernel: dump_stack_lvl+0x3b/0x50
May 29 02:51:14 volumio kernel: dump_stack+0x14/0x20
May 29 02:51:14 volumio kernel: print_bad_pte+0x1ad/0x280
May 29 02:51:14 volumio kernel: ? get_swap_device+0x8a/0x110
May 29 02:51:14 volumio kernel: unmap_page_range+0xc9f/0x1000
May 29 02:51:14 volumio kernel: unmap_single_vma+0x89/0xe0
May 29 02:51:14 volumio kernel: unmap_vmas+0xb9/0x180
May 29 02:51:14 volumio kernel: exit_mmap+0x103/0x380
May 29 02:51:14 volumio kernel: __mmput+0x41/0x130
May 29 02:51:14 volumio kernel: mmput+0x31/0x40
May 29 02:51:14 volumio kernel: begin_new_exec+0x4e4/0xb30
May 29 02:51:14 volumio kernel: load_elf_binary+0x2b6/0x1780
May 29 02:51:14 volumio kernel: ? __kernel_read+0x1ae/0x2c0
May 29 02:51:14 volumio kernel: bprm_execve+0x28f/0x650
May 29 02:51:14 volumio kernel: do_execveat_common.isra.0+0x1a0/0x240
May 29 02:51:14 volumio kernel: __x64_sys_execve+0x3b/0x50
May 29 02:51:14 volumio kernel: x64_sys_call+0x10b1/0x1c90
May 29 02:51:14 volumio kernel: do_syscall_64+0x39/0x90
May 29 02:51:14 volumio kernel: entry_SYSCALL_64_after_hwframe+0x78/0xe2
May 29 02:51:14 volumio kernel: RIP: 0033:0x7fcb2b311777
May 29 02:51:14 volumio kernel: Code: Unable to access opcode bytes at 0x7fcb2b31174d.
May 29 02:51:14 volumio kernel: RSP: 002b:00007fcb19ff9dc8 EFLAGS: 00000202 ORIG_RAX: 000000000000003b
May 29 02:51:14 volumio kernel: RAX: ffffffffffffffda RBX: 00007fcb19ff9e50 RCX: 00007fcb2b311777
May 29 02:51:14 volumio kernel: RDX: 00007fcaec0012b0 RSI: 00007fcaec0035e0 RDI: 00007fcb19ffa530
May 29 02:51:14 volumio kernel: RBP: 00007fcb19ff9e70 R08: 000000000000802f R09: 0000000000000000
May 29 02:51:14 volumio kernel: R10: fffffffffffff389 R11: 0000000000000202 R12: 00007fcaec0013d5
May 29 02:51:14 volumio kernel: R13: 00007fcaec000e80 R14: 00007fcb19ffa520 R15: 0000000000000000
May 29 02:51:14 volumio kernel:
May 29 02:51:14 volumio kernel: Disabling lock debugging due to kernel taint
May 29 02:51:14 volumio kernel: BUG: Bad rss-counter state mm:00000000d0783781 type:MM_SWAPENTS val:-1
May 29 02:51:29 volumio go-librespot[1678]: time="2025-05-29T02:51:29-05:00" level=trace msg="sent dealer ping"
May 29 02:51:32 volumio go-librespot[1678]: time="2025-05-29T02:51:32-05:00" level=trace msg="received dealer pong"
May 29 02:51:59 volumio go-librespot[1678]: time="2025-05-29T02:51:59-05:00" level=trace msg="sent dealer ping"
May 29 02:51:59 volumio go-librespot[1678]: time="2025-05-29T02:51:59-05:00" level=trace msg="received dealer pong"
May 29 02:52:29 volumio go-librespot[1678]: time="2025-05-29T02:52:29-05:00" level=trace msg="sent dealer ping"
May 29 02:52:32 volumio go-librespot[1678]: time="2025-05-29T02:52:32-05:00" level=trace msg="received dealer pong"
May 29 02:52:32 volumio go-librespot[1678]: time="2025-05-29T02:52:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:52:32 volumio go-librespot[1678]: time="2025-05-29T02:52:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:52:59 volumio go-librespot[1678]: time="2025-05-29T02:52:59-05:00" level=trace msg="sent dealer ping"
May 29 02:52:59 volumio go-librespot[1678]: time="2025-05-29T02:52:59-05:00" level=trace msg="received dealer pong"
May 29 02:53:29 volumio go-librespot[1678]: time="2025-05-29T02:53:29-05:00" level=trace msg="sent dealer ping"
May 29 02:53:30 volumio go-librespot[1678]: time="2025-05-29T02:53:30-05:00" level=trace msg="received dealer pong"
May 29 02:53:59 volumio go-librespot[1678]: time="2025-05-29T02:53:59-05:00" level=trace msg="sent dealer ping"
May 29 02:53:59 volumio go-librespot[1678]: time="2025-05-29T02:53:59-05:00" level=trace msg="received dealer pong"
May 29 02:54:29 volumio go-librespot[1678]: time="2025-05-29T02:54:29-05:00" level=trace msg="sent dealer ping"
May 29 02:54:30 volumio go-librespot[1678]: time="2025-05-29T02:54:30-05:00" level=trace msg="received dealer pong"
May 29 02:54:32 volumio go-librespot[1678]: time="2025-05-29T02:54:32-05:00" level=trace msg="received accesspoint ping"
May 29 02:54:32 volumio go-librespot[1678]: time="2025-05-29T02:54:32-05:00" level=trace msg="received accesspoint pong ack"
May 29 02:54:38 volumio systemd[1]: upmpdcli.service: Main process exited, code=killed, status=11/SEGV
May 29 02:54:38 volumio systemd[1]: upmpdcli.service: Failed with result 'signal'.
May 29 02:54:38 volumio kernel: traps: upmpdcli[20658] general protection fault ip:7fcb2b2cae2e sp:7fcb19ff9b70 error:0 in libc-2.28.so[7fcb2b26d000+147000]
May 29 02:54:38 volumio kernel: traps: upmpdcli[4324] general protection fault ip:7fcb2b2cae2e sp:7fcb19ffa240 error:0 in libc-2.28.so[7fcb2b26d000+147000]
May 29 02:54:59 volumio go-librespot[1678]: time="2025-05-29T02:54:59-05:00" level=trace msg="sent dealer ping"
May 29 02:54:59 volumio go-librespot[1678]: time="2025-05-29T02:54:59-05:00" level=trace msg="received dealer pong"
May 29 02:55:29 volumio volumio[1159]: info: CorePlayQueue::getTrack 38
May 29 02:55:29 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:29 volumio volumio[1159]: info: Prefetching next song
May 29 02:55:29 volumio volumio[1159]: info: DOING PREFETCH IN MPD
May 29 02:55:29 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love V/6. Hotel California.flac"
May 29 02:55:29 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love V/6. Hotel California.flac" took 1 milliseconds
May 29 02:55:29 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand consume 1
May 29 02:55:29 volumio volumio[1159]: info:
May 29 02:55:29 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:55:29 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:55:29 volumio volumio[1159]: info: sendMpdCommand consume 1 took 0 milliseconds
May 29 02:55:29 volumio volumio[1159]: Upnp client error: Error: This socket has been ended by the other party
May 29 02:55:29 volumio volumio[1159]: info:
May 29 02:55:29 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:55:29 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:55:29 volumio volumio[1159]: info:
May 29 02:55:29 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:55:29 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:55:29 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:55:29 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:55:29 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:55:29 volumio go-librespot[1678]: time="2025-05-29T02:55:29-05:00" level=trace msg="sent dealer ping"
May 29 02:55:30 volumio go-librespot[1678]: time="2025-05-29T02:55:30-05:00" level=trace msg="received dealer pong"
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:55:33 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:33 volumio volumio[1159]: info:
May 29 02:55:33 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:55:33 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:55:33 volumio volumio[1159]: info:
May 29 02:55:33 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:55:33 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:55:33 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:55:33 volumio volumio[1159]: info:
May 29 02:55:33 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:55:33 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:55:33 volumio volumio[1159]: info:
May 29 02:55:33 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:55:33 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:55:33 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:55:33 volumio volumio[1159]: info:
May 29 02:55:33 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:55:33 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:55:33 volumio volumio[1159]: info:
May 29 02:55:33 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:55:33 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:55:33 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:55:33 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:55:33 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:55:33 volumio volumio[1159]: info: ------------------------------ 0ms
May 29 02:55:33 volumio volumio[1159]: info: sendMpdCommand status took 0 milliseconds
May 29 02:55:33 volumio volumio[1159]: info: ------------------------------ 1ms
May 29 02:55:33 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:55:33 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:55:33 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:55:33 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:55:33 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:55:33 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:55:33 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:55:33 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:55:33 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:55:33 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 0 milliseconds
May 29 02:55:33 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:55:33 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:55:33 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:55:33 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:55:33 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:55:33 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:33 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":20,"duration":381,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1276 Kbps","isStreaming":false,"title":"Hotel California","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/6. Hotel California.flac","trackType":"flac"}
May 29 02:55:33 volumio volumio[1159]: verbose: CURRENT POSITION 35
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:55:33 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:33 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:33 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:33 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:33 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:33 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:33 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:55:33 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:55:33 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:33 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":20,"duration":381,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1276 Kbps","isStreaming":false,"title":"Hotel California","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/6. Hotel California.flac","trackType":"flac"}
May 29 02:55:33 volumio volumio[1159]: verbose: CURRENT POSITION 35
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:55:33 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:33 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:33 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:33 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:33 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:33 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:55:33 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:55:33 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:33 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":20,"duration":381,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1276 Kbps","isStreaming":false,"title":"Hotel California","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/6. Hotel California.flac","trackType":"flac"}
May 29 02:55:33 volumio volumio[1159]: verbose: CURRENT POSITION 35
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:55:33 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:33 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:33 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:33 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:33 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:33 volumio volumio[1159]: info: ------------------------------ 17ms
May 29 02:55:33 volumio volumio[1159]: info: ------------------------------ 16ms
May 29 02:55:33 volumio volumio[1159]: info: ------------------------------ 17ms
May 29 02:55:33 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:55:33 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:55:33 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:55:33 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:55:33 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:55:33 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:55:33 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:33 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:33 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:33 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:33 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80
May 29 02:55:40 volumio volumio[1159]: info: VolumeController::SetAlsaVolume12
May 29 02:55:40 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:40 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:40 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:40 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:40 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 12
May 29 02:55:40 volumio volumio[1159]: SPOTIFY: SPOTIFY VOLUME 80
May 29 02:55:40 volumio volumio[1159]: SPOTIFY: VOLUMIO VOLUME 12
May 29 02:55:40 volumio volumio[1159]: SPOTIFY: DELTA VOLUME ENOUGH: true
May 29 02:55:40 volumio volumio[1159]: info: Setting Spotify Volume from Volumio: 12
May 29 02:55:41 volumio volumio[1159]: SPOTIFY: SETTING SPOTIFY VOLUME 12
May 29 02:55:41 volumio volumio[1159]: info: Sending Spotify command with payload to local API: /player/volume
May 29 02:55:41 volumio go-librespot[1678]: time="2025-05-29T02:55:41-05:00" level=debug msg="update volume to 7864/65535"
May 29 02:55:41 volumio volumio[1159]: info: VolumeController::SetAlsaVolume20
May 29 02:55:41 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:41 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:41 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:41 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:41 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:41 volumio volumio[1159]: SPOTIFY: SPOTIFY VOLUME 12
May 29 02:55:41 volumio volumio[1159]: SPOTIFY: VOLUMIO VOLUME 20
May 29 02:55:41 volumio volumio[1159]: SPOTIFY: DELTA VOLUME ENOUGH: true
May 29 02:55:41 volumio volumio[1159]: info: Setting Spotify Volume from Volumio: 20
May 29 02:55:42 volumio go-librespot[1678]: time="2025-05-29T02:55:42-05:00" level=debug msg="renewing login5 access token"
May 29 02:55:42 volumio go-librespot[1678]: time="2025-05-29T02:55:42-05:00" level=info msg="authenticated Login5 as txqeumjpo0e2sqzbg8ea9kho7"
May 29 02:55:42 volumio go-librespot[1678]: time="2025-05-29T02:55:42-05:00" level=debug msg="put connect state because VOLUME_CHANGED"
May 29 02:55:42 volumio go-librespot[1678]: time="2025-05-29T02:55:42-05:00" level=trace msg="emitting websocket event: volume"
May 29 02:55:42 volumio volumio[1159]: SPOTIFY: received: {"type":"volume","data":{"value":12,"max":100}}
May 29 02:55:42 volumio volumio[1159]: SPOTIFY: RECEIVED SPOTIFY VOLUME 12
May 29 02:55:42 volumio volumio[1159]: info: Setting Volumio Volume from Spotify: 12
May 29 02:55:42 volumio volumio[1159]: info: VolumeController::SetAlsaVolume12
May 29 02:55:42 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:42 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:42 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:42 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:42 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 12
May 29 02:55:43 volumio volumio[1159]: SPOTIFY: SETTING SPOTIFY VOLUME 20
May 29 02:55:43 volumio volumio[1159]: info: Sending Spotify command with payload to local API: /player/volume
May 29 02:55:43 volumio go-librespot[1678]: time="2025-05-29T02:55:43-05:00" level=debug msg="update volume to 13107/65535"
May 29 02:55:44 volumio go-librespot[1678]: time="2025-05-29T02:55:44-05:00" level=debug msg="put connect state because VOLUME_CHANGED"
May 29 02:55:44 volumio go-librespot[1678]: time="2025-05-29T02:55:44-05:00" level=trace msg="emitting websocket event: volume"
May 29 02:55:44 volumio volumio[1159]: SPOTIFY: received: {"type":"volume","data":{"value":20,"max":100}}
May 29 02:55:44 volumio volumio[1159]: SPOTIFY: RECEIVED SPOTIFY VOLUME 20
May 29 02:55:44 volumio volumio[1159]: info: Setting Volumio Volume from Spotify: 20
May 29 02:55:44 volumio volumio[1159]: info: VolumeController::SetAlsaVolume20
May 29 02:55:44 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:44 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:44 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:44 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:44 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioNext
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::next
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::stop
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::setConsumeUpdateService undefined
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::stPlaybackTimer
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::updateTrackBlock
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrackBlock
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::serviceStop
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 35
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::serviceStop
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::stop
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand stop
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand stop took 4 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::play index undefined
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::setConsumeUpdateService undefined
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::startPlaybackTimer
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::clearAddPlayTracks USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/9. No Matter What.flac
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand stop
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::updateTrackBlock
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrackBlock
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand status took 2 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand stop took 1 milliseconds
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand clear
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:55:47 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 1 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand clear took 1 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/9. No Matter What.flac"
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Hotel California","artist":"Yao Si Ting","album":"Endless Love V","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love V/6. Hotel California.flac","trackType":"flac"}
May 29 02:55:47 volumio volumio[1159]: verbose: CURRENT POSITION 25
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState stateService stop
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus stop
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: No code
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null}
May 29 02:55:47 volumio volumio[1159]: verbose: CURRENT POSITION 25
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState stateService stop
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus stop
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: No code
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null}
May 29 02:55:47 volumio volumio[1159]: verbose: CURRENT POSITION 25
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState stateService stop
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus stop
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: No code
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 26ms
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 25ms
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 24ms
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:55:47 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:55:47 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:55:47 volumio volumio[1159]: error: updateQueue error: null
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:55:47 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 25ms
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand add "USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/9. No Matter What.flac" took 24 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 2ms
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 2ms
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand play
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:55:47 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces system playlist update
May 29 02:55:47 volumio volumio[1159]: info: Ignoring MPD Status Update
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 6ms
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand play took 4 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 4ms
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 4ms
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:55:47 volumio volumio[1159]: info: FusionDsp - ---- read samplerate, raw: 48000,S32_LE,2,32
May 29 02:55:47 volumio volumio[1159]: info: FusionDsp - ---- read samplerate from file: 48000
May 29 02:55:47 volumio volumio[1159]: info: FusionDsp - If filter freq >samplerate/2 then disable it
May 29 02:55:47 volumio volumio[1159]: info: FusionDsp - crossfeed linkwitz
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand status took 10 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand status took 10 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand status took 9 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:55:47 volumio volumio[1159]: info:
May 29 02:55:47 volumio volumio[1159]: ---------------------------- MPD announces state update: player
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::getState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand status
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand status took 2 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 2 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 2 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 2 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand status took 1 milliseconds
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseState
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::sendMpdCommand playlistinfo
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":254,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"No Matter What","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/9. No Matter What.flac","trackType":"flac"}
May 29 02:55:47 volumio volumio[1159]: verbose: CURRENT POSITION 25
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus stop
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":254,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"No Matter What","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/9. No Matter What.flac","trackType":"flac"}
May 29 02:55:47 volumio volumio[1159]: verbose: CURRENT POSITION 25
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:55:47 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":254,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"No Matter What","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/9. No Matter What.flac","trackType":"flac"}
May 29 02:55:47 volumio volumio[1159]: verbose: CURRENT POSITION 25
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:55:47 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 17ms
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 24ms
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 24ms
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 14 milliseconds
May 29 02:55:47 volumio volumio[1159]: info: sendMpdCommand playlistinfo took 15 milliseconds
May 29 02:55:47 volumio volumio[1159]: verbose: ControllerMpd::parseTrackInfo
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":254,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"No Matter What","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/9. No Matter What.flac","trackType":"flac"}
May 29 02:55:47 volumio volumio[1159]: verbose: CURRENT POSITION 25
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:55:47 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":254,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"No Matter What","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/9. No Matter What.flac","trackType":"flac"}
May 29 02:55:47 volumio volumio[1159]: verbose: CURRENT POSITION 25
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:55:47 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: ControllerMpd::pushState
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::servicePushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":254,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"No Matter What","artist":"Yao Si Ting","album":"Endless Love II","uri":"USB/MEMORIA_USB/Yao Si Ting - Endless Love IV/9. No Matter What.flac","trackType":"flac"}
May 29 02:55:47 volumio volumio[1159]: verbose: CURRENT POSITION 25
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState stateService play
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::syncState currentStatus play
May 29 02:55:47 volumio volumio[1159]: info: Received an update from plugin. extracting info from payload
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:47 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:47 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 40ms
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 39ms
May 29 02:55:47 volumio volumio[1159]: info: ------------------------------ 39ms
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20
May 29 02:55:47 volumio volumio[1159]: info: FusionDsp - {"Reload":{"result":"Ok"}}
May 29 02:55:52 volumio volumio[1159]: info: VolumeController::SetAlsaVolume42
May 29 02:55:52 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:52 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:52 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:52 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:52 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 42
May 29 02:55:52 volumio volumio[1159]: SPOTIFY: SPOTIFY VOLUME 20
May 29 02:55:52 volumio volumio[1159]: SPOTIFY: VOLUMIO VOLUME 42
May 29 02:55:52 volumio volumio[1159]: SPOTIFY: DELTA VOLUME ENOUGH: true
May 29 02:55:52 volumio volumio[1159]: info: Setting Spotify Volume from Volumio: 42
May 29 02:55:53 volumio volumio[1159]: info: VolumeController::SetAlsaVolume48
May 29 02:55:53 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:53 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:53 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:53 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:53 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48
May 29 02:55:53 volumio volumio[1159]: SPOTIFY: SPOTIFY VOLUME 42
May 29 02:55:53 volumio volumio[1159]: SPOTIFY: VOLUMIO VOLUME 48
May 29 02:55:53 volumio volumio[1159]: SPOTIFY: DELTA VOLUME ENOUGH: true
May 29 02:55:53 volumio volumio[1159]: info: Setting Spotify Volume from Volumio: 48
May 29 02:55:54 volumio volumio[1159]: info: VolumeController::SetAlsaVolume29
May 29 02:55:54 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:54 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:54 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:54 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:54 volumio volumio[1159]: SPOTIFY: RECEIVED VOLUMIO VOLUME 29
May 29 02:55:54 volumio volumio[1159]: SPOTIFY: SPOTIFY VOLUME 48
May 29 02:55:54 volumio volumio[1159]: SPOTIFY: VOLUMIO VOLUME 29
May 29 02:55:54 volumio volumio[1159]: SPOTIFY: DELTA VOLUME ENOUGH: true
May 29 02:55:54 volumio volumio[1159]: info: Setting Spotify Volume from Volumio: 29
May 29 02:55:54 volumio volumio[1159]: info: VolumeController::SetAlsaVolume28
May 29 02:55:54 volumio volumio[1159]: info: CoreStateMachine::pushState
May 29 02:55:54 volumio volumio[1159]: info: CorePlayQueue::getTrack 25
May 29 02:55:54 volumio volumio[1159]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 29 02:55:54 volumio volumio[1159]: info: CoreCommandRouter::volumioPushState
May 29 02:55:54 volumio volumio[1159]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
May 29 02:55:54 volumio volumio[1159]: Error: invalid payload
May 29 02:55:54 volumio volumio[1159]: at decodeString (/data/plugins/audio_interface/fusiondsp/node_modules/socket.io-parser/index.js:355:13)
May 29 02:55:54 volumio volumio[1159]: at Decoder.add (/data/plugins/audio_interface/fusiondsp/node_modules/socket.io-parser/index.js:245:14)
May 29 02:55:54 volumio volumio[1159]: at Manager.ondata (/data/plugins/audio_interface/fusiondsp/node_modules/socket.io-client/lib/manager.js:339:16)
May 29 02:55:54 volumio volumio[1159]: at Socket. (/data/plugins/audio_interface/fusiondsp/node_modules/component-bind/index.js:21:15)
May 29 02:55:54 volumio volumio[1159]: at Socket.Emitter.emit (/data/plugins/audio_interface/fusiondsp/node_modules/component-emitter/index.js:145:20)
May 29 02:55:54 volumio volumio[1159]: at Socket.onPacket (/data/plugins/audio_interface/fusiondsp/node_modules/engine.io-client/lib/socket.js:461:14)
May 29 02:55:54 volumio volumio[1159]: at WS. (/data/plugins/audio_interface/fusiondsp/node_modules/engine.io-client/lib/socket.js:278:10)
May 29 02:55:54 volumio volumio[1159]: at WS.Emitter.emit (/data/plugins/audio_interface/fusiondsp/node_modules/component-emitter/index.js:145:20)
May 29 02:55:54 volumio volumio[1159]: at WS.Transport.onPacket (/data/plugins/audio_interface/fusiondsp/node_modules/engine.io-client/lib/transport.js:149:8)
May 29 02:55:54 volumio volumio[1159]: at WS.Transport.onData (/data/plugins/audio_interface/fusiondsp/node_modules/engine.io-client/lib/transport.js:141:8)
May 29 02:55:54 volumio volumio[1159]: at WebSocket.ws.onmessage (/data/plugins/audio_interface/fusiondsp/node_modules/engine.io-client/lib/transports/websocket.js:160:10)
May 29 02:55:54 volumio volumio[1159]: at WebSocket.onMessage (/data/plugins/audio_interface/fusiondsp/node_modules/ws/lib/event-target.js:132:16)
May 29 02:55:54 volumio volumio[1159]: at WebSocket.emit (events.js:400:28)
May 29 02:55:54 volumio volumio[1159]: at Receiver.receiverOnMessage (/data/plugins/audio_interface/fusiondsp/node_modules/ws/lib/websocket.js:1070:20)
May 29 02:55:54 volumio volumio[1159]: at Receiver.emit (events.js:400:28)
May 29 02:55:54 volumio volumio[1159]: at Receiver.dataMessage (/data/plugins/audio_interface/fusiondsp/node_modules/ws/lib/receiver.js:517:14)
May 29 02:55:54 volumio volumio[1159]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
May 29 02:55:54 volumio sudo[20898]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-29 01:54
May 29 02:55:54 volumio sudo[20898]: 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="570c5791513f5bac7da274aba6690c1a961705de"
VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6"
VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a"
VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d"
VOLUMIO_ARCH="x64"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:50:12 PM CEST"
VOLUMIO_VERSION="3.812"
VOLUMIO_HARDWARE="x86_amd64"
VOLUMIO_DEVICENAME="x86_64"
VOLUMIO_HASH="39b0f8c200b2dcadf117e189b4b3632d"