Jun 14 00:59:02 volumio go-librespot[1420]: time="2025-06-14T00:59:02+09:00" level=debug msg="fetched chunk 14/17, size: 524288" uri="spotify:track:5y1oS61sbPEqKCYVuH5XT7" Jun 14 00:59:02 volumio go-librespot[1420]: time="2025-06-14T00:59:02+09:00" level=trace msg="sent dealer ping" Jun 14 00:59:02 volumio go-librespot[1420]: time="2025-06-14T00:59:02+09:00" level=trace msg="received dealer pong" Jun 14 00:59:12 volumio go-librespot[1420]: time="2025-06-14T00:59:12+09:00" level=debug msg="fetched chunk 15/17, size: 524288" uri="spotify:track:5y1oS61sbPEqKCYVuH5XT7" Jun 14 00:59:14 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 14 00:59:14 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 14 00:59:14 volumio volumio[1097]: info: Discovery: Getting this device information Jun 14 00:59:14 volumio volumio[1097]: info: CoreCommandRouter::volumioGetState Jun 14 00:59:14 volumio volumio[1097]: info: CorePlayQueue::getTrack 5 Jun 14 00:59:14 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 14 00:59:23 volumio go-librespot[1420]: time="2025-06-14T00:59:23+09:00" level=debug msg="fetched chunk 16/17, size: 524288" uri="spotify:track:5y1oS61sbPEqKCYVuH5XT7" Jun 14 00:59:32 volumio go-librespot[1420]: time="2025-06-14T00:59:32+09:00" level=trace msg="sent dealer ping" Jun 14 00:59:32 volumio go-librespot[1420]: time="2025-06-14T00:59:32+09:00" level=trace msg="received dealer pong" Jun 14 00:59:35 volumio go-librespot[1420]: time="2025-06-14T00:59:35+09:00" level=debug msg="fetched chunk 17/17, size: 415703" uri="spotify:track:5y1oS61sbPEqKCYVuH5XT7" Jun 14 00:59:38 volumio wpa_supplicant[989]: RRM: Ignoring radio measurement request: Not RRM network Jun 14 00:59:41 volumio wpa_supplicant[989]: RRM: Ignoring radio measurement request: Not RRM network Jun 14 00:59:44 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 14 00:59:44 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 14 00:59:44 volumio volumio[1097]: info: Discovery: Getting this device information Jun 14 00:59:44 volumio volumio[1097]: info: CoreCommandRouter::volumioGetState Jun 14 00:59:44 volumio volumio[1097]: info: CorePlayQueue::getTrack 5 Jun 14 00:59:44 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 14 00:59:44 volumio wpa_supplicant[989]: RRM: Ignoring radio measurement request: Not RRM network Jun 14 00:59:55 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jun 14 00:59:55 volumio dbus-daemon[570]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.62' (uid=0 pid=5415 comm="timedatectl show --property=NTPSynchronized --valu") Jun 14 00:59:55 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jun 14 00:59:55 volumio dbus-daemon[570]: [system] Successfully activated service 'org.freedesktop.timedate1' Jun 14 00:59:55 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. Jun 14 00:59:55 volumio setdatetime-helper.sh[5414]: Time is already synchronized. Jun 14 00:59:55 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jun 14 00:59:55 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jun 14 01:00:02 volumio go-librespot[1420]: time="2025-06-14T01:00:02+09:00" level=trace msg="received accesspoint ping" Jun 14 01:00:02 volumio go-librespot[1420]: time="2025-06-14T01:00:02+09:00" level=trace msg="received accesspoint pong ack" Jun 14 01:00:02 volumio go-librespot[1420]: time="2025-06-14T01:00:02+09:00" level=trace msg="sent dealer ping" Jun 14 01:00:02 volumio go-librespot[1420]: time="2025-06-14T01:00:02+09:00" level=trace msg="received dealer pong" Jun 14 01:00:14 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 14 01:00:14 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 14 01:00:14 volumio volumio[1097]: info: Discovery: Getting this device information Jun 14 01:00:14 volumio volumio[1097]: info: CoreCommandRouter::volumioGetState Jun 14 01:00:14 volumio volumio[1097]: info: CorePlayQueue::getTrack 5 Jun 14 01:00:14 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 14 01:00:14 volumio volumio[1097]: info: CorePlayQueue::getTrack 5 Jun 14 01:00:14 volumio volumio[1097]: info: CorePlayQueue::getTrack 6 Jun 14 01:00:14 volumio volumio[1097]: info: Prefetching next song Jun 14 01:00:14 volumio volumio[1097]: info: [1749830414755] ControllerSpotify::prefetch Jun 14 01:00:14 volumio volumio[1097]: info: Sending Spotify command with payload to local API: /player/add_to_queue Jun 14 01:00:14 volumio go-librespot[1420]: time="2025-06-14T01:00:14+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 14 01:00:14 volumio go-librespot[1420]: time="2025-06-14T01:00:14+09:00" level=debug msg="prefetching next track" uri="spotify:track:0TLCjQ9SCJReMpiqOZJkPZ" Jun 14 01:00:14 volumio go-librespot[1420]: time="2025-06-14T01:00:14+09:00" level=debug msg="selected format OGG_VORBIS_320 (680b1dd980592db8a82f16595dc34d1f80c81ca0)" uri="spotify:track:0TLCjQ9SCJReMpiqOZJkPZ" Jun 14 01:00:14 volumio go-librespot[1420]: time="2025-06-14T01:00:14+09:00" level=debug msg="requested aes key for file 680b1dd980592db8a82f16595dc34d1f80c81ca0, gid: 0TLCjQ9SCJReMpiqOZJkPZ" Jun 14 01:00:15 volumio go-librespot[1420]: time="2025-06-14T01:00:15+09:00" level=debug msg="fetched first chunk of 16, total size is 8024494 bytes" uri="spotify:track:0TLCjQ9SCJReMpiqOZJkPZ" Jun 14 01:00:15 volumio go-librespot[1420]: time="2025-06-14T01:00:15+09:00" level=info msg="prefetched track \"GUM (feat. Taprikk Sweezee & BAKUBAKU DOKIN)\" (duration: 184786ms)" uri="spotify:track:0TLCjQ9SCJReMpiqOZJkPZ" Jun 14 01:00:15 volumio go-librespot[1420]: time="2025-06-14T01:00:15+09:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:0TLCjQ9SCJReMpiqOZJkPZ" Jun 14 01:00:15 volumio go-librespot[1420]: time="2025-06-14T01:00:15+09:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:0TLCjQ9SCJReMpiqOZJkPZ" Jun 14 01:00:15 volumio go-librespot[1420]: time="2025-06-14T01:00:15+09:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:0TLCjQ9SCJReMpiqOZJkPZ" Jun 14 01:00:18 volumio volumio[1097]: info: CoreCommandRouter::volumioPause Jun 14 01:00:18 volumio volumio[1097]: info: CoreStateMachine::pause Jun 14 01:00:18 volumio volumio[1097]: info: CoreStateMachine::stPlaybackTimer Jun 14 01:00:18 volumio volumio[1097]: info: CoreStateMachine::servicePause Jun 14 01:00:18 volumio volumio[1097]: info: CorePlayQueue::getTrack 5 Jun 14 01:00:18 volumio volumio[1097]: info: CoreCommandRouter::servicePause Jun 14 01:00:18 volumio volumio[1097]: info: Spotify Received pause Jun 14 01:00:18 volumio volumio[1097]: SPOTIFY: SPOTIFY PAUSE Jun 14 01:00:18 volumio volumio[1097]: SPOTIFY: {"status":"play","position":5,"title":"THE PROPHET (feat. 高橋幸宏 & 細野晴臣)","artist":"TOWA TEI","album":"AH!!","albumart":"https://i.scdn.co/image/ab67616d0000b2730b574e8e5a7d94c6d50003ac","uri":"spotify:track:5y1oS61sbPEqKCYVuH5XT7","trackType":"spotify","codec":"ogg","seek":0,"duration":216,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jun 14 01:00:18 volumio volumio[1097]: info: Sending Spotify command to local API: /player/pause Jun 14 01:00:18 volumio go-librespot[1420]: time="2025-06-14T01:00:18+09:00" level=debug msg="pause track at 215054ms" Jun 14 01:00:18 volumio go-librespot[1420]: time="2025-06-14T01:00:18+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 14 01:00:18 volumio go-librespot[1420]: time="2025-06-14T01:00:18+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 14 01:00:18 volumio go-librespot[1420]: time="2025-06-14T01:00:18+09:00" level=trace msg="emitting websocket event: paused" Jun 14 01:00:18 volumio volumio[1097]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:5y1oS61sbPEqKCYVuH5XT7","play_origin":"go-librespot"}} Jun 14 01:00:18 volumio volumio[1097]: SPOTIFY: PUSH STATE SPOTIFY Jun 14 01:00:18 volumio volumio[1097]: SPOTIFY: {"status":"pause","service":"spop","title":"THE PROPHET (feat. 高橋幸宏 & 細野晴臣)","artist":"TOWA TEI, Yukihiro Takahashi, Haruomi Hosono","album":"AH!!","albumart":"https://i.scdn.co/image/ab67616d00001e020b574e8e5a7d94c6d50003ac","uri":"spotify:track:5y1oS61sbPEqKCYVuH5XT7","trackType":"spotify","seek":214000,"duration":216,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 14 01:00:18 volumio volumio[1097]: info: CoreCommandRouter::servicePushState Jun 14 01:00:18 volumio volumio[1097]: info: CorePlayQueue::getTrack 5 Jun 14 01:00:18 volumio volumio[1097]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"THE PROPHET (feat. 高橋幸宏 & 細野晴臣)","artist":"TOWA TEI, Yukihiro Takahashi, Haruomi Hosono","album":"AH!!","albumart":"https://i.scdn.co/image/ab67616d00001e020b574e8e5a7d94c6d50003ac","uri":"spotify:track:5y1oS61sbPEqKCYVuH5XT7","trackType":"spotify","seek":214000,"duration":216,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 14 01:00:18 volumio volumio[1097]: verbose: CURRENT POSITION 5 Jun 14 01:00:18 volumio volumio[1097]: info: CoreStateMachine::syncState stateService pause Jun 14 01:00:18 volumio volumio[1097]: info: CoreStateMachine::syncState currentStatus pause Jun 14 01:00:18 volumio volumio[1097]: info: CoreStateMachine::pushState Jun 14 01:00:18 volumio volumio[1097]: info: CorePlayQueue::getTrack 5 Jun 14 01:00:18 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 14 01:00:18 volumio volumio[1097]: info: CoreCommandRouter::volumioPushState Jun 14 01:00:18 volumio volumio[1097]: info: CoreStateMachine::stPlaybackTimer Jun 14 01:00:18 volumio volumio[1097]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 14 01:00:25 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Jun 14 01:00:29 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Jun 14 01:00:29 volumio volumio[1097]: info: CURURI: music-library Jun 14 01:00:30 volumio volumio[1097]: info: Preload queue cleared Jun 14 01:00:30 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Jun 14 01:00:30 volumio volumio[1097]: info: CURURI: music-library/USB Jun 14 01:00:30 volumio volumio[1097]: info: Preload queue cleared Jun 14 01:00:31 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Jun 14 01:00:31 volumio volumio[1097]: info: CURURI: music-library/USB Jun 14 01:00:31 volumio volumio[1097]: info: Preload queue cleared Jun 14 01:00:32 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Jun 14 01:00:32 volumio volumio[1097]: info: CURURI: music-library/USB/781D-B169 Jun 14 01:00:32 volumio volumio[1097]: info: Preload queue cleared Jun 14 01:00:32 volumio go-librespot[1420]: time="2025-06-14T01:00:32+09:00" level=trace msg="sent dealer ping" Jun 14 01:00:32 volumio go-librespot[1420]: time="2025-06-14T01:00:32+09:00" level=trace msg="received dealer pong" Jun 14 01:00:37 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Jun 14 01:00:37 volumio volumio[1097]: info: CURURI: music-library/USB/781D-B169/Inoyamaland Jun 14 01:00:37 volumio volumio[1097]: info: Preload queue cleared Jun 14 01:00:38 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Jun 14 01:00:38 volumio volumio[1097]: info: CURURI: music-library/USB/781D-B169/Inoyamaland/INOYAMALAND Jun 14 01:00:38 volumio wpa_supplicant[989]: RRM: Ignoring radio measurement request: Not RRM network Jun 14 01:00:38 volumio volumio[1097]: info: Preload queue cleared Jun 14 01:00:41 volumio wpa_supplicant[989]: RRM: Ignoring radio measurement request: Not RRM network Jun 14 01:00:42 volumio volumio[1097]: info: CoreCommandRouter::volumioAddQueueItems Jun 14 01:00:42 volumio volumio[1097]: info: CoreStateMachine::addQueueItems Jun 14 01:00:42 volumio volumio[1097]: info: CorePlayQueue::addQueueItems Jun 14 01:00:42 volumio volumio[1097]: info: Preload queue cleared Jun 14 01:00:42 volumio volumio[1097]: info: Adding Item to queue: music-library/USB/781D-B169/Inoyamaland/DANZINDAN-POJIDON Jun 14 01:00:42 volumio volumio[1097]: info: Exploding uri music-library/USB/781D-B169/Inoyamaland/DANZINDAN-POJIDON in service mpd Jun 14 01:00:42 volumio volumio[1097]: info: ALBUMART /albumart?cacheid=528&web=INOYAMALAND/DANZINDAN-POJIDON/extralarge&path=%2Fmnt%2FUSB%2F781D-B169%2FInoyamaland%2FDANZINDAN-POJIDON%2FDANZINDAN-POJIDON.cue&metadata=false Jun 14 01:00:42 volumio volumio[1097]: info: URI /mnt/USB/781D-B169/Inoyamaland/DANZINDAN-POJIDON/DANZINDAN-POJIDON.cue Jun 14 01:00:42 volumio volumio[1097]: info: ALBUMART /albumart?cacheid=528&web=INOYAMALAND/DANZINDAN-POJIDON/extralarge&path=%2Fmnt%2FUSB%2F781D-B169%2FInoyamaland%2FDANZINDAN-POJIDON%2FDANZINDAN-POJIDON.cue&metadata=false Jun 14 01:00:42 volumio volumio[1097]: info: URI /mnt/USB/781D-B169/Inoyamaland/DANZINDAN-POJIDON/DANZINDAN-POJIDON.cue Jun 14 01:00:42 volumio volumio[1097]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 14 01:00:42 volumio volumio[1097]: Error: Unable to resolve or reject the same promise twice Jun 14 01:00:42 volumio volumio[1097]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Jun 14 01:00:42 volumio volumio[1097]: at /volumio/app/plugins/music_service/mpd/index.js:2569:21 Jun 14 01:00:42 volumio volumio[1097]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3) Jun 14 01:00:42 volumio volumio[1097]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12) Jun 14 01:00:42 volumio volumio[1097]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Jun 14 01:00:42 volumio volumio[1097]: at Socket.emit (node:events:514:28) Jun 14 01:00:42 volumio volumio[1097]: at addChunk (node:internal/streams/readable:343:12) Jun 14 01:00:42 volumio volumio[1097]: at readableAddChunk (node:internal/streams/readable:312:11) Jun 14 01:00:42 volumio volumio[1097]: at Readable.push (node:internal/streams/readable:253:10) Jun 14 01:00:42 volumio volumio[1097]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) Jun 14 01:00:42 volumio volumio[1097]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 14 01:00:43 volumio sudo[5493]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-06-14 00:59' Jun 14 01:00:43 volumio sudo[5493]: 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="fd567ba9bc0dc34c0403e2d5b72a0f46467d1983" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri May 23 08:02:06 UTC 2025" VOLUMIO_VERSION="0.069" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="76fa67e30b28261e1dc7c3a89e610b9e"