Oct 02 14:21:02 volumio go-librespot[21027]: time="2026-10-02T14:21:02+03:00" level=debug msg="fetched chunk 29/75, size: 524288" uri="spotify:track:6cjis4vuQTND33tresUkHF" Oct 02 14:21:04 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 4139. Oct 02 14:21:04 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 02 14:21:04 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 02 14:21:04 volumio upmpdcli[4960]: Could not open config: /tmp/upmpdcli.conf Oct 02 14:21:04 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 02 14:21:04 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 02 14:21:11 volumio go-librespot[21027]: time="2026-10-02T14:21:11+03:00" level=debug msg="fetched chunk 30/75, size: 524288" uri="spotify:track:6cjis4vuQTND33tresUkHF" Oct 02 14:21:19 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 4140. Oct 02 14:21:19 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 02 14:21:19 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 02 14:21:19 volumio upmpdcli[4989]: Could not open config: /tmp/upmpdcli.conf Oct 02 14:21:19 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 02 14:21:19 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 02 14:21:20 volumio go-librespot[21027]: time="2026-10-02T14:21:20+03:00" level=debug msg="fetched chunk 31/75, size: 524288" uri="spotify:track:6cjis4vuQTND33tresUkHF" Oct 02 14:21:28 volumio go-librespot[21027]: time="2026-10-02T14:21:28+03:00" level=trace msg="sent dealer ping" Oct 02 14:21:28 volumio go-librespot[21027]: time="2026-10-02T14:21:28+03:00" level=trace msg="received dealer pong" Oct 02 14:21:29 volumio go-librespot[21027]: time="2026-10-02T14:21:29+03:00" level=debug msg="fetched chunk 32/75, size: 524288" uri="spotify:track:6cjis4vuQTND33tresUkHF" Oct 02 14:21:34 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 4141. Oct 02 14:21:34 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 02 14:21:34 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 02 14:21:35 volumio upmpdcli[5006]: Could not open config: /tmp/upmpdcli.conf Oct 02 14:21:35 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 02 14:21:35 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 02 14:21:41 volumio go-librespot[21027]: time="2026-10-02T14:21:41+03:00" level=debug msg="fetched chunk 33/75, size: 524288" uri="spotify:track:6cjis4vuQTND33tresUkHF" Oct 02 14:21:47 volumio go-librespot[21027]: time="2026-10-02T14:21:47+03:00" level=debug msg="handling pause player command from 11dc22cd147d423a2a4c69dc2cf8d5c3991521bf" Oct 02 14:21:47 volumio go-librespot[21027]: time="2026-10-02T14:21:47+03:00" level=debug msg="pause track at 321342ms" Oct 02 14:21:48 volumio go-librespot[21027]: time="2026-10-02T14:21:48+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 02 14:21:48 volumio go-librespot[21027]: time="2026-10-02T14:21:48+03:00" level=debug msg="sending successful reply for dealer request" Oct 02 14:21:48 volumio go-librespot[21027]: time="2026-10-02T14:21:48+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 02 14:21:48 volumio go-librespot[21027]: time="2026-10-02T14:21:48+03:00" level=trace msg="emitting websocket event: paused" Oct 02 14:21:48 volumio volumio[1156]: info: CoreCommandRouter::servicePushState Oct 02 14:21:48 volumio volumio[1156]: info: CoreStateMachine::pushState Oct 02 14:21:48 volumio volumio[1156]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 02 14:21:48 volumio volumio[1156]: info: CoreCommandRouter::volumioPushState Oct 02 14:21:48 volumio volumio[1156]: info: CoreCommandRouter::servicePushState Oct 02 14:21:48 volumio volumio[1156]: info: CoreStateMachine::pushState Oct 02 14:21:48 volumio volumio[1156]: info: CoreCommandRouter::volumioPushState Oct 02 14:21:48 volumio volumio[1156]: info: CoreCommandRouter::servicePushState Oct 02 14:21:48 volumio volumio[1156]: info: CoreStateMachine::pushState Oct 02 14:21:48 volumio volumio[1156]: info: CoreCommandRouter::volumioPushState Oct 02 14:21:48 volumio volumio[1156]: info: touch_display: Setting screensaver timeout to 0 seconds. Oct 02 14:21:50 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 4142. Oct 02 14:21:50 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 02 14:21:50 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 02 14:21:50 volumio upmpdcli[5038]: Could not open config: /tmp/upmpdcli.conf Oct 02 14:21:50 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 02 14:21:50 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 02 14:21:58 volumio go-librespot[21027]: time="2026-10-02T14:21:58+03:00" level=trace msg="sent dealer ping" Oct 02 14:21:58 volumio go-librespot[21027]: time="2026-10-02T14:21:58+03:00" level=trace msg="received dealer pong" Oct 02 14:22:04 volumio kernel: usb 1-1.2: new high-speed USB device number 3 using xhci_hcd Oct 02 14:22:04 volumio kernel: usb 1-1.2: New USB device found, idVendor=054c, idProduct=02a5, bcdDevice= 1.00 Oct 02 14:22:04 volumio kernel: usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3 Oct 02 14:22:04 volumio kernel: usb 1-1.2: Product: Storage Media Oct 02 14:22:04 volumio kernel: usb 1-1.2: Manufacturer: Sony Oct 02 14:22:04 volumio kernel: usb 1-1.2: SerialNumber: 9B2001211070022934 Oct 02 14:22:04 volumio kernel: usb-storage 1-1.2:1.0: USB Mass Storage device detected Oct 02 14:22:04 volumio kernel: usb-storage 1-1.2:1.0: Quirks match for vid 054c pid 02a5: 80000 Oct 02 14:22:04 volumio kernel: scsi host0: usb-storage 1-1.2:1.0 Oct 02 14:22:05 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 4143. Oct 02 14:22:05 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 02 14:22:05 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 02 14:22:05 volumio upmpdcli[5059]: Could not open config: /tmp/upmpdcli.conf Oct 02 14:22:05 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Oct 02 14:22:05 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Oct 02 14:22:05 volumio kernel: scsi 0:0:0:0: Direct-Access Sony Storage Media 0100 PQ: 0 ANSI: 4 Oct 02 14:22:05 volumio kernel: sd 0:0:0:0: [sda] 7618560 512-byte logical blocks: (3.90 GB/3.63 GiB) Oct 02 14:22:05 volumio kernel: sd 0:0:0:0: [sda] Write Protect is off Oct 02 14:22:05 volumio kernel: sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00 Oct 02 14:22:05 volumio kernel: sd 0:0:0:0: [sda] No Caching mode page found Oct 02 14:22:05 volumio kernel: sd 0:0:0:0: [sda] Assuming drive cache: write through Oct 02 14:22:05 volumio kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0 Oct 02 14:22:05 volumio kernel: sda: sda1 sda2 Oct 02 14:22:05 volumio kernel: sd 0:0:0:0: [sda] Attached SCSI removable disk Oct 02 14:22:05 volumio volumio[1156]: info: Mounting Device EFI Oct 02 14:22:06 volumio sudo[5072]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/EFI -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Oct 02 14:22:06 volumio sudo[5072]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 14:22:06 volumio kernel: FAT-fs (sda1): utf8 is not a recommended IO charset for FAT filesystems, filesystem will be case sensitive! Oct 02 14:22:06 volumio sudo[5072]: pam_unix(sudo:session): session closed for user root Oct 02 14:22:06 volumio kernel: FAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck. Oct 02 14:22:06 volumio volumio[1156]: info: Mounting Device SONY_4GB Oct 02 14:22:06 volumio sudo[5082]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda2 /mnt/USB/SONY_4GB -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Oct 02 14:22:06 volumio sudo[5082]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 02 14:22:06 volumio kernel: FAT-fs (sda2): utf8 is not a recommended IO charset for FAT filesystems, filesystem will be case sensitive! Oct 02 14:22:06 volumio sudo[5082]: pam_unix(sudo:session): session closed for user root Oct 02 14:22:06 volumio kernel: FAT-fs (sda2): Volume was not properly unmounted. Some data may be corrupt. Please run fsck. Oct 02 14:22:06 volumio volumio[1156]: info: Scanning new location : "USB/SONY_4GB" Oct 02 14:22:06 volumio volumio[1156]: info: Scanning new location : "USB/EFI" Oct 02 14:22:06 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:06 volumio volumio[1156]: info: Oct 02 14:22:06 volumio volumio[1156]: ---------------------------- MPD announces state update: update Oct 02 14:22:06 volumio volumio[1156]: info: ControllerMpd::getState Oct 02 14:22:06 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:06 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:06 volumio volumio[1156]: info: Oct 02 14:22:06 volumio volumio[1156]: ---------------------------- MPD announces state update: update Oct 02 14:22:06 volumio volumio[1156]: info: ControllerMpd::getState Oct 02 14:22:06 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:06 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:06 volumio volumio[1156]: info: Oct 02 14:22:06 volumio volumio[1156]: ---------------------------- MPD announces state update: update Oct 02 14:22:06 volumio volumio[1156]: info: ControllerMpd::getState Oct 02 14:22:06 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:06 volumio volumio[1156]: info: sendMpdCommand playlistinfo took 13638544 milliseconds Oct 02 14:22:06 volumio volumio[1156]: info: sendMpdCommand status took 5 milliseconds Oct 02 14:22:06 volumio volumio[1156]: info: sendMpdCommand status took 4 milliseconds Oct 02 14:22:06 volumio volumio[1156]: verbose: ControllerMpd::parseTrackInfo Oct 02 14:22:06 volumio volumio[1156]: verbose: ControllerMpd::parseState Oct 02 14:22:08 volumio volumio[1156]: info: Command Router : Notfying DB Updatetrue Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::parseState Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 02 14:22:08 volumio volumio[1156]: error: ControllerMpd::pushError: TypeError: Cannot read properties of undefined (reading 'split') Oct 02 14:22:08 volumio volumio[1156]: info: ------------------------------ 13640725ms Oct 02 14:22:08 volumio volumio[1156]: info: sendMpdCommand status took 2170 milliseconds Oct 02 14:22:08 volumio volumio[1156]: info: sendMpdCommand status took 2170 milliseconds Oct 02 14:22:08 volumio volumio[1156]: info: sendMpdCommand status took 2169 milliseconds Oct 02 14:22:08 volumio volumio[1156]: info: sendMpdCommand status took 2168 milliseconds Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::parseState Oct 02 14:22:08 volumio volumio[1156]: info: Command Router : Notfying DB Updatetrue Oct 02 14:22:08 volumio volumio[1156]: info: CoreCommandRouter::Close All Modals sent Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::parseState Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::parseState Oct 02 14:22:08 volumio volumio[1156]: info: Command Router : Notfying DB Updatetrue Oct 02 14:22:08 volumio volumio[1156]: info: CoreCommandRouter::Close All Modals sent Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::parseState Oct 02 14:22:08 volumio volumio[1156]: info: ControllerMpd::pushState Oct 02 14:22:08 volumio volumio[1156]: info: CoreCommandRouter::servicePushState Oct 02 14:22:08 volumio volumio[1156]: info: CorePlayQueue::getTrack 0 Oct 02 14:22:08 volumio volumio[1156]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Oct 02 14:22:08 volumio volumio[1156]: info: ------------------------------ 2220ms Oct 02 14:22:08 volumio volumio[1156]: info: sendMpdCommand playlistinfo took 59 milliseconds Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::parseTrackInfo Oct 02 14:22:08 volumio volumio[1156]: info: ControllerMpd::pushState Oct 02 14:22:08 volumio volumio[1156]: info: CoreCommandRouter::servicePushState Oct 02 14:22:08 volumio volumio[1156]: info: CoreStateMachine::pushState Oct 02 14:22:08 volumio volumio[1156]: info: CoreCommandRouter::volumioPushState Oct 02 14:22:08 volumio volumio[1156]: info: CorePlayQueue::getTrack 0 Oct 02 14:22:08 volumio volumio[1156]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Oct 02 14:22:08 volumio volumio[1156]: info: ------------------------------ 2234ms Oct 02 14:22:08 volumio volumio[1156]: info: MPD Database updated - AlbumList cache refreshed Oct 02 14:22:08 volumio volumio[1156]: info: Oct 02 14:22:08 volumio volumio[1156]: ---------------------------- MPD announces state update: database Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:08 volumio volumio[1156]: info: Oct 02 14:22:08 volumio volumio[1156]: ---------------------------- MPD announces state update: update Oct 02 14:22:08 volumio volumio[1156]: info: ControllerMpd::getState Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:08 volumio volumio[1156]: info: ControllerMpd::getState Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:08 volumio volumio[1156]: info: MPD Database updated - AlbumList cache refreshed Oct 02 14:22:08 volumio volumio[1156]: info: Oct 02 14:22:08 volumio volumio[1156]: ---------------------------- MPD announces state update: database Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:08 volumio volumio[1156]: info: Oct 02 14:22:08 volumio volumio[1156]: ---------------------------- MPD announces state update: update Oct 02 14:22:08 volumio volumio[1156]: info: ControllerMpd::getState Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:08 volumio volumio[1156]: info: ControllerMpd::getState Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:08 volumio volumio[1156]: info: MPD Database updated - AlbumList cache refreshed Oct 02 14:22:08 volumio volumio[1156]: info: Oct 02 14:22:08 volumio volumio[1156]: ---------------------------- MPD announces state update: database Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:08 volumio volumio[1156]: info: Oct 02 14:22:08 volumio volumio[1156]: ---------------------------- MPD announces state update: update Oct 02 14:22:08 volumio volumio[1156]: verbose: ControllerMpd::sendMpdCommand status Oct 02 14:22:08 volumio volumio[1156]: info: Oct 02 14:22:08 volumio volumio[1156]: ---------------------------- MPD announces state update: update Oct 02 14:22:08 volumio volumio[1156]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 02 14:22:08 volumio volumio[1156]: TypeError: Cannot read properties of undefined (reading 'substring') Oct 02 14:22:08 volumio volumio[1156]: at /volumio/app/plugins/music_service/mpd/index.js:2840:70 Oct 02 14:22:08 volumio volumio[1156]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3) Oct 02 14:22:08 volumio volumio[1156]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12) Oct 02 14:22:08 volumio volumio[1156]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Oct 02 14:22:08 volumio volumio[1156]: at Socket.emit (node:events:514:28) Oct 02 14:22:08 volumio volumio[1156]: at addChunk (node:internal/streams/readable:343:12) Oct 02 14:22:08 volumio volumio[1156]: at readableAddChunk (node:internal/streams/readable:312:11) Oct 02 14:22:08 volumio volumio[1156]: at Readable.push (node:internal/streams/readable:253:10) Oct 02 14:22:08 volumio volumio[1156]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) Oct 02 14:22:08 volumio volumio[1156]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 02 14:22:09 volumio sudo[5134]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-02 14:21' Oct 02 14:22:09 volumio sudo[5134]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"