Sep 11 11:39:18 volumio go-librespot[17013]: time="2025-09-11T11:39:18+09:30" level=trace msg="sent dealer ping" Sep 11 11:39:18 volumio wpa_supplicant[1363]: RRM: Ignoring radio measurement request: Not RRM network Sep 11 11:39:18 volumio go-librespot[17013]: time="2025-09-11T11:39:18+09:30" level=trace msg="received dealer pong" Sep 11 11:39:19 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Sep 11 11:39:34 volumio wpa_supplicant[1363]: RRM: Ignoring radio measurement request: Not RRM network Sep 11 11:39:37 volumio go-librespot[17013]: time="2025-09-11T11:39:37+09:30" level=trace msg="received accesspoint ping" Sep 11 11:39:37 volumio go-librespot[17013]: time="2025-09-11T11:39:37+09:30" level=trace msg="received accesspoint pong ack" Sep 11 11:39:40 volumio wpa_supplicant[1363]: RRM: Ignoring radio measurement request: Not RRM network Sep 11 11:39:47 volumio wpa_supplicant[1363]: RRM: Ignoring radio measurement request: Not RRM network Sep 11 11:39:48 volumio go-librespot[17013]: time="2025-09-11T11:39:48+09:30" level=trace msg="sent dealer ping" Sep 11 11:39:48 volumio go-librespot[17013]: time="2025-09-11T11:39:48+09:30" level=trace msg="received dealer pong" Sep 11 11:39:53 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Sep 11 11:39:53 volumio dbus-daemon[936]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.1139' (uid=0 pid=25104 comm="timedatectl show --property=NTPSynchronized --valu") Sep 11 11:39:53 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... Sep 11 11:39:53 volumio dbus-daemon[936]: [system] Successfully activated service 'org.freedesktop.timedate1' Sep 11 11:39:53 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. Sep 11 11:39:53 volumio setdatetime-helper.sh[25103]: Time is already synchronized. Sep 11 11:39:53 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Sep 11 11:39:53 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Sep 11 11:39:54 volumio wpa_supplicant[1363]: RRM: Ignoring radio measurement request: Not RRM network Sep 11 11:40:04 volumio wpa_supplicant[1363]: RRM: Ignoring radio measurement request: Not RRM network Sep 11 11:40:10 volumio wpa_supplicant[1363]: RRM: Ignoring radio measurement request: Not RRM network Sep 11 11:40:18 volumio go-librespot[17013]: time="2025-09-11T11:40:18+09:30" level=trace msg="sent dealer ping" Sep 11 11:40:18 volumio go-librespot[17013]: time="2025-09-11T11:40:18+09:30" level=trace msg="received dealer pong" Sep 11 11:40:18 volumio wpa_supplicant[1363]: RRM: Ignoring radio measurement request: Not RRM network Sep 11 11:40:23 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Sep 11 11:40:24 volumio wpa_supplicant[1363]: RRM: Ignoring radio measurement request: Not RRM network Sep 11 11:40:30 volumio wpa_supplicant[1363]: RRM: Ignoring radio measurement request: Not RRM network Sep 11 11:40:31 volumio volumio[1451]: info: Preload queue cleared Sep 11 11:40:31 volumio volumio[1451]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 11 11:40:31 volumio volumio[1451]: info: CoreStateMachine::ClearQueue Sep 11 11:40:31 volumio volumio[1451]: info: CoreStateMachine::stop Sep 11 11:40:31 volumio volumio[1451]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 11 11:40:31 volumio volumio[1451]: info: CoreStateMachine::stPlaybackTimer Sep 11 11:40:31 volumio volumio[1451]: info: CoreStateMachine::updateTrackBlock Sep 11 11:40:31 volumio volumio[1451]: info: CorePlayQueue::getTrackBlock Sep 11 11:40:31 volumio volumio[1451]: info: CoreStateMachine::pushState Sep 11 11:40:31 volumio volumio[1451]: info: CorePlayQueue::getTrack 2 Sep 11 11:40:31 volumio volumio[1451]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 11 11:40:31 volumio volumio[1451]: info: CoreCommandRouter::volumioPushState Sep 11 11:40:31 volumio volumio[1451]: info: CoreStateMachine::serviceStop Sep 11 11:40:31 volumio volumio[1451]: info: CorePlayQueue::getTrack 2 Sep 11 11:40:31 volumio volumio[1451]: info: CoreCommandRouter::serviceStop Sep 11 11:40:31 volumio volumio[1451]: info: ControllerMpd::stop Sep 11 11:40:31 volumio volumio[1451]: verbose: ControllerMpd::sendMpdCommand stop Sep 11 11:40:31 volumio volumio[1451]: info: CorePlayQueue::clearPlayQueue Sep 11 11:40:31 volumio volumio[1451]: info: CorePlayQueue::saveQueue Sep 11 11:40:31 volumio volumio[1451]: info: CoreCommandRouter::volumioPushQueue Sep 11 11:40:31 volumio volumio[1451]: info: CoreStateMachine::addQueueItems Sep 11 11:40:31 volumio volumio[1451]: info: CorePlayQueue::addQueueItems Sep 11 11:40:31 volumio volumio[1451]: info: Preload queue cleared Sep 11 11:40:31 volumio volumio[1451]: info: Adding Item to queue: music-library/NAS/truenas_music/Shintaro Sakamoto (坂本慎太郎) - まともがわからない (Don't Know What's Normal) Sep 11 11:40:31 volumio volumio[1451]: info: Exploding uri music-library/NAS/truenas_music/Shintaro Sakamoto (坂本慎太郎) - まともがわからない (Don't Know What's Normal) in service mpd Sep 11 11:40:31 volumio volumio[1451]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Sep 11 11:40:31 volumio volumio[1451]: info: Sep 11 11:40:31 volumio volumio[1451]: ---------------------------- MPD announces state update: player Sep 11 11:40:31 volumio volumio[1451]: info: sendMpdCommand stop took 22 milliseconds Sep 11 11:40:31 volumio volumio[1451]: info: ControllerMpd::getState Sep 11 11:40:31 volumio volumio[1451]: verbose: ControllerMpd::sendMpdCommand status Sep 11 11:40:31 volumio volumio[1451]: info: ALBUMART /albumart?cacheid=509&web=%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E/%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8C%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84/extralarge&path=%2Fmnt%2FNAS%2Ftruenas_music%2FShintaro%20Sakamoto%20(%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E)%20-%20%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8B%E3%82%99%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84%20(Don't%20Know%20What's%20Normal)%2F01%20%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E%20-%20%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8B%E3%82%99%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84.flac&metadata=false Sep 11 11:40:31 volumio volumio[1451]: info: URI /mnt/NAS/truenas_music/Shintaro Sakamoto (坂本慎太郎) - まともがわからない (Don't Know What's Normal)/01 坂本慎太郎 - まともがわからない.flac Sep 11 11:40:31 volumio volumio[1451]: info: ALBUMART /albumart?cacheid=509&web=%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E/%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8C%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84/extralarge&path=%2Fmnt%2FNAS%2Ftruenas_music%2FShintaro%20Sakamoto%20(%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E)%20-%20%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8B%E3%82%99%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84%20(Don't%20Know%20What's%20Normal)%2F02%20%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E%20-%20%E6%AD%BB%E8%80%85%E3%82%88%E3%82%8A.flac&metadata=false Sep 11 11:40:31 volumio volumio[1451]: info: URI /mnt/NAS/truenas_music/Shintaro Sakamoto (坂本慎太郎) - まともがわからない (Don't Know What's Normal)/02 坂本慎太郎 - 死者より.flac Sep 11 11:40:31 volumio volumio[1451]: info: ALBUMART /albumart?cacheid=509&web=%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E/%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8C%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84/extralarge&path=%2Fmnt%2FNAS%2Ftruenas_music%2FShintaro%20Sakamoto%20(%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E)%20-%20%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8B%E3%82%99%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84%20(Don't%20Know%20What's%20Normal)%2F03%20%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E%20-%20%E6%82%B2%E3%81%97%E3%81%BF%E3%81%AE%E3%81%AA%E3%81%84%E4%B8%96%E7%95%8C.flac&metadata=false Sep 11 11:40:31 volumio volumio[1451]: info: URI /mnt/NAS/truenas_music/Shintaro Sakamoto (坂本慎太郎) - まともがわからない (Don't Know What's Normal)/03 坂本慎太郎 - 悲しみのない世界.flac Sep 11 11:40:31 volumio volumio[1451]: info: ALBUMART /albumart?cacheid=509&web=%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E/%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8C%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84/extralarge&path=%2Fmnt%2FNAS%2Ftruenas_music%2FShintaro%20Sakamoto%20(%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E)%20-%20%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8B%E3%82%99%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84%20(Don't%20Know%20What's%20Normal)%2F%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8B%E3%82%99%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84.cue&metadata=false Sep 11 11:40:31 volumio volumio[1451]: info: URI /mnt/NAS/truenas_music/Shintaro Sakamoto (坂本慎太郎) - まともがわからない (Don't Know What's Normal)/まともがわからない.cue Sep 11 11:40:31 volumio volumio[1451]: info: ALBUMART /albumart?cacheid=509&web=%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E/%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8C%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84/extralarge&path=%2Fmnt%2FNAS%2Ftruenas_music%2FShintaro%20Sakamoto%20(%E5%9D%82%E6%9C%AC%E6%85%8E%E5%A4%AA%E9%83%8E)%20-%20%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8B%E3%82%99%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84%20(Don't%20Know%20What's%20Normal)%2F%E3%81%BE%E3%81%A8%E3%82%82%E3%81%8B%E3%82%99%E3%82%8F%E3%81%8B%E3%82%89%E3%81%AA%E3%81%84.cue&metadata=false Sep 11 11:40:31 volumio volumio[1451]: info: URI /mnt/NAS/truenas_music/Shintaro Sakamoto (坂本慎太郎) - まともがわからない (Don't Know What's Normal)/まともがわからない.cue Sep 11 11:40:31 volumio volumio[1451]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 11 11:40:31 volumio volumio[1451]: Error: Unable to resolve or reject the same promise twice Sep 11 11:40:31 volumio volumio[1451]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Sep 11 11:40:31 volumio volumio[1451]: at /volumio/app/plugins/music_service/mpd/index.js:2569:21 Sep 11 11:40:31 volumio volumio[1451]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3) Sep 11 11:40:31 volumio volumio[1451]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12) Sep 11 11:40:31 volumio volumio[1451]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Sep 11 11:40:31 volumio volumio[1451]: at Socket.emit (node:events:514:28) Sep 11 11:40:31 volumio volumio[1451]: at addChunk (node:internal/streams/readable:343:12) Sep 11 11:40:31 volumio volumio[1451]: at readableAddChunk (node:internal/streams/readable:312:11) Sep 11 11:40:31 volumio volumio[1451]: at Readable.push (node:internal/streams/readable:253:10) Sep 11 11:40:31 volumio volumio[1451]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) Sep 11 11:40:31 volumio volumio[1451]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 11 11:40:31 volumio sudo[25188]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-09-11 11:39' Sep 11 11:40:31 volumio sudo[25188]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="dfc7bb04e09bf2260691765a2340814af1fa2971" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="30d63a8c53d2826bd7f262e22b4e4511a4cc9d01" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Aug 30 06:39:32 UTC 2025" VOLUMIO_VERSION="4.022" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e7b0bd0cb5661ea77402e5bd121ec64a"