-- Logs begin at Fri 2025-08-29 19:43:54 WIB, end at Fri 2025-08-29 19:48:44 WIB. -- Aug 29 19:47:00 volumio go-librespot[1753]: time="2025-08-29T19:47:00+07:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 19:47:00 volumio go-librespot[1753]: time="2025-08-29T19:47:00+07:00" level=trace msg="emitting websocket event: volume" Aug 29 19:47:00 volumio volumio[1298]: SPOTIFY: received: {"type":"volume","data":{"value":91,"max":100}} Aug 29 19:47:00 volumio volumio[1298]: SPOTIFY: RECEIVED SPOTIFY VOLUME 91 Aug 29 19:47:01 volumio volumio[1298]: info: VolumeController::SetAlsaVolume88 Aug 29 19:47:01 volumio volumio[1298]: info: CoreStateMachine::pushState Aug 29 19:47:01 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:47:01 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 19:47:01 volumio volumio[1298]: info: CoreCommandRouter::volumioPushState Aug 29 19:47:01 volumio volumio[1298]: SPOTIFY: RECEIVED VOLUMIO VOLUME 88 Aug 29 19:47:01 volumio volumio[1298]: SPOTIFY: SPOTIFY VOLUME 91 Aug 29 19:47:01 volumio volumio[1298]: SPOTIFY: VOLUMIO VOLUME 88 Aug 29 19:47:01 volumio volumio[1298]: SPOTIFY: DELTA VOLUME ENOUGH: true Aug 29 19:47:01 volumio volumio[1298]: info: Setting Spotify Volume from Volumio: 88 Aug 29 19:47:02 volumio volumio[1298]: SPOTIFY: SETTING SPOTIFY VOLUME 88 Aug 29 19:47:02 volumio volumio[1298]: info: Sending Spotify command with payload to local API: /player/volume Aug 29 19:47:02 volumio go-librespot[1753]: time="2025-08-29T19:47:02+07:00" level=debug msg="update volume requested to 57670/65535" Aug 29 19:47:03 volumio go-librespot[1753]: time="2025-08-29T19:47:03+07:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 19:47:03 volumio go-librespot[1753]: time="2025-08-29T19:47:03+07:00" level=trace msg="emitting websocket event: volume" Aug 29 19:47:03 volumio volumio[1298]: SPOTIFY: received: {"type":"volume","data":{"value":88,"max":100}} Aug 29 19:47:03 volumio volumio[1298]: SPOTIFY: RECEIVED SPOTIFY VOLUME 88 Aug 29 19:47:25 volumio go-librespot[1753]: time="2025-08-29T19:47:25+07:00" level=trace msg="sent dealer ping" Aug 29 19:47:26 volumio go-librespot[1753]: time="2025-08-29T19:47:26+07:00" level=trace msg="received dealer pong" Aug 29 19:47:28 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 19:47:28 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 19:47:28 volumio volumio[1298]: info: Discovery: Getting this device information Aug 29 19:47:28 volumio volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 29 19:47:28 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:47:28 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 19:47:29 volumio volumio[1298]: info: VolumeController::SetAlsaVolume90 Aug 29 19:47:29 volumio volumio[1298]: info: CoreStateMachine::pushState Aug 29 19:47:29 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:47:29 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 19:47:29 volumio volumio[1298]: info: CoreCommandRouter::volumioPushState Aug 29 19:47:29 volumio volumio[1298]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 29 19:47:29 volumio volumio[1298]: SPOTIFY: SPOTIFY VOLUME 88 Aug 29 19:47:29 volumio volumio[1298]: SPOTIFY: VOLUMIO VOLUME 90 Aug 29 19:47:29 volumio volumio[1298]: SPOTIFY: DELTA VOLUME ENOUGH: true Aug 29 19:47:29 volumio volumio[1298]: info: Setting Spotify Volume from Volumio: 90 Aug 29 19:47:31 volumio volumio[1298]: info: VolumeController::SetAlsaVolume96 Aug 29 19:47:31 volumio volumio[1298]: info: CoreStateMachine::pushState Aug 29 19:47:31 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:47:31 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 19:47:31 volumio volumio[1298]: info: CoreCommandRouter::volumioPushState Aug 29 19:47:31 volumio volumio[1298]: SPOTIFY: RECEIVED VOLUMIO VOLUME 96 Aug 29 19:47:31 volumio volumio[1298]: SPOTIFY: SPOTIFY VOLUME 90 Aug 29 19:47:31 volumio volumio[1298]: SPOTIFY: VOLUMIO VOLUME 96 Aug 29 19:47:31 volumio volumio[1298]: SPOTIFY: DELTA VOLUME ENOUGH: true Aug 29 19:47:31 volumio volumio[1298]: info: Setting Spotify Volume from Volumio: 96 Aug 29 19:47:32 volumio volumio[1298]: SPOTIFY: SETTING SPOTIFY VOLUME 96 Aug 29 19:47:32 volumio volumio[1298]: info: Sending Spotify command with payload to local API: /player/volume Aug 29 19:47:32 volumio go-librespot[1753]: time="2025-08-29T19:47:32+07:00" level=debug msg="update volume requested to 62913/65535" Aug 29 19:47:33 volumio go-librespot[1753]: time="2025-08-29T19:47:33+07:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 19:47:33 volumio go-librespot[1753]: time="2025-08-29T19:47:33+07:00" level=trace msg="emitting websocket event: volume" Aug 29 19:47:33 volumio volumio[1298]: SPOTIFY: received: {"type":"volume","data":{"value":96,"max":100}} Aug 29 19:47:33 volumio volumio[1298]: SPOTIFY: RECEIVED SPOTIFY VOLUME 96 Aug 29 19:47:33 volumio volumio[1298]: info: VolumeController::SetAlsaVolume95 Aug 29 19:47:33 volumio volumio[1298]: info: CoreStateMachine::pushState Aug 29 19:47:33 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:47:33 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 19:47:33 volumio volumio[1298]: info: CoreCommandRouter::volumioPushState Aug 29 19:47:33 volumio volumio[1298]: SPOTIFY: RECEIVED VOLUMIO VOLUME 95 Aug 29 19:47:33 volumio volumio[1298]: SPOTIFY: SPOTIFY VOLUME 96 Aug 29 19:47:33 volumio volumio[1298]: SPOTIFY: VOLUMIO VOLUME 95 Aug 29 19:47:33 volumio volumio[1298]: SPOTIFY: DELTA VOLUME ENOUGH: false Aug 29 19:47:34 volumio volumio[1298]: info: VolumeController::SetAlsaVolume93 Aug 29 19:47:34 volumio volumio[1298]: info: CoreStateMachine::pushState Aug 29 19:47:34 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:47:34 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 19:47:34 volumio volumio[1298]: info: CoreCommandRouter::volumioPushState Aug 29 19:47:34 volumio volumio[1298]: SPOTIFY: RECEIVED VOLUMIO VOLUME 93 Aug 29 19:47:34 volumio volumio[1298]: SPOTIFY: SPOTIFY VOLUME 96 Aug 29 19:47:34 volumio volumio[1298]: SPOTIFY: VOLUMIO VOLUME 93 Aug 29 19:47:34 volumio volumio[1298]: SPOTIFY: DELTA VOLUME ENOUGH: true Aug 29 19:47:34 volumio volumio[1298]: info: Setting Spotify Volume from Volumio: 93 Aug 29 19:47:35 volumio volumio[1298]: SPOTIFY: SETTING SPOTIFY VOLUME 93 Aug 29 19:47:35 volumio volumio[1298]: info: Sending Spotify command with payload to local API: /player/volume Aug 29 19:47:35 volumio go-librespot[1753]: time="2025-08-29T19:47:35+07:00" level=debug msg="update volume requested to 60947/65535" Aug 29 19:47:36 volumio go-librespot[1753]: time="2025-08-29T19:47:36+07:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 19:47:36 volumio go-librespot[1753]: time="2025-08-29T19:47:36+07:00" level=trace msg="emitting websocket event: volume" Aug 29 19:47:36 volumio volumio[1298]: SPOTIFY: received: {"type":"volume","data":{"value":93,"max":100}} Aug 29 19:47:36 volumio volumio[1298]: SPOTIFY: RECEIVED SPOTIFY VOLUME 93 Aug 29 19:47:55 volumio go-librespot[1753]: time="2025-08-29T19:47:55+07:00" level=trace msg="sent dealer ping" Aug 29 19:47:56 volumio go-librespot[1753]: time="2025-08-29T19:47:56+07:00" level=trace msg="received dealer pong" Aug 29 19:47:58 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 19:47:58 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 19:47:58 volumio volumio[1298]: info: Discovery: Getting this device information Aug 29 19:47:58 volumio volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 29 19:47:58 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:47:58 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 19:48:02 volumio volumio[1298]: info: VolumeController::SetAlsaVolume88 Aug 29 19:48:02 volumio volumio[1298]: info: CoreStateMachine::pushState Aug 29 19:48:02 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:02 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 19:48:02 volumio volumio[1298]: info: CoreCommandRouter::volumioPushState Aug 29 19:48:02 volumio volumio[1298]: SPOTIFY: RECEIVED VOLUMIO VOLUME 88 Aug 29 19:48:02 volumio volumio[1298]: SPOTIFY: SPOTIFY VOLUME 93 Aug 29 19:48:02 volumio volumio[1298]: SPOTIFY: VOLUMIO VOLUME 88 Aug 29 19:48:02 volumio volumio[1298]: SPOTIFY: DELTA VOLUME ENOUGH: true Aug 29 19:48:02 volumio volumio[1298]: info: Setting Spotify Volume from Volumio: 88 Aug 29 19:48:02 volumio volumio[1298]: info: VolumeController::SetAlsaVolume82 Aug 29 19:48:02 volumio volumio[1298]: info: CoreStateMachine::pushState Aug 29 19:48:02 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:02 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 19:48:02 volumio volumio[1298]: info: CoreCommandRouter::volumioPushState Aug 29 19:48:02 volumio volumio[1298]: SPOTIFY: RECEIVED VOLUMIO VOLUME 82 Aug 29 19:48:02 volumio volumio[1298]: SPOTIFY: SPOTIFY VOLUME 88 Aug 29 19:48:02 volumio volumio[1298]: SPOTIFY: VOLUMIO VOLUME 82 Aug 29 19:48:02 volumio volumio[1298]: SPOTIFY: DELTA VOLUME ENOUGH: true Aug 29 19:48:02 volumio volumio[1298]: info: Setting Spotify Volume from Volumio: 82 Aug 29 19:48:04 volumio volumio[1298]: SPOTIFY: SETTING SPOTIFY VOLUME 82 Aug 29 19:48:04 volumio volumio[1298]: info: Sending Spotify command with payload to local API: /player/volume Aug 29 19:48:04 volumio go-librespot[1753]: time="2025-08-29T19:48:04+07:00" level=debug msg="update volume requested to 53738/65535" Aug 29 19:48:04 volumio go-librespot[1753]: time="2025-08-29T19:48:04+07:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 19:48:04 volumio go-librespot[1753]: time="2025-08-29T19:48:04+07:00" level=trace msg="emitting websocket event: volume" Aug 29 19:48:04 volumio volumio[1298]: SPOTIFY: received: {"type":"volume","data":{"value":82,"max":100}} Aug 29 19:48:04 volumio volumio[1298]: SPOTIFY: RECEIVED SPOTIFY VOLUME 82 Aug 29 19:48:12 volumio volumio[1298]: info: VolumeController::SetAlsaVolume79 Aug 29 19:48:12 volumio volumio[1298]: info: CoreStateMachine::pushState Aug 29 19:48:12 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:12 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 19:48:12 volumio volumio[1298]: info: CoreCommandRouter::volumioPushState Aug 29 19:48:12 volumio volumio[1298]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Aug 29 19:48:12 volumio volumio[1298]: SPOTIFY: SPOTIFY VOLUME 82 Aug 29 19:48:12 volumio volumio[1298]: SPOTIFY: VOLUMIO VOLUME 79 Aug 29 19:48:12 volumio volumio[1298]: SPOTIFY: DELTA VOLUME ENOUGH: true Aug 29 19:48:12 volumio volumio[1298]: info: Setting Spotify Volume from Volumio: 79 Aug 29 19:48:12 volumio volumio[1298]: info: VolumeController::SetAlsaVolume72 Aug 29 19:48:12 volumio volumio[1298]: info: CoreStateMachine::pushState Aug 29 19:48:12 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:12 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 19:48:12 volumio volumio[1298]: info: CoreCommandRouter::volumioPushState Aug 29 19:48:12 volumio volumio[1298]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Aug 29 19:48:12 volumio volumio[1298]: SPOTIFY: SPOTIFY VOLUME 79 Aug 29 19:48:12 volumio volumio[1298]: SPOTIFY: VOLUMIO VOLUME 72 Aug 29 19:48:12 volumio volumio[1298]: SPOTIFY: DELTA VOLUME ENOUGH: true Aug 29 19:48:12 volumio volumio[1298]: info: Setting Spotify Volume from Volumio: 72 Aug 29 19:48:13 volumio volumio[1298]: SPOTIFY: SETTING SPOTIFY VOLUME 72 Aug 29 19:48:13 volumio volumio[1298]: info: Sending Spotify command with payload to local API: /player/volume Aug 29 19:48:13 volumio go-librespot[1753]: time="2025-08-29T19:48:13+07:00" level=debug msg="update volume requested to 47185/65535" Aug 29 19:48:14 volumio go-librespot[1753]: time="2025-08-29T19:48:14+07:00" level=debug msg="put connect state because VOLUME_CHANGED" Aug 29 19:48:14 volumio go-librespot[1753]: time="2025-08-29T19:48:14+07:00" level=trace msg="emitting websocket event: volume" Aug 29 19:48:14 volumio volumio[1298]: SPOTIFY: received: {"type":"volume","data":{"value":72,"max":100}} Aug 29 19:48:14 volumio volumio[1298]: SPOTIFY: RECEIVED SPOTIFY VOLUME 72 Aug 29 19:48:15 volumio volumio[1298]: info: CoreCommandRouter::volumioPause Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::pause Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::stPlaybackTimer Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::servicePause Aug 29 19:48:15 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:15 volumio volumio[1298]: info: CoreCommandRouter::servicePause Aug 29 19:48:15 volumio volumio[1298]: info: ControllerMpd::pause Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::sendMpdCommand pause Aug 29 19:48:15 volumio volumio[1298]: info: sendMpdCommand pause took 0 milliseconds Aug 29 19:48:15 volumio volumio[1298]: info: Aug 29 19:48:15 volumio volumio[1298]: ---------------------------- MPD announces state update: player Aug 29 19:48:15 volumio volumio[1298]: info: ControllerMpd::getState Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::sendMpdCommand status Aug 29 19:48:15 volumio volumio[1298]: info: Aug 29 19:48:15 volumio volumio[1298]: ---------------------------- MPD announces state update: player Aug 29 19:48:15 volumio volumio[1298]: info: ControllerMpd::getState Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::sendMpdCommand status Aug 29 19:48:15 volumio volumio[1298]: info: Aug 29 19:48:15 volumio volumio[1298]: ---------------------------- MPD announces state update: player Aug 29 19:48:15 volumio volumio[1298]: info: ControllerMpd::getState Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::sendMpdCommand status Aug 29 19:48:15 volumio volumio[1298]: info: sendMpdCommand status took 1 milliseconds Aug 29 19:48:15 volumio volumio[1298]: info: sendMpdCommand status took 1 milliseconds Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::parseState Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::parseState Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 19:48:15 volumio volumio[1298]: info: sendMpdCommand status took 2 milliseconds Aug 29 19:48:15 volumio volumio[1298]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 29 19:48:15 volumio volumio[1298]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::parseState Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::parseTrackInfo Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::parseTrackInfo Aug 29 19:48:15 volumio volumio[1298]: info: ControllerMpd::pushState Aug 29 19:48:15 volumio volumio[1298]: info: CoreCommandRouter::servicePushState Aug 29 19:48:15 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:15 volumio volumio[1298]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":180754,"duration":276,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Popsicle Toes","artist":"Michael Franks","album":"The Best Of Michael Franks: A Backward Glance","uri":"USB/0A6A-0F5D/The Best Of Michael Franks- A Backward Glance/01 Popsicle Toes.mp3","trackType":"mp3"} Aug 29 19:48:15 volumio volumio[1298]: verbose: CURRENT POSITION 0 Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::syncState stateService pause Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::syncState currentStatus pause Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::pushState Aug 29 19:48:15 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:15 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 19:48:15 volumio volumio[1298]: info: CoreCommandRouter::volumioPushState Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::stPlaybackTimer Aug 29 19:48:15 volumio volumio[1298]: info: ControllerMpd::pushState Aug 29 19:48:15 volumio volumio[1298]: info: CoreCommandRouter::servicePushState Aug 29 19:48:15 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:15 volumio volumio[1298]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":180754,"duration":276,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Popsicle Toes","artist":"Michael Franks","album":"The Best Of Michael Franks: A Backward Glance","uri":"USB/0A6A-0F5D/The Best Of Michael Franks- A Backward Glance/01 Popsicle Toes.mp3","trackType":"mp3"} Aug 29 19:48:15 volumio volumio[1298]: verbose: CURRENT POSITION 0 Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::syncState stateService pause Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::syncState currentStatus pause Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::pushState Aug 29 19:48:15 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:15 volumio volumio[1298]: info: CoreCommandRouter::volumioPushState Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::stPlaybackTimer Aug 29 19:48:15 volumio volumio[1298]: info: ------------------------------ 17ms Aug 29 19:48:15 volumio volumio[1298]: info: ------------------------------ 16ms Aug 29 19:48:15 volumio volumio[1298]: info: sendMpdCommand playlistinfo took 13 milliseconds Aug 29 19:48:15 volumio volumio[1298]: verbose: ControllerMpd::parseTrackInfo Aug 29 19:48:15 volumio volumio[1298]: info: ControllerMpd::pushState Aug 29 19:48:15 volumio volumio[1298]: info: CoreCommandRouter::servicePushState Aug 29 19:48:15 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:15 volumio volumio[1298]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":180754,"duration":276,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Popsicle Toes","artist":"Michael Franks","album":"The Best Of Michael Franks: A Backward Glance","uri":"USB/0A6A-0F5D/The Best Of Michael Franks- A Backward Glance/01 Popsicle Toes.mp3","trackType":"mp3"} Aug 29 19:48:15 volumio volumio[1298]: verbose: CURRENT POSITION 0 Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::syncState stateService pause Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::syncState currentStatus pause Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::pushState Aug 29 19:48:15 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:15 volumio volumio[1298]: info: CoreCommandRouter::volumioPushState Aug 29 19:48:15 volumio volumio[1298]: info: CoreStateMachine::stPlaybackTimer Aug 29 19:48:15 volumio volumio[1298]: info: ------------------------------ 23ms Aug 29 19:48:15 volumio volumio[1298]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Aug 29 19:48:15 volumio volumio[1298]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Aug 29 19:48:15 volumio volumio[1298]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Aug 29 19:48:24 volumio go-librespot[1753]: time="2025-08-29T19:48:24+07:00" level=trace msg="received accesspoint ping" Aug 29 19:48:25 volumio go-librespot[1753]: time="2025-08-29T19:48:25+07:00" level=trace msg="received accesspoint pong ack" Aug 29 19:48:25 volumio go-librespot[1753]: time="2025-08-29T19:48:25+07:00" level=trace msg="sent dealer ping" Aug 29 19:48:26 volumio go-librespot[1753]: time="2025-08-29T19:48:26+07:00" level=trace msg="received dealer pong" Aug 29 19:48:28 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 19:48:28 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 19:48:28 volumio volumio[1298]: info: Discovery: Getting this device information Aug 29 19:48:28 volumio volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 29 19:48:28 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:28 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 19:48:32 volumio volumio[1298]: info: CoreCommandRouter::volumioGetState Aug 29 19:48:32 volumio volumio[1298]: info: CorePlayQueue::getTrack 0 Aug 29 19:48:39 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 29 19:48:39 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 29 19:48:43 volumio volumio[1298]: info: Enabling plugin fusiondsp Aug 29 19:48:43 volumio volumio[1298]: info: Loading plugin "fusiondsp"... Aug 29 19:48:43 volumio volumio[1298]: info: Applying required configuration parameters for plugin fusiondsp Aug 29 19:48:43 volumio volumio[1298]: info: Preparing to generate the ALSA configuration file Aug 29 19:48:43 volumio volumio[1298]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Aug 29 19:48:43 volumio volumio[1298]: info: Reading ALSA contributions from plugins. Aug 29 19:48:43 volumio volumio[1298]: info: Asound.conf file written Aug 29 19:48:43 volumio sudo[3052]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 29 19:48:43 volumio sudo[3052]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 19:48:43 volumio sudo[3052]: pam_unix(sudo:session): session closed for user root Aug 29 19:48:43 volumio volumio[1298]: info: Output device has changed, restarting MPD Aug 29 19:48:43 volumio sudo[3058]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 29 19:48:43 volumio sudo[3058]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 19:48:43 volumio sudo[3058]: pam_unix(sudo:session): session closed for user root Aug 29 19:48:43 volumio volumio[1298]: info: PLUGIN START: fusiondsp Aug 29 19:48:43 volumio volumio[1298]: info: Loading i18n strings for locale en Aug 29 19:48:43 volumio sudo[3061]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 19:48:43 volumio sudo[3061]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: FusionDsp - mixtype--------------------- Hardware Aug 29 19:48:43 volumio volumio[1298]: info: Preparing to generate the ALSA configuration file Aug 29 19:48:43 volumio systemd[1]: Stopping Music Player Daemon... Aug 29 19:48:43 volumio volumio[1298]: info: Done. Aug 29 19:48:43 volumio volumio[1298]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Aug 29 19:48:43 volumio volumio[1298]: info: Reading ALSA contributions from plugins. Aug 29 19:48:43 volumio volumio[1298]: info: MPD Permissions set Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio systemd[1]: mpd.service: Succeeded. Aug 29 19:48:43 volumio systemd[1]: Stopped Music Player Daemon. Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 29 19:48:43 volumio volumio[1298]: info: Asound.conf file unchanged, so no further update is needed Aug 29 19:48:43 volumio volumio[1298]: info: Output device has changed, restarting MPD Aug 29 19:48:43 volumio systemd[1]: Starting Music Player Daemon... Aug 29 19:48:43 volumio sudo[3071]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 29 19:48:43 volumio sudo[3071]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 19:48:43 volumio sudo[3071]: pam_unix(sudo:session): session closed for user root Aug 29 19:48:43 volumio volumio[1298]: info: MPD Permissions set Aug 29 19:48:43 volumio sudo[3074]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 29 19:48:43 volumio sudo[3074]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 19:48:43 volumio volumio[1298]: info: FusionDsp - kef Aug 29 19:48:43 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Aug 29 19:48:43 volumio systemd[1]: mpd.service: Succeeded. Aug 29 19:48:43 volumio systemd[1]: Stopped Music Player Daemon. Aug 29 19:48:43 volumio systemd[1]: Starting Music Player Daemon... Aug 29 19:48:43 volumio sudo[3076]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 29 19:48:43 volumio sudo[3076]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 29 19:48:43 volumio sudo[3076]: pam_unix(sudo:session): session closed for user root Aug 29 19:48:43 volumio volumio[1298]: info: FusionDsp - kef.json,test.json Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Aug 29 19:48:43 volumio volumio[1298]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 19:48:43 volumio mpd[3078]: Aug 29 19:48 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 29 19:48:43 volumio systemd[1]: Started Music Player Daemon. Aug 29 19:48:43 volumio sudo[3061]: pam_unix(sudo:session): session closed for user root Aug 29 19:48:43 volumio sudo[3074]: pam_unix(sudo:session): session closed for user root Aug 29 19:48:43 volumio volumio[1298]: error: MPD error: The expression evaluated to a falsy value: Aug 29 19:48:43 volumio volumio[1298]: assert.ok(self.idling) Aug 29 19:48:43 volumio volumio[1298]: error: The expression evaluated to a falsy value: Aug 29 19:48:43 volumio volumio[1298]: assert.ok(self.idling) Aug 29 19:48:43 volumio volumio[1298]: error: updateQueue error: null Aug 29 19:48:44 volumio volumio[1298]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 19:48:44 volumio volumio[1298]: TypeError: Cannot read property 'off' of undefined Aug 29 19:48:44 volumio volumio[1298]: at FusionDsp.onStop (/data/plugins/audio_interface/fusiondsp/index.js:107:15) Aug 29 19:48:44 volumio volumio[1298]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) Aug 29 19:48:44 volumio volumio[1298]: at PluginManager.disableAndStopPlugin (/volumio/app/pluginmanager.js:1883:8) Aug 29 19:48:44 volumio volumio[1298]: at CoreCommandRouter.disableAndStopPlugin (/volumio/app/index.js:1556:29) Aug 29 19:48:44 volumio volumio[1298]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1401:47) Aug 29 19:48:44 volumio volumio[1298]: at Socket.emit (events.js:400:28) Aug 29 19:48:44 volumio volumio[1298]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Aug 29 19:48:44 volumio volumio[1298]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Aug 29 19:48:44 volumio volumio[1298]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 19:48:44 volumio sudo[3096]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-08-29 19:47 Aug 29 19:48:44 volumio sudo[3096]: 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="669bb6cc406bb77b11c5184fedb8a4dfd19ba4ec" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 11:08:46 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="9ef0bfa9b61509be20c9051562554f31"