-- Logs begin at Wed 2025-12-24 04:18:40 CET, end at Thu 2025-12-25 00:42:27 CET. -- Dec 25 00:41:00 motivo volumio5-onboarding[1562]: time=2025-12-25T00:41:00.005+01:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 chunks=1 index=0 tries=9 Dec 25 00:41:00 motivo volumio5-onboarding[1562]: time=2025-12-25T00:41:00.306+01:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=8 chunks=1 index=0 tries=10 Dec 25 00:41:00 motivo volumio5-onboarding[1562]: time=2025-12-25T00:41:00.306+01:00 level=ERROR msg="pending write exceeded maximum retries, dropping" component=conn/ble Dec 25 00:41:00 motivo go-librespot[9724]: time="2025-12-25T00:41:00+01:00" level=trace msg="sent dealer ping" Dec 25 00:41:01 motivo go-librespot[9724]: time="2025-12-25T00:41:01+01:00" level=trace msg="received dealer pong" Dec 25 00:41:04 motivo volumio[1065]: info: CoreCommandRouter::volumioGetState Dec 25 00:41:10 motivo volumio[1065]: info: CoreCommandRouter::volumioGetState Dec 25 00:41:12 motivo volumio[1065]: info: Executing endpoint metavolumio Dec 25 00:41:12 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 25 00:41:12 motivo volumio[1065]: info: Executing endpoint metavolumio Dec 25 00:41:12 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 25 00:41:14 motivo go-librespot[9724]: time="2025-12-25T00:41:14+01:00" level=trace msg="received accesspoint ping" Dec 25 00:41:14 motivo volumio[1065]: info: CoreCommandRouter::volumioGetState Dec 25 00:41:14 motivo volumio[1065]: info: Listing playlists Dec 25 00:41:14 motivo volumio[1065]: info: Listing playlists Dec 25 00:41:14 motivo go-librespot[9724]: time="2025-12-25T00:41:14+01:00" level=trace msg="received accesspoint pong ack" Dec 25 00:41:16 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Dec 25 00:41:16 motivo volumio[1065]: info: CURURI: albums:// Dec 25 00:41:16 motivo mpd[1596]: exception: No database Dec 25 00:41:16 motivo volumio[1065]: error: Failed to execute browseSource: Error: Cannot list albums Dec 25 00:41:19 motivo volumio[1065]: error: Failed request for metavolumio API Dec 25 00:41:19 motivo volumio[1065]: info: CoreCommandRouter::volumioGetState Dec 25 00:41:21 motivo volumio[1065]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 25 00:41:21 motivo volumio[1065]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 25 00:41:21 motivo volumio[1065]: info: Retrieving Cloud Streaming UI Dec 25 00:41:21 motivo volumio[1065]: info: Getting Tidal Cloud Configuration Dec 25 00:41:21 motivo volumio[1065]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 25 00:41:21 motivo volumio[1065]: info: Getting Qobuz Cloud Configuration Dec 25 00:41:21 motivo volumio[1065]: info: Asking plugin for UI Config Dec 25 00:41:21 motivo volumio[1065]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 25 00:41:21 motivo volumio[1065]: info: Getting Spotify Cloud Configuration Dec 25 00:41:21 motivo volumio[1065]: info: Asking plugin for UI Config Dec 25 00:41:21 motivo volumio[1065]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 25 00:41:21 motivo volumio[1065]: info: Saving Spotify Acccount Dec 25 00:41:21 motivo volumio[1065]: info: Got it Dec 25 00:41:21 motivo volumio[1065]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Dec 25 00:41:21 motivo volumio[1065]: info: Got Tidal Cloud Configuration Dec 25 00:41:21 motivo volumio[1065]: info: Got it Dec 25 00:41:21 motivo volumio[1065]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 25 00:41:21 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 25 00:41:21 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 25 00:41:21 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 25 00:41:21 motivo volumio[1065]: info: CoreCommandRouter::volumioGetBrowseSources Dec 25 00:41:21 motivo volumio[1065]: info: CoreCommandRouter::volumioGetBrowseSources Dec 25 00:41:21 motivo volumio[1065]: info: CoreCommandRouter::volumioGetBrowseSources Dec 25 00:41:22 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:41:22 motivo mpd[1596]: exception: No database Dec 25 00:41:23 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Dec 25 00:41:23 motivo volumio[1065]: info: Executing endpoint metavolumio Dec 25 00:41:23 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 25 00:41:23 motivo volumio[1065]: info: Executing endpoint metavolumio Dec 25 00:41:23 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 25 00:41:24 motivo volumio[1065]: info: CoreCommandRouter::volumioGetState Dec 25 00:41:25 motivo volumio5-onboarding[1562]: time=2025-12-25T00:41:25.843+01:00 level=INFO msg="new address was allocated" component=conn/ble old=9 new=10 Dec 25 00:41:26 motivo dbus-daemon[717]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.21" (uid=0 pid=1562 comm="/usr/bin/volumio5-onboarding ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.4" (uid=0 pid=768 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn") Dec 25 00:41:26 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:41:26 motivo mpd[1596]: exception: No database Dec 25 00:41:30 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:41:30 motivo mpd[1596]: exception: No database Dec 25 00:41:30 motivo go-librespot[9724]: time="2025-12-25T00:41:30+01:00" level=trace msg="sent dealer ping" Dec 25 00:41:31 motivo go-librespot[9724]: time="2025-12-25T00:41:31+01:00" level=trace msg="received dealer pong" Dec 25 00:41:31 motivo volumio[1065]: error: Failed request for metavolumio API Dec 25 00:41:33 motivo volumio5-onboarding[1562]: time=2025-12-25T00:41:33.345+01:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=9 chunks=1 index=0 tries=0 Dec 25 00:41:33 motivo volumio5-onboarding[1562]: time=2025-12-25T00:41:33.703+01:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0900 addr=9 Dec 25 00:41:34 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: networkfs , editShare Dec 25 00:41:34 motivo sudo[12866]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount /mnt/NAS/NAS Dec 25 00:41:34 motivo sudo[12866]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 25 00:41:34 motivo systemd[1]: mnt-NAS-NAS.mount: Succeeded. Dec 25 00:41:34 motivo sudo[12866]: pam_unix(sudo:session): session closed for user root Dec 25 00:41:34 motivo volumio[1065]: info: Share NAS successfully unmounted Dec 25 00:41:34 motivo sudo[12870]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft,vers=2.1 //192.168.1.227/NAS /mnt/NAS/NAS Dec 25 00:41:34 motivo sudo[12870]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 25 00:41:34 motivo kernel: CIFS: Attempting to mount //192.168.1.227/NAS Dec 25 00:41:34 motivo volumio[1065]: info: CoreCommandRouter::volumioGetState Dec 25 00:41:34 motivo volumio[1065]: info: Listing playlists Dec 25 00:41:34 motivo sudo[12870]: pam_unix(sudo:session): session closed for user root Dec 25 00:41:34 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:41:34 motivo mpd[1596]: exception: No database Dec 25 00:41:34 motivo volumio[1065]: info: [1766619694949] Database scan error: Error: Command failed: /usr/bin/mpc update Dec 25 00:41:34 motivo volumio[1065]: MPD error: No database Dec 25 00:41:35 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Dec 25 00:41:38 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:41:38 motivo mpd[1596]: exception: No database Dec 25 00:41:42 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:41:42 motivo mpd[1596]: exception: No database Dec 25 00:41:44 motivo volumio[1065]: info: CoreCommandRouter::volumioGetState Dec 25 00:41:46 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:41:46 motivo mpd[1596]: exception: No database Dec 25 00:41:50 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:41:50 motivo mpd[1596]: exception: No database Dec 25 00:41:54 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:41:54 motivo mpd[1596]: exception: No database Dec 25 00:41:55 motivo volumio[1065]: info: CoreCommandRouter::volumioGetState Dec 25 00:41:55 motivo volumio[1065]: info: Listing playlists Dec 25 00:41:55 motivo volumio[1065]: info: Listing playlists Dec 25 00:41:58 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:41:58 motivo mpd[1596]: exception: No database Dec 25 00:42:00 motivo go-librespot[9724]: time="2025-12-25T00:42:00+01:00" level=trace msg="sent dealer ping" Dec 25 00:42:01 motivo go-librespot[9724]: time="2025-12-25T00:42:01+01:00" level=trace msg="received dealer pong" Dec 25 00:42:02 motivo volumio[1065]: info: MRS: Found cast device: S95D-7abf6571da66dbe5984cb43f4caa6faa Dec 25 00:42:02 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:42:02 motivo mpd[1596]: exception: No database Dec 25 00:42:04 motivo volumio[1065]: info: MRS: Found cast device: LS60D-90902e32c76477c36962127d5a73d27b Dec 25 00:42:04 motivo volumio[1065]: info: MRS: Found cast device: Q995GD-39ecce8be71e126bce09f484590c3140 Dec 25 00:42:04 motivo volumio[1065]: info: CoreCommandRouter::volumioGetState Dec 25 00:42:06 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:42:06 motivo mpd[1596]: exception: No database Dec 25 00:42:07 motivo nmbd[769]: [2025/12/25 00:42:07.194487, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Dec 25 00:42:07 motivo nmbd[769]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.1.60 for name WORKGROUP<1d>. Dec 25 00:42:07 motivo nmbd[769]: This response was from IP 192.168.1.62, reporting an IP address of 192.168.1.62. Dec 25 00:42:11 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:42:11 motivo mpd[1596]: exception: No database Dec 25 00:42:14 motivo volumio[1065]: info: CoreCommandRouter::volumioGetState Dec 25 00:42:14 motivo volumio[1065]: info: Listing playlists Dec 25 00:42:14 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:42:14 motivo mpd[1596]: exception: No database Dec 25 00:42:18 motivo volumio[1065]: info: MRS: Found cast device: Chromecast-Ultra-757dffe807e6d523868ba823e074fd94 Dec 25 00:42:18 motivo volumio[1065]: info: MRS: Found cast device: Smart-Connect-5.1-d7f58743424bcff44f6189084e5378a8 Dec 25 00:42:18 motivo volumio[1065]: info: MRS: Found cast device: Beosound-2-3rd-Gen-a389263720b0e455901a87875374bc02 Dec 25 00:42:18 motivo volumio[1065]: info: MRS: Found cast device: Google-Cast-Group-e449562d5e2f47089b00278e1bb6fc6f-1 Dec 25 00:42:18 motivo volumio[1065]: info: MRS: Found cast device: MagentaTV-One-(2.-Ge-c5106f83881d3c36a26767e7e7850010 Dec 25 00:42:18 motivo volumio[1065]: info: MRS: Found cast device: Cambridge-Audio-Evo--51f0d699602dd7ae8fa385838942ca4d Dec 25 00:42:18 motivo volumio[1065]: info: MRS: Found cast device: SHIELD-Android-TV-3ef922b754733c217fb01d233adf9419 Dec 25 00:42:18 motivo volumio[1065]: info: MRS: Found cast device: WiiM-Pro-Receiver-9f15915c818e12a8fc141bc0fc9a7cef Dec 25 00:42:18 motivo volumio[1065]: info: MRS: Found cast device: Pixel-Tablet-bb733d44682262a4affedb4bd95ed0db Dec 25 00:42:18 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:42:18 motivo mpd[1596]: exception: No database Dec 25 00:42:19 motivo volumio[1065]: info: MRS: Found cast device: Beosound-A5-a11eefd798fffb69662c85f01c8e7aee Dec 25 00:42:19 motivo volumio[1065]: info: MRS: Found cast device: WiiM-AMP-da40eeddddcf237a2c9e58a0e09d37fe Dec 25 00:42:19 motivo volumio[1065]: info: MRS: Found cast device: Google-Cast-Group-0b353684548d495c8cd3aeedcd712621 Dec 25 00:42:19 motivo volumio[1065]: info: MRS: Found cast device: Chromecast-Audio-026fa659971c659884fa09ffe7575a10 Dec 25 00:42:19 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: networkfs , deleteShare Dec 25 00:42:19 motivo sudo[13009]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount /mnt/NAS/NAS Dec 25 00:42:19 motivo sudo[13009]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 25 00:42:19 motivo systemd[1]: mnt-NAS-NAS.mount: Succeeded. Dec 25 00:42:19 motivo sudo[13009]: pam_unix(sudo:session): session closed for user root Dec 25 00:42:19 motivo volumio[1065]: info: Share NAS successfully unmounted Dec 25 00:42:19 motivo kernel: Bluetooth: hci0: Opcode 0x200a failed: -16 Dec 25 00:42:20 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Dec 25 00:42:22 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: networkfs , discoverShares Dec 25 00:42:22 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , browseForService Dec 25 00:42:22 motivo volumio[1065]: info: [1766619742359] Database scan error: Error: Command failed: /usr/bin/mpc update Dec 25 00:42:22 motivo volumio[1065]: MPD error: No database Dec 25 00:42:22 motivo volumio5-onboarding[1562]: time=2025-12-25T00:42:22.723+01:00 level=INFO msg="new address was allocated" component=conn/ble old=10 new=11 Dec 25 00:42:22 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:42:22 motivo mpd[1596]: exception: No database Dec 25 00:42:22 motivo dbus-daemon[717]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.21" (uid=0 pid=1562 comm="/usr/bin/volumio5-onboarding ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.4" (uid=0 pid=768 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap,hostn") Dec 25 00:42:23 motivo volumio[1065]: info: Executing SMB command: smbclient --no-pass --debuglevel=0 -L QROO41.local. -m SMB3_11 Dec 25 00:42:24 motivo volumio5-onboarding[1562]: time=2025-12-25T00:42:24.075+01:00 level=WARN msg="pending write acknowledgment timed out, retrying" component=conn/ble addr=10 chunks=1 index=0 tries=0 Dec 25 00:42:24 motivo volumio5-onboarding[1562]: time=2025-12-25T00:42:24.182+01:00 level=WARN msg="received acknowledgment for source with no pending writes" component=conn/ble data=0400 addr=4 Dec 25 00:42:25 motivo volumio[1065]: info: CoreCommandRouter::volumioGetState Dec 25 00:42:25 motivo volumio[1065]: info: Error browsing device QROO41 for shares: Command failed: smbclient --no-pass --debuglevel=0 -L QROO41.local. -m SMB3_11 Dec 25 00:42:25 motivo volumio[1065]: Unable to initialize messaging context Dec 25 00:42:26 motivo volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 25 00:42:26 motivo mpd[1596]: exception: No database Dec 25 00:42:27 motivo volumio[1065]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 25 00:42:27 motivo volumio[1065]: Error: dns service error: unknown Dec 25 00:42:27 motivo volumio[1065]: at MDNSService.on_resolver_done (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:19:30) Dec 25 00:42:27 motivo volumio[1065]: at SocketWatcher.MDNSService.self.watcher.callback (/volumio/node_modules/mdns/lib/mdns_service.js:18:40) { Dec 25 00:42:27 motivo volumio[1065]: errorCode: -65537 Dec 25 00:42:27 motivo volumio[1065]: } Dec 25 00:42:27 motivo volumio[1065]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 25 00:42:27 motivo sudo[13052]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-25 00:41 Dec 25 00:42:27 motivo sudo[13052]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="49c352e1d55e9b76c3bd7b0e3940507619bf455a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="d9e2b6784b9276d5a676bf564ce7524ad160509b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="motivo" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 19 Dec 2025 04:11:49 PM CET" VOLUMIO_VERSION="3.887" VOLUMIO_HARDWARE="cm4" VOLUMIO_DEVICENAME="CM4" VOLUMIO_VENDOR_MODEL="Volumio Motivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Motivo" VOLUMIO_HASH="c3b344bc26027ecf9c252fb696fa667b"