Oct 03 14:28:36 mp ntpd[1124]: CLOCK: time stepped by 507415.157010 Oct 03 14:28:36 mp ntpd[1124]: CLOCK: time changed from 2026-09-27 to 2026-10-03 Oct 03 14:28:36 mp ntpd[1124]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Oct 03 14:28:37 mp volumio[1346]: info: Discovery: A device disappeared from network Oct 03 14:28:37 mp volumio[1346]: info: Discovery: Device mp disappeared from network Oct 03 14:28:37 mp volumio[1346]: info: Discovery: A device disappeared from network Oct 03 14:28:37 mp volumio[1346]: info: Discovery: adding b2bfd805-fd46-4bff-a398-a92087a4a661 Oct 03 14:28:37 mp volumio[1346]: info: Discovery: Found device mp Oct 03 14:28:37 mp volumio[1346]: info: CoreCommandRouter::volumioGetState Oct 03 14:28:37 mp volumio[1346]: info: CorePlayQueue::getTrack 0 Oct 03 14:28:37 mp volumio[1346]: info: Discovery: this is already registered, b2bfd805-fd46-4bff-a398-a92087a4a661 Oct 03 14:28:37 mp volumio[1346]: info: Discovery: Found device mp Oct 03 14:28:37 mp volumio[1346]: info: CoreCommandRouter::volumioGetState Oct 03 14:28:37 mp volumio[1346]: info: CorePlayQueue::getTrack 0 Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.418+08:00 level=INFO msg="established new WebSocket connection" component=conn/ws remoteAddr=192.168.0.4:49796 Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.441+08:00 level=INFO msg="app ready event" component=server event=CLIENT_EVENT_TYPE_APP_READY peer="192.168.0.4:49796 @ 0x210e9c0" latency=16.385301ms platform=PLATFORM_IOS version=6.260807.0 Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.441+08:00 level=INFO msg="device data request" component=server type=REQUEST_TYPE_DEVICE_DATA peer="192.168.0.4:49796 @ 0x210e9c0" latency=16.542486ms timeout=20s Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.441+08:00 level=INFO msg="emitting device capabilities changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 03 14:28:38 mp volumio[1346]: info: Received Get System Info Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 03 14:28:38 mp volumio[1346]: info: Discovery: Getting this device information Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::volumioGetState Oct 03 14:28:38 mp volumio[1346]: info: CorePlayQueue::getTrack 0 Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.443+08:00 level=INFO msg="emitting device name changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" name=mp Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.445+08:00 level=INFO msg="emitting device language changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" language=en Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getCurrentTimezone Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.446+08:00 level=INFO msg="emitting device timezone changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" timezone=Asia/Singapore Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.446+08:00 level=INFO msg="emitting ethernet info changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" available=true connected=true macAddress=2c:cf:67:01:ba:b3 ip4Address=192.168.0.5/24 ip6Address= Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.447+08:00 level=INFO msg="emitting wifi info changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" available=true connected=false macAddress= ip4Address= ip6Address= ssid= Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.447+08:00 level=INFO msg="emitting device setup status changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" setupComplete=true Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getExtendedOutputDevices Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 03 14:28:38 mp volumio[1346]: amixer -c 0 info | grep "vc4-hdmi-0" Oct 03 14:28:38 mp volumio[1346]: Card sysdefault:0 'vc4hdmi0'/'vc4-hdmi-0' Oct 03 14:28:38 mp volumio[1346]: amixer -c 1 info | grep "vc4-hdmi-1" Oct 03 14:28:38 mp volumio[1346]: Card sysdefault:1 'vc4hdmi1'/'vc4-hdmi-1' Oct 03 14:28:38 mp volumio[1346]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Oct 03 14:28:38 mp volumio[1346]: /bin/sh: 1: /usr/local/bin/alsacap: not found Oct 03 14:28:38 mp volumio[1346]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Oct 03 14:28:38 mp volumio[1346]: amixer -c 5 info | grep "XMOS USB AUDIO" Oct 03 14:28:38 mp volumio[1346]: Card sysdefault:5 'AUDIO'/'SkySong XMOS USB AUDIO at usb-xhci-hcd.1-2, high speed' Oct 03 14:28:38 mp volumio[1346]: error: Cannot read Audio Device Capabilities Command failed: /usr/local/bin/alsacap -C 5 Oct 03 14:28:38 mp volumio[1346]: /bin/sh: 1: /usr/local/bin/alsacap: not found Oct 03 14:28:38 mp volumio[1346]: {"cmd":"/usr/local/bin/alsacap -C 5","code":127,"killed":false,"signal":null,"stack":"Error: Command failed: /usr/local/bin/alsacap -C 5\n/bin/sh: 1: /usr/local/bin/alsacap: not found\n\n at ChildProcess.exithandler (node:child_process:421:12)\n at ChildProcess.emit (node:events:514:28)\n at maybeClose (node:internal/child_process:1105:16)\n at Socket. (node:internal/child_process:457:11)\n at Socket.emit (node:events:514:28)\n at Pipe. (node:net:337:12)"} Oct 03 14:28:38 mp volumio[1346]: amixer -c 5 info | grep "XMOS USB AUDIO" Oct 03 14:28:38 mp volumio[1346]: Card sysdefault:5 'AUDIO'/'SkySong XMOS USB AUDIO at usb-xhci-hcd.1-2, high speed' Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.492+08:00 level=INFO msg="emitting audio outputs changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" selectedOutputId=5 Oct 03 14:28:38 mp volumio[1346]: info: Received Get System Info Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 03 14:28:38 mp volumio[1346]: info: Discovery: Getting this device information Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::volumioGetState Oct 03 14:28:38 mp volumio[1346]: info: CorePlayQueue::getTrack 0 Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.496+08:00 level=INFO msg="emitting software info changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" currentVersion=4.119 latestVersion=4.119 Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.496+08:00 level=INFO msg="emitting software update progress event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" status=UPDATE_STATUS_NONE progress=0 Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.498+08:00 level=INFO msg="emitting user changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" userId= Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.499+08:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=tidal error="could not open plugin config file for \"tidal\": open /data/configuration/music_service/tidal/config.json: no such file or directory" Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.499+08:00 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=qobuz error="could not open plugin config file for \"qobuz\": open /data/configuration/music_service/qobuz/config.json: no such file or directory" Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.499+08:00 level=WARN msg="could not read username/password data for music provider" component=volumio provider=hi_res_audio error="could not open plugin config file for \"hi_res_audio\": open /data/configuration/music_service/hi_res_audio/config.json: no such file or directory" Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.499+08:00 level=INFO msg="emitting music providers changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" providers=3 Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.500+08:00 level=INFO msg="emitting plugins changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" plugins=0 Oct 03 14:28:38 mp volumio[1346]: info: CoreCommandRouter::volumioGetState Oct 03 14:28:38 mp volumio[1346]: info: CorePlayQueue::getTrack 0 Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.501+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" state=STATUS_STOPPED positionMs=0 volume=100 Oct 03 14:28:38 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:38.501+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.4:49796 @ 0x210e9c0" id="music-library/USB/ntfs-disk/music/蔡琴 (Tsai Chin)/精選 Hi Fi頂級人聲天碟試 (Featured Hi Fi Vocals)/01 渡口.m4a" title="1 - 渡口" Oct 03 14:28:39 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 03 14:28:39 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 03 14:28:39 mp volumio[1346]: info: Discovery: Getting this device information Oct 03 14:28:39 mp volumio[1346]: info: CoreCommandRouter::volumioGetState Oct 03 14:28:39 mp volumio[1346]: info: CorePlayQueue::getTrack 0 Oct 03 14:28:39 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 03 14:28:39 mp volumio[1346]: verbose: New Socket.io Connection to 192.168.0.5:3000 from 192.168.0.4 UA: Dart/3.12 (dart:io) Engine version: 3 Transport: websocket Total Clients: 4 Oct 03 14:28:39 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 03 14:28:39 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 03 14:28:41 mp bluealsa[1086]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_5D_CA_4E_2A_76_55, ...) Oct 03 14:28:41 mp systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Oct 03 14:28:41 mp systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Oct 03 14:28:41 mp systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Oct 03 14:28:41 mp systemd[1]: dpkg-db-backup.service: Deactivated successfully. Oct 03 14:28:41 mp systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Oct 03 14:28:43 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:43.185+08:00 level=INFO msg="new address was allocated" component=ble/conn old=1 new=2 Oct 03 14:28:43 mp dbus-daemon[932]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.13" (uid=0 pid=1560 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.1" (uid=0 pid=931 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Oct 03 14:28:43 mp systemd[1]: systemd-fsckd.service: Deactivated successfully. Oct 03 14:28:43 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:43.935+08:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=14.786455ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Oct 03 14:28:43 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:43.959+08:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s Oct 03 14:28:44 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:44.039+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=80.608866ms Oct 03 14:28:44 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:44.080+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=https://google.com duration=121.124364ms Oct 03 14:28:44 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:44.108+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=149.070767ms Oct 03 14:28:44 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:44.113+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=153.930394ms Oct 03 14:28:44 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:44.127+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=https://www.googleapis.com duration=168.489884ms Oct 03 14:28:44 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:44.248+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=https://securetoken.googleapis.com duration=289.217302ms Oct 03 14:28:44 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:44.301+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=http://pushupdates.volumio.org duration=341.937487ms Oct 03 14:28:44 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:44.344+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=https://functions.volumio.cloud duration=384.536362ms Oct 03 14:28:44 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:44.344+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=https://functions.volumio.cloud duration=384.275899ms Oct 03 14:28:44 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:44.443+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=484.077084ms Oct 03 14:28:44 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:44.564+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=https://database.volumio.cloud duration=604.157037ms Oct 03 14:28:44 mp sudo[1901]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 03 14:28:44 mp sudo[1901]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 03 14:28:44 mp sudo[1903]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 03 14:28:44 mp sudo[1903]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 03 14:28:44 mp sudo[1901]: pam_unix(sudo:session): session closed for user root Oct 03 14:28:44 mp sudo[1903]: pam_unix(sudo:session): session closed for user root Oct 03 14:28:44 mp volumio[1346]: verbose: New Socket.io Connection to 192.168.0.5 from 192.168.0.4 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 4 Oct 03 14:28:44 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:44.681+08:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=http://plugins.volumio.org duration=721.449204ms Oct 03 14:28:44 mp systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Oct 03 14:28:44 mp systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Oct 03 14:28:44 mp systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Oct 03 14:28:44 mp systemd[1]: systemd-hostnamed.service: Deactivated successfully. Oct 03 14:28:44 mp sudo[1822]: pam_unix(sudo:session): session closed for user root Oct 03 14:28:44 mp volumio[1346]: info: Upmpdcli Daemon Started Oct 03 14:28:44 mp sudo[1927]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 03 14:28:44 mp sudo[1929]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 03 14:28:44 mp sudo[1927]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 03 14:28:44 mp sudo[1929]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 03 14:28:44 mp sudo[1929]: pam_unix(sudo:session): session closed for user root Oct 03 14:28:44 mp sudo[1927]: pam_unix(sudo:session): session closed for user root Oct 03 14:28:44 mp volumio[1346]: verbose: New Socket.io Connection to 192.168.0.5 from 192.168.0.4 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 4 Oct 03 14:28:45 mp volumio[1346]: info: CoreCommandRouter::volumioGetState Oct 03 14:28:45 mp volumio[1346]: info: CorePlayQueue::getTrack 0 Oct 03 14:28:45 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 03 14:28:45 mp volumio[1346]: info: Listing playlists Oct 03 14:28:45 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 03 14:28:45 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 03 14:28:45 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 03 14:28:45 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 03 14:28:45 mp volumio5-onboarding[1560]: time=2026-10-03T14:28:45.157+08:00 level=ERROR msg="endpoint is not reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.4:49796,00:00:00:00:00:00%01 @ 0x210e9c0" latency=16.03926ms timeout=10s endpoint=http://cddb.volumio.org duration=1.1976458s error="Head \"http://gnudb.gnudb.org/~cddb/cddb.cgi/\": EOF" Oct 03 14:28:47 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 03 14:28:47 mp volumio[1346]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 03 14:28:47 mp volumio[1346]: info: CoreCommandRouter::volumioGetState Oct 03 14:28:47 mp volumio[1346]: info: CorePlayQueue::getTrack 0 Oct 03 14:28:47 mp volumio[1346]: info: CoreCommandRouter::volumioGetQueue Oct 03 14:28:47 mp volumio[1346]: info: CoreStateMachine::getQueue Oct 03 14:28:47 mp volumio[1346]: info: CorePlayQueue::getQueue Oct 03 14:28:50 mp volumio[1346]: info: CoreCommandRouter::volumioGetVisibleSources Oct 03 14:28:50 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 03 14:28:51 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 03 14:28:51 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 03 14:28:51 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 03 14:28:51 mp volumio-remote-updater[956]: Test mode disabled Oct 03 14:28:51 mp volumio-remote-updater[956]: Alpha mode disabled Oct 03 14:28:51 mp volumio-remote-updater[956]: Alpha legacy test mode disabled Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::volumioGetBrowseSources Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 03 14:28:52 mp volumio[1346]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 03 14:28:52 mp volumio[1346]: error: MyVolumio Plugin failed to authenticate in a timely fashion Oct 03 14:28:52 mp volumio[1346]: info: Completed starting MyVolumio Plugin Oct 03 14:28:52 mp volumio[1346]: [Metrics] CommandRouter: 32s 618.51ms Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::volumiosetStartupVolume Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::Close All Modals sent Oct 03 14:28:52 mp volumio[1346]: info: CoreCommandRouter::Close All Modals sent Oct 03 14:28:53 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 03 14:28:53 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 03 14:28:53 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 03 14:28:54 mp upmpdcli[1957]: writing RSA key Oct 03 14:28:54 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 03 14:28:54 mp volumio[1346]: info: CURURI: albums:// Oct 03 14:28:54 mp volumio[1346]: info: listAlbums - loading Albums from cache Oct 03 14:28:54 mp volumio[1346]: info: Preload queue cleared Oct 03 14:28:59 mp volumio[1346]: info: BOOT COMPLETED Oct 03 14:29:03 mp systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Oct 03 14:29:03 mp systemd[1]: setdatetime-helper.service: Deactivated successfully. Oct 03 14:29:03 mp systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Oct 03 14:29:03 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 03 14:29:03 mp volumio[1346]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 03 14:29:03 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 03 14:29:03 mp volumio[1346]: info: Received Get System Version Oct 03 14:29:03 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 03 14:29:03 mp volumio[1346]: info: Received Get System Info Oct 03 14:29:03 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 03 14:29:03 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 03 14:29:03 mp volumio[1346]: info: Discovery: Getting this device information Oct 03 14:29:03 mp volumio[1346]: info: CoreCommandRouter::volumioGetState Oct 03 14:29:03 mp volumio[1346]: info: CorePlayQueue::getTrack 0 Oct 03 14:29:03 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 03 14:29:21 mp volumio[1346]: Searching all installed plugins Oct 03 14:29:21 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 03 14:29:21 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: , search Oct 03 14:29:21 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: mpd , search Oct 03 14:29:21 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Oct 03 14:29:21 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Oct 03 14:29:21 mp volumio[1346]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Oct 03 14:29:21 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: webradio , search Oct 03 14:29:21 mp volumio[1346]: info: All search sources collected, pushing search results Oct 03 14:29:22 mp volumio[1346]: Searching all installed plugins Oct 03 14:29:22 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 03 14:29:22 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: , search Oct 03 14:29:22 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: mpd , search Oct 03 14:29:22 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Oct 03 14:29:22 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Oct 03 14:29:22 mp volumio[1346]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Oct 03 14:29:22 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: webradio , search Oct 03 14:29:23 mp volumio[1346]: info: All search sources collected, pushing search results Oct 03 14:29:24 mp volumio[1346]: Searching all installed plugins Oct 03 14:29:24 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 03 14:29:24 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: , search Oct 03 14:29:24 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: mpd , search Oct 03 14:29:24 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Oct 03 14:29:24 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Oct 03 14:29:24 mp volumio[1346]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Oct 03 14:29:24 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: webradio , search Oct 03 14:29:24 mp volumio[1346]: info: All search sources collected, pushing search results Oct 03 14:29:25 mp volumio[1346]: Searching all installed plugins Oct 03 14:29:25 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 03 14:29:25 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: , search Oct 03 14:29:25 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: mpd , search Oct 03 14:29:25 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , search Oct 03 14:29:25 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Oct 03 14:29:25 mp volumio[1346]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Oct 03 14:29:25 mp volumio[1346]: info: CoreCommandRouter::executeOnPlugin: webradio , search Oct 03 14:29:25 mp volumio[1346]: info: All search sources collected, pushing search results Oct 03 14:29:29 mp volumio[1346]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 03 14:29:29 mp volumio[1346]: TypeError: Cannot read properties of null (reading 'slice') Oct 03 14:29:29 mp volumio[1346]: at download (/volumio/app/plugins/miscellanea/albumart/albumart.js:718:41) Oct 03 14:29:29 mp volumio[1346]: at ClientRequest. (/volumio/app/plugins/miscellanea/albumart/albumart.js:728:7) Oct 03 14:29:29 mp volumio[1346]: at Object.onceWrapper (node:events:629:26) Oct 03 14:29:29 mp volumio[1346]: at ClientRequest.emit (node:events:514:28) Oct 03 14:29:29 mp volumio[1346]: at HTTPParser.parserOnIncomingClient [as onIncoming] (node:_http_client:693:27) Oct 03 14:29:29 mp volumio[1346]: at HTTPParser.parserOnHeadersComplete (node:_http_common:119:17) Oct 03 14:29:29 mp volumio[1346]: at TLSSocket.socketOnData (node:_http_client:535:22) Oct 03 14:29:29 mp volumio[1346]: at TLSSocket.emit (node:events:514:28) Oct 03 14:29:29 mp volumio[1346]: at addChunk (node:internal/streams/readable:343:12) Oct 03 14:29:29 mp volumio[1346]: at readableAddChunk (node:internal/streams/readable:316:9) Oct 03 14:29:29 mp volumio[1346]: at Readable.push (node:internal/streams/readable:253:10) Oct 03 14:29:29 mp volumio[1346]: at TLSWrap.onStreamRead (node:internal/stream_base_commons:190:23) Oct 03 14:29:29 mp volumio[1346]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 03 14:29:29 mp sudo[2046]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-03 14:28' Oct 03 14:29:29 mp sudo[2046]: 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"