Oct 28 19:51:03 volumio volumio[1097]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatest/Bluetoothremote/volumio/bookworm/armhf Oct 28 19:51:03 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Oct 28 19:51:03 volumio dbus-daemon[613]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.24' (uid=0 pid=1995 comm="timedatectl show --property=NTPSynchronized --valu") Oct 28 19:51:03 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... Oct 28 19:51:04 volumio dbus-daemon[613]: [system] Successfully activated service 'org.freedesktop.timedate1' Oct 28 19:51:04 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. Oct 28 19:51:04 volumio setdatetime-helper.sh[1993]: Time is not synchronized. Attempting to sync... Oct 28 19:51:04 volumio sudo[2004]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Tue, 28 Oct 2025 10:51:04 GMT#015' Oct 28 19:51:04 volumio sudo[2004]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:51:04 volumio setdatetime-helper.sh[2005]: Tue Oct 28 19:51:04 JST 2025 Oct 28 19:51:04 volumio systemd-journald[339]: Time jumped backwards, rotating. Oct 28 19:51:04 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Oct 28 19:51:04 volumio sudo[2004]: pam_unix(sudo:session): session closed for user root Oct 28 19:51:04 volumio setdatetime-helper.sh[1993]: Time synchronized successfully. Oct 28 19:51:04 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Oct 28 19:51:06 volumio volumio[1097]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatest/Bluetoothremote/volumio/bookworm/armhf Oct 28 19:51:06 volumio volumio[1097]: info: Folder /tmp/plugins removed Oct 28 19:51:07 volumio volumio[1097]: info: Check plugin dependencies Oct 28 19:51:07 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 28 19:51:07 volumio volumio[1097]: info: Checking if plugin already exists Oct 28 19:51:07 volumio volumio[1097]: info: Rename folder Oct 28 19:51:07 volumio volumio[1097]: info: Folder /tmp/downloaded_plugin.zip removed Oct 28 19:51:08 volumio volumio[1097]: info: Move to category Oct 28 19:51:09 volumio volumio[1097]: info: Checking if install.sh is present Oct 28 19:51:09 volumio volumio[1097]: info: Executing install.sh Oct 28 19:51:09 volumio sudo[2043]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/system_hardware/Bluetoothremote/install.sh Oct 28 19:51:09 volumio sudo[2043]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 28 19:51:09 volumio volumio[1097]: info: Installing Bluetooth Remote Plugin Dependencies Oct 28 19:51:10 volumio sudo[2047]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/apt update Oct 28 19:51:10 volumio sudo[2047]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:51:11 volumio volumio[1097]: info: Get:1 https://deb.nodesource.com/node_20.x bookworm InRelease [4586 B] Oct 28 19:51:11 volumio volumio[1097]: info: Get:2 http://archive.raspberrypi.com/debian bookworm InRelease [54.9 kB] Oct 28 19:51:12 volumio volumio[1097]: info: Get:3 http://raspbian.raspberrypi.com/raspbian bookworm InRelease [15.0 kB] Oct 28 19:51:12 volumio volumio[1097]: info: Get:4 https://deb.nodesource.com/node_20.x bookworm/main armhf Packages [783 B] Oct 28 19:51:13 volumio volumio[1097]: info: Get:5 http://raspbian.raspberrypi.com/raspbian bookworm/main armhf Packages [14.5 MB] Oct 28 19:51:13 volumio volumio[1097]: info: Get:6 http://archive.raspberrypi.com/debian bookworm/main armhf Packages [560 kB] Oct 28 19:51:14 volumio volumio[1097]: info: Get:7 http://archive.raspberrypi.com/debian bookworm/untested armhf Packages [1114 B] Oct 28 19:51:33 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Oct 28 19:51:38 volumio volumio[1097]: info: Get:8 http://raspbian.raspberrypi.com/raspbian bookworm/contrib armhf Packages [62.3 kB] Oct 28 19:51:39 volumio volumio[1097]: info: Get:9 http://raspbian.raspberrypi.com/raspbian bookworm/non-free armhf Packages [118 kB] Oct 28 19:51:42 volumio volumio[1097]: info: Get:10 http://raspbian.raspberrypi.com/raspbian bookworm/rpi armhf Packages [1360 B] Oct 28 19:51:50 volumio volumio[1097]: info: Fetched 15.3 MB in 37s (417 kB/s) Oct 28 19:51:55 volumio volumio[1097]: info: Reading package lists... Oct 28 19:51:57 volumio volumio[1097]: info: Building dependency tree... Oct 28 19:51:58 volumio volumio[1097]: info: Reading state information... Oct 28 19:51:58 volumio volumio[1097]: info: 109 packages can be upgraded. Run 'apt list --upgradable' to see them. Oct 28 19:51:58 volumio sudo[2047]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:04 volumio sudo[2410]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/apt install -y evtest Oct 28 19:52:04 volumio sudo[2410]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:52:04 volumio volumio[1097]: info: Reading package lists... Oct 28 19:52:05 volumio volumio[1097]: info: Building dependency tree... Oct 28 19:52:05 volumio volumio[1097]: info: Reading state information... Oct 28 19:52:07 volumio volumio[1097]: info: The following additional packages will be installed: Oct 28 19:52:07 volumio volumio[1097]: info: evemu-tools libevdev2 libevemu3 Oct 28 19:52:07 volumio volumio[1097]: info: The following NEW packages will be installed: Oct 28 19:52:07 volumio volumio[1097]: info: evemu-tools evtest libevdev2 libevemu3 Oct 28 19:52:08 volumio volumio[1097]: info: 0 upgraded, 4 newly installed, 0 to remove and 109 not upgraded. Oct 28 19:52:08 volumio volumio[1097]: info: Need to get 67.5 kB of archives. Oct 28 19:52:08 volumio volumio[1097]: info: After this operation, 249 kB of additional disk space will be used. Oct 28 19:52:08 volumio volumio[1097]: info: Get:1 http://raspbian.raspberrypi.com/raspbian bookworm/main armhf libevdev2 armhf 1.13.0+dfsg-1+rpi1 [27.9 kB] Oct 28 19:52:08 volumio volumio[1097]: info: Get:2 http://ftp.udx.icscoe.jp/Linux/raspbian/raspbian bookworm/main armhf libevemu3 armhf 2.7.0-3 [11.5 kB] Oct 28 19:52:09 volumio volumio[1097]: info: Get:3 http://ftp.udx.icscoe.jp/Linux/raspbian/raspbian bookworm/main armhf evemu-tools armhf 2.7.0-3 [14.3 kB] Oct 28 19:52:10 volumio volumio[1097]: info: Get:4 http://ftp.udx.icscoe.jp/Linux/raspbian/raspbian bookworm/main armhf evtest armhf 1:1.35-1 [13.8 kB] Oct 28 19:52:10 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Oct 28 19:52:10 volumio dbus-daemon[613]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.27' (uid=0 pid=2459 comm="timedatectl show --property=NTPSynchronized --valu") Oct 28 19:52:10 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... Oct 28 19:52:11 volumio dbus-daemon[613]: [system] Successfully activated service 'org.freedesktop.timedate1' Oct 28 19:52:11 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. Oct 28 19:52:11 volumio setdatetime-helper.sh[2458]: Time is not synchronized. Attempting to sync... Oct 28 19:52:11 volumio sudo[2471]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Tue, 28 Oct 2025 10:52:12 GMT#015' Oct 28 19:52:11 volumio sudo[2471]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:52:12 volumio setdatetime-helper.sh[2472]: Tue Oct 28 19:52:12 JST 2025 Oct 28 19:52:12 volumio sudo[2471]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:12 volumio setdatetime-helper.sh[2458]: Time synchronized successfully. Oct 28 19:52:12 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Oct 28 19:52:12 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Oct 28 19:52:12 volumio volumio[1097]: info: Fetched 67.5 kB in 3s (26.7 kB/s) Oct 28 19:52:12 volumio volumio[1097]: info: Selecting previously unselected package libevdev2:armhf. Oct 28 19:52:14 volumio volumio[1097]: [620B blob data] Oct 28 19:52:14 volumio volumio[1097]: info: Preparing to unpack .../libevdev2_1.13.0+dfsg-1+rpi1_armhf.deb ... Oct 28 19:52:14 volumio volumio[1097]: info: Unpacking libevdev2:armhf (1.13.0+dfsg-1+rpi1) ... Oct 28 19:52:15 volumio volumio[1097]: info: Selecting previously unselected package libevemu3:armhf. Oct 28 19:52:15 volumio volumio[1097]: info: Preparing to unpack .../libevemu3_2.7.0-3_armhf.deb ... Oct 28 19:52:15 volumio volumio[1097]: info: Unpacking libevemu3:armhf (2.7.0-3) ... Oct 28 19:52:15 volumio volumio[1097]: info: Selecting previously unselected package evemu-tools. Oct 28 19:52:15 volumio volumio[1097]: info: Preparing to unpack .../evemu-tools_2.7.0-3_armhf.deb ... Oct 28 19:52:15 volumio volumio[1097]: info: Unpacking evemu-tools (2.7.0-3) ... Oct 28 19:52:17 volumio volumio[1097]: info: Selecting previously unselected package evtest. Oct 28 19:52:17 volumio volumio[1097]: info: Preparing to unpack .../evtest_1%3a1.35-1_armhf.deb ... Oct 28 19:52:17 volumio volumio[1097]: info: Unpacking evtest (1:1.35-1) ... Oct 28 19:52:17 volumio volumio[1097]: info: Setting up evtest (1:1.35-1) ... Oct 28 19:52:17 volumio volumio[1097]: info: Setting up libevdev2:armhf (1.13.0+dfsg-1+rpi1) ... Oct 28 19:52:17 volumio volumio[1097]: info: Setting up libevemu3:armhf (2.7.0-3) ... Oct 28 19:52:17 volumio volumio[1097]: info: Setting up evemu-tools (2.7.0-3) ... Oct 28 19:52:17 volumio volumio[1097]: info: Processing triggers for libc-bin (2.36-9+rpt2+deb12u10) ... Oct 28 19:52:21 volumio ntpd[827]: CLOCK: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Oct 28 19:52:22 volumio ntpd[827]: CLOCK: time stepped by 0.784132 Oct 28 19:52:22 volumio ntpd[827]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Oct 28 19:52:22 volumio ntpd[827]: CLOCK: frequency error 2355 PPM exceeds tolerance 500 PPM Oct 28 19:52:22 volumio sudo[2410]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:22 volumio sudo[2568]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /data/INTERNAL/Bluetooth_Remote Oct 28 19:52:22 volumio sudo[2568]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:52:22 volumio sudo[2568]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:22 volumio sudo[2571]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/chown -R volumio /data/INTERNAL/Bluetooth_Remote Oct 28 19:52:22 volumio sudo[2571]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:52:22 volumio sudo[2571]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:22 volumio sudo[2573]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/chgrp -R volumio /data/INTERNAL/Bluetooth_Remote Oct 28 19:52:22 volumio sudo[2573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:52:22 volumio sudo[2573]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:22 volumio sudo[2575]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/chmod -R 777 /data/INTERNAL/Bluetooth_Remote Oct 28 19:52:22 volumio sudo[2575]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:52:22 volumio sudo[2575]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:22 volumio sudo[2577]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /etc/systemd/system/triggerhappy.service.d Oct 28 19:52:22 volumio sudo[2577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:52:22 volumio sudo[2577]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:22 volumio sudo[2579]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/tee /etc/systemd/system/triggerhappy.service.d/override.conf Oct 28 19:52:22 volumio sudo[2579]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:52:22 volumio sudo[2579]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:22 volumio sudo[2581]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/systemctl daemon-reexec Oct 28 19:52:22 volumio sudo[2581]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:52:22 volumio systemd[1]: Reexecuting. Oct 28 19:52:23 volumio systemd[1]: systemd 252.36-1~deb12u1+rpi1 running in system mode (+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT default-hierarchy=unified) Oct 28 19:52:23 volumio systemd[1]: Detected architecture arm. Oct 28 19:52:24 volumio sudo[2581]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:24 volumio sudo[2601]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/systemctl daemon-reload Oct 28 19:52:24 volumio sudo[2601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:52:24 volumio systemd[1]: Reloading. Oct 28 19:52:26 volumio sudo[2601]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:26 volumio sudo[2637]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/systemctl restart triggerhappy Oct 28 19:52:26 volumio sudo[2637]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 28 19:52:26 volumio systemd[1]: Stopping triggerhappy.service - triggerhappy global hotkey daemon... Oct 28 19:52:26 volumio systemd[1]: triggerhappy.service: Deactivated successfully. Oct 28 19:52:26 volumio systemd[1]: Stopped triggerhappy.service - triggerhappy global hotkey daemon. Oct 28 19:52:26 volumio systemd[1]: Starting triggerhappy.service - triggerhappy global hotkey daemon... Oct 28 19:52:27 volumio thd[2639]: Found socket passed from systemd Oct 28 19:52:27 volumio systemd[1]: Started triggerhappy.service - triggerhappy global hotkey daemon. Oct 28 19:52:27 volumio sudo[2637]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:27 volumio sudo[2043]: pam_unix(sudo:session): session closed for user root Oct 28 19:52:27 volumio volumio[1097]: info: Install script completed Oct 28 19:52:27 volumio volumio[1097]: info: Adding reference to registry Oct 28 19:52:29 volumio volumio[1097]: info: Done installing plugin. Oct 28 19:52:29 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 28 19:52:29 volumio volumio[1097]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 28 19:52:29 volumio volumio[1097]: Plugin install end detected on script Oct 28 19:52:29 volumio volumio[1097]: info: Folder /tmp/plugins removed Oct 28 19:52:29 volumio volumio[1097]: info: Folder /tmp/downloaded_plugin.zip removed Oct 28 19:52:29 volumio volumio[1097]: info: Folder /data/temp removed Oct 28 19:52:30 volumio volumio[1097]: info: Enabling plugin Bluetoothremote Oct 28 19:52:30 volumio volumio[1097]: info: Loading plugin "Bluetoothremote"... Oct 28 19:52:31 volumio volumio[1097]: info: PLUGIN START: Bluetoothremote Oct 28 19:52:31 volumio volumio[1097]: info: Loading i18n strings for locale ja Oct 28 19:52:31 volumio volumio[1097]: info: Done. Oct 28 19:52:35 volumio volumio[1097]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 28 19:52:35 volumio volumio[1097]: error: Bluetoothremote--- Failed to read remote_devices.json: Error: ENOENT: no such file or directory, open '/data/plugins/system_hardware/Bluetoothremote/remote_devices.json' Oct 28 19:52:35 volumio bluetoothd[721]: Adv Monitor app :1.30 disconnected from D-Bus Oct 28 19:52:35 volumio volumio[1097]: warn: Bluetoothremote--- Failed to get connected devices: Oct 28 19:52:42 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Oct 28 19:52:56 volumio volumio[1097]: info: Bluetoothremote--- Checking for trusted devices to reconnect... Oct 28 19:52:56 volumio volumio[1097]: info: Bluetoothremote--- Device list cleared and placeholder written. Oct 28 19:52:56 volumio bluetoothd[721]: Adv Monitor app :1.31 disconnected from D-Bus Oct 28 19:52:56 volumio volumio[1097]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 28 19:52:56 volumio volumio[1097]: TypeError: Cannot read properties of null (reading 'message') Oct 28 19:52:56 volumio volumio[1097]: at /data/plugins/system_hardware/Bluetoothremote/index.js:224:97 Oct 28 19:52:56 volumio volumio[1097]: at ChildProcess.exithandler (node:child_process:413:7) Oct 28 19:52:56 volumio volumio[1097]: at ChildProcess.emit (node:events:514:28) Oct 28 19:52:56 volumio volumio[1097]: at maybeClose (node:internal/child_process:1105:16) Oct 28 19:52:56 volumio volumio[1097]: at ChildProcess._handle.onexit (node:internal/child_process:305:5) Oct 28 19:52:56 volumio volumio[1097]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 28 19:52:57 volumio sudo[2764]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-28 19:51' Oct 28 19:52:57 volumio sudo[2764]: 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="4a70cb031e64a8e498efc3e29470650871ff7d54" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat May 31 04:09:10 UTC 2025" VOLUMIO_VERSION="4.005" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="f9bd4447a30d4b2c74b3880e7a50e48b"