-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Sun 2025-06-01 12:24:44 UTC. -- Jun 01 12:23:57 volumio3 systemd-timedated[1021]: Changed local time to Sun Jun 1 12:23:57 2025 Jun 01 12:23:57 volumio3 sudo[1019]: pam_unix(sudo:session): session closed for user root Jun 01 12:23:57 volumio3 volumio-time-update[544]: volumio-time-update-util: System time updated successfully. Jun 01 12:23:57 volumio3 systemd[1]: Starting Daily apt download activities... Jun 01 12:23:57 volumio3 systemd[1]: Started Volumio Time Update Utility. Jun 01 12:23:57 volumio3 wpa_supplicant[855]: wlan0: Trying to associate with SSID 'HG8045-906B-bg' Jun 01 12:23:57 volumio3 wireless.js[532]: trying... Jun 01 12:23:57 volumio3 sudo[1045]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 01 12:23:57 volumio3 sudo[1045]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:23:57 volumio3 sudo[1045]: pam_unix(sudo:session): session closed for user root Jun 01 12:23:58 volumio3 wpa_supplicant[855]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Jun 01 12:23:58 volumio3 systemd[1]: systemd-fsckd.service: Succeeded. Jun 01 12:23:58 volumio3 nmbd[740]: [2025/06/01 12:23:58.452672, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 01 12:23:58 volumio3 nmbd[740]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Jun 01 12:23:58 volumio3 systemd[1]: Started Samba NMB Daemon. Jun 01 12:23:58 volumio3 systemd[1]: Starting Samba Winbind Daemon... Jun 01 12:23:58 volumio3 winbindd[1048]: [2025/06/01 12:23:58.704730, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Jun 01 12:23:58 volumio3 winbindd[1048]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Jun 01 12:23:58 volumio3 winbindd[1048]: [2025/06/01 12:23:58.732087, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 01 12:23:58 volumio3 winbindd[1048]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Jun 01 12:23:58 volumio3 systemd[1]: Started Samba Winbind Daemon. Jun 01 12:23:58 volumio3 systemd[1]: Starting Samba SMB Daemon... Jun 01 12:23:58 volumio3 wireless.js[532]: Overtime, starting plan B Jun 01 12:23:58 volumio3 wireless.js[532]: STARTING HOTSPOT Jun 01 12:23:59 volumio3 wpa_supplicant[855]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlan0/drop_unicast_in_l2_multicast: No such file or directory Jun 01 12:23:59 volumio3 wpa_supplicant[855]: nl80211: Failed to set IPv4 unicast in multicast filter Jun 01 12:23:59 volumio3 wpa_supplicant[855]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlan0/drop_unicast_in_l2_multicast: No such file or directory Jun 01 12:23:59 volumio3 wpa_supplicant[855]: nl80211: Failed to set IPv4 unicast in multicast filter Jun 01 12:23:59 volumio3 wpa_supplicant[855]: nl80211: deinit ifname=p2p-dev-wlan0 disabled_11b_rates=0 Jun 01 12:23:59 volumio3 wpa_supplicant[855]: p2p-dev-wlan0: CTRL-EVENT-TERMINATING Jun 01 12:23:59 volumio3 wpa_supplicant[855]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0 Jun 01 12:23:59 volumio3 systemd[1]: Started Samba SMB Daemon. Jun 01 12:23:59 volumio3 smbd[1053]: [2025/06/01 12:23:59.174465, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 01 12:23:59 volumio3 smbd[1053]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Jun 01 12:23:59 volumio3 wpa_supplicant[855]: wlan0: CTRL-EVENT-TERMINATING Jun 01 12:24:02 volumio3 sudo[1068]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Jun 01 12:24:02 volumio3 sudo[1068]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:02 volumio3 sudo[1068]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:02 volumio3 sudo[1070]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Jun 01 12:24:02 volumio3 sudo[1070]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:02 volumio3 sudo[1070]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:02 volumio3 avahi-daemon[538]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.211.1. Jun 01 12:24:02 volumio3 avahi-daemon[538]: New relevant interface wlan0.IPv4 for mDNS. Jun 01 12:24:02 volumio3 avahi-daemon[538]: Registering new address record for 192.168.211.1 on wlan0.IPv4. Jun 01 12:24:02 volumio3 kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Jun 01 12:24:02 volumio3 systemd[1]: Starting dnsmasq - A lightweight DHCP and caching DNS server... Jun 01 12:24:02 volumio3 systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator... Jun 01 12:24:02 volumio3 systemd[1]: systemd-hostnamed.service: Succeeded. Jun 01 12:24:03 volumio3 volumio-remote-updater[533]: [2025-06-01 12:24:03] [info] asio async_connect error: system:111 (Connection refused) Jun 01 12:24:03 volumio3 volumio-remote-updater[533]: [2025-06-01 12:24:03] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jun 01 12:24:03 volumio3 volumio-remote-updater[533]: [2025-06-01 12:24:03] [error] handle_connect error: Underlying Transport Error Jun 01 12:24:05 volumio3 dnsmasq[1076]: dnsmasq: syntax check OK. Jun 01 12:24:10 volumio3 hostapd[1077]: Configuration file: /etc/hostapd/hostapd.conf Jun 01 12:24:10 volumio3 hostapd[1077]: wlan0: Could not connect to kernel driver Jun 01 12:24:10 volumio3 hostapd[1077]: Using interface wlan0 with hwaddr dc:a6:32:9f:38:5a and ssid "undefined" Jun 01 12:24:10 volumio3 dnsmasq[1086]: started, version 2.80 cachesize 150 Jun 01 12:24:10 volumio3 dnsmasq[1086]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify dumpfile Jun 01 12:24:10 volumio3 dnsmasq-dhcp[1086]: DHCP, IP range 192.168.211.100 -- 192.168.211.200, lease time 1d Jun 01 12:24:10 volumio3 dnsmasq[1086]: reading /etc/resolv.conf Jun 01 12:24:10 volumio3 dnsmasq[1086]: using nameserver 208.67.222.222#53 Jun 01 12:24:10 volumio3 dnsmasq[1086]: using nameserver 208.67.220.220#53 Jun 01 12:24:10 volumio3 dnsmasq[1086]: using nameserver 192.168.1.1#53 Jun 01 12:24:10 volumio3 dnsmasq[1086]: read /etc/hosts - 3 addresses Jun 01 12:24:10 volumio3 hostapd[1077]: wlan0: interface state UNINITIALIZED->ENABLED Jun 01 12:24:10 volumio3 hostapd[1077]: wlan0: AP-ENABLED Jun 01 12:24:10 volumio3 dhcpcd[866]: wlan0: carrier acquired Jun 01 12:24:10 volumio3 systemd[1]: Started Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Jun 01 12:24:10 volumio3 dhcpcd[866]: wlan0: IAID 32:9f:38:5a Jun 01 12:24:10 volumio3 dhcpcd[866]: wlan0: adding address fe80::dea6:32ff:fe9f:385a Jun 01 12:24:10 volumio3 dhcpcd[866]: ipv6_addaddr1: Permission denied Jun 01 12:24:10 volumio3 systemd[1]: Started dnsmasq - A lightweight DHCP and caching DNS server. Jun 01 12:24:10 volumio3 systemd[1]: Reached target Host and Network Name Lookups. Jun 01 12:24:10 volumio3 iwconfig[1095]: Error for wireless request "Set Power Management" (8B2C) : Jun 01 12:24:10 volumio3 iwconfig[1095]: SET failed on device wlan0 ; Invalid argument. Jun 01 12:24:10 volumio3 systemd[1]: Started Wireless Services. Jun 01 12:24:10 volumio3 systemd[1]: Started Volumio Backend Module. Jun 01 12:24:10 volumio3 systemd[1]: Started Volumio Cpu Tweaker. Jun 01 12:24:10 volumio3 systemd[1]: Reached target Multi-User System. Jun 01 12:24:10 volumio3 systemd[1]: Reached target Graphical Interface. Jun 01 12:24:10 volumio3 systemd[1]: Starting Update UTMP about System Runlevel Changes... Jun 01 12:24:10 volumio3 dhcpcd[866]: wlan0: soliciting a DHCP lease Jun 01 12:24:10 volumio3 systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jun 01 12:24:10 volumio3 systemd[1]: Started Update UTMP about System Runlevel Changes. Jun 01 12:24:10 volumio3 dhcpcd[866]: wlan0: soliciting an IPv6 router Jun 01 12:24:11 volumio3 kernel: hwmon hwmon1: Undervoltage detected! Jun 01 12:24:11 volumio3 ntpd[748]: Listen normally on 4 wlan0 192.168.211.1:123 Jun 01 12:24:11 volumio3 ntpd[748]: new interface(s) found: waking up resolver Jun 01 12:24:13 volumio3 volumio-remote-updater[533]: [2025-06-01 12:24:13] [info] asio async_connect error: system:111 (Connection refused) Jun 01 12:24:13 volumio3 volumio-remote-updater[533]: [2025-06-01 12:24:13] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jun 01 12:24:13 volumio3 volumio-remote-updater[533]: [2025-06-01 12:24:13] [error] handle_connect error: Underlying Transport Error Jun 01 12:24:15 volumio3 dhcpcd[866]: wlan0: probing for an IPv4LL address Jun 01 12:24:15 volumio3 kernel: hwmon hwmon1: Voltage normalised Jun 01 12:24:20 volumio3 dhcpcd[866]: wlan0: using IPv4LL address 169.254.12.10 Jun 01 12:24:20 volumio3 avahi-daemon[538]: Registering new address record for 169.254.12.10 on wlan0.IPv4. Jun 01 12:24:20 volumio3 dhcpcd[866]: wlan0: adding route to 169.254.0.0/16 Jun 01 12:24:20 volumio3 volumio-cpu-tweak[1097]: Setting RT Priority for mpd Jun 01 12:24:20 volumio3 volumio-cpu-tweak[1097]: Setting MPD Affinity Jun 01 12:24:20 volumio3 volumio-cpu-tweak[1097]: pid 770's current affinity mask: f Jun 01 12:24:20 volumio3 volumio-cpu-tweak[1097]: pid 770's new affinity mask: 3 Jun 01 12:24:20 volumio3 volumio-cpu-tweak[1097]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Jun 01 12:24:20 volumio3 volumio-cpu-tweak[1097]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Jun 01 12:24:20 volumio3 systemd[1]: volumio_cpu_tweak.service: Succeeded. Jun 01 12:24:21 volumio3 ntpd[748]: Listen normally on 5 wlan0 169.254.12.10:123 Jun 01 12:24:21 volumio3 ntpd[748]: new interface(s) found: waking up resolver Jun 01 12:24:21 volumio3 systemd[1]: apt-daily.service: Succeeded. Jun 01 12:24:21 volumio3 systemd[1]: Started Daily apt download activities. Jun 01 12:24:21 volumio3 systemd[1]: Starting Daily apt upgrade and clean activities... Jun 01 12:24:22 volumio3 volumio[1096]: info: ------------------------------------------- Jun 01 12:24:22 volumio3 volumio[1096]: info: ----- Volumio3 ---- Jun 01 12:24:22 volumio3 volumio[1096]: info: ------------------------------------------- Jun 01 12:24:22 volumio3 volumio[1096]: info: ----- System startup ---- Jun 01 12:24:22 volumio3 volumio[1096]: info: ------------------------------------------- Jun 01 12:24:22 volumio3 systemd[1]: apt-daily-upgrade.service: Succeeded. Jun 01 12:24:22 volumio3 systemd[1]: Started Daily apt upgrade and clean activities. Jun 01 12:24:22 volumio3 systemd[1]: Startup finished in 13.407s (kernel) + 58.532s (userspace) = 1min 11.939s. Jun 01 12:24:23 volumio3 volumio[1096]: info: MYVOLUMIO Environment detected Jun 01 12:24:23 volumio3 volumio[1096]: info: Plugin folders cleanup Jun 01 12:24:23 volumio3 volumio[1096]: info: Scanning into folder /volumio/app/plugins/ Jun 01 12:24:23 volumio3 volumio[1096]: info: Scanning category audio_interface Jun 01 12:24:23 volumio3 volumio[1096]: info: Scanning category miscellanea Jun 01 12:24:23 volumio3 volumio[1096]: info: Scanning category music_service Jun 01 12:24:23 volumio3 volumio[1096]: info: Scanning category plugins.json Jun 01 12:24:23 volumio3 volumio[1096]: info: Scanning category system_controller Jun 01 12:24:23 volumio3 volumio[1096]: info: Scanning category user_interface Jun 01 12:24:23 volumio3 volumio[1096]: info: Scanning into folder /data/plugins/ Jun 01 12:24:23 volumio3 volumio[1096]: info: Scanning category music_service Jun 01 12:24:23 volumio3 volumio[1096]: info: Plugin folders cleanup completed Jun 01 12:24:23 volumio3 volumio[1096]: info: ------------------------------------------- Jun 01 12:24:23 volumio3 volumio[1096]: info: ----- Core plugins startup ---- Jun 01 12:24:23 volumio3 volumio[1096]: info: ------------------------------------------- Jun 01 12:24:23 volumio3 volumio[1096]: info: Loading plugins from folder /volumio/app/plugins/ Jun 01 12:24:23 volumio3 volumio[1096]: info: Adding plugin upnp to MyMusic Plugins Jun 01 12:24:23 volumio3 volumio[1096]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 01 12:24:23 volumio3 volumio[1096]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 01 12:24:23 volumio3 volumio[1096]: info: Loading plugins from folder /data/plugins/ Jun 01 12:24:23 volumio3 volumio[1096]: info: Loading plugin "system"... Jun 01 12:24:23 volumio3 volumio[1096]: info: Loading plugin "appearance"... Jun 01 12:24:23 volumio3 volumio-remote-updater[533]: [2025-06-01 12:24:23] [connect] Successful connection Jun 01 12:24:24 volumio3 volumio[1096]: info: Loading plugin "network"... Jun 01 12:24:24 volumio3 volumio[1096]: info: Refreshing Cached IP Addresses Jun 01 12:24:24 volumio3 sudo[1229]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 12:24:24 volumio3 sudo[1229]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:24 volumio3 sudo[1229]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:24 volumio3 sudo[1231]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 12:24:24 volumio3 sudo[1231]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:24 volumio3 sudo[1231]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:24 volumio3 volumio[1096]: info: Loading plugin "services"... Jun 01 12:24:24 volumio3 volumio[1096]: info: Loading plugin "alsa_controller"... Jun 01 12:24:24 volumio3 sudo[1241]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 01 12:24:24 volumio3 sudo[1241]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:24 volumio3 sudo[1241]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:24 volumio3 kernel: ieee80211 phy0: brcmf_vif_set_mgmt_ie: vndr ie set error : -52 Jun 01 12:24:24 volumio3 kernel: ieee80211 phy0: brcmf_cfg80211_scan: scan error (-52) Jun 01 12:24:24 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 12:24:24 volumio3 volumio[1096]: info: Loading plugin "wizard"... Jun 01 12:24:24 volumio3 volumio[1096]: info: Loading plugin "networkfs"... Jun 01 12:24:24 volumio3 volumio[1096]: info: Starting Udev Watcher for removable devices Jun 01 12:24:24 volumio3 sudo[1255]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft ///\\\\Jinichi_someya\\f /mnt/NAS/外付HDD Jun 01 12:24:24 volumio3 sudo[1255]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:24 volumio3 volumio[1096]: info: Ignoring mount for partition: boot Jun 01 12:24:24 volumio3 volumio[1096]: info: Ignoring mount for partition: volumio Jun 01 12:24:24 volumio3 volumio[1096]: info: Ignoring mount for partition: volumio_data Jun 01 12:24:24 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 12:24:24 volumio3 volumio[1096]: info: Loading plugin "volumio_command_line_client"... Jun 01 12:24:24 volumio3 sudo[1255]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:24 volumio3 volumio[1096]: info: Plugin upnp is not enabled Jun 01 12:24:24 volumio3 volumio[1096]: info: Loading plugin "my_music"... Jun 01 12:24:24 volumio3 volumio[1096]: info: Loading plugin "mpd"... Jun 01 12:24:24 volumio3 volumio[1096]: info: Loading plugin "upnp_browser"... Jun 01 12:24:24 volumio3 volumio[1096]: info: Loading plugin "alarm-clock"... Jun 01 12:24:25 volumio3 volumio[1096]: info: Plugin airplay_emulation is not enabled Jun 01 12:24:25 volumio3 volumio[1096]: info: Loading plugin "last_100"... Jun 01 12:24:25 volumio3 volumio[1096]: info: Loading plugin "webradio"... Jun 01 12:24:25 volumio3 volumio[1096]: info: Loading plugin "i2s_dacs"... Jun 01 12:24:25 volumio3 volumio[1096]: info: Loading plugin "volumiodiscovery"... Jun 01 12:24:25 volumio3 volumio[1096]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 12:24:25 volumio3 volumio[1096]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 12:24:25 volumio3 volumio[1096]: *** WARNING *** For more information see Jun 01 12:24:25 volumio3 volumio[1096]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 12:24:25 volumio3 volumio[1096]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 12:24:25 volumio3 volumio[1096]: *** WARNING *** For more information see Jun 01 12:24:25 volumio3 node[1096]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 12:24:25 volumio3 node[1096]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 12:24:25 volumio3 node[1096]: *** WARNING *** For more information see Jun 01 12:24:25 volumio3 node[1096]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 12:24:25 volumio3 node[1096]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 12:24:25 volumio3 node[1096]: *** WARNING *** For more information see Jun 01 12:24:25 volumio3 volumio[1096]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 01 12:24:25 volumio3 volumio[1096]: info: Discovery: Started advertising with name: Volumio3 Jun 01 12:24:25 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 12:24:25 volumio3 volumio[1096]: info: Loading plugin "spop"... Jun 01 12:24:26 volumio3 volumio[1096]: info: Loading plugin "outputs"... Jun 01 12:24:26 volumio3 volumio[1096]: info: Loading plugin "albumart"... Jun 01 12:24:26 volumio3 volumio[1096]: info: Plugin example_plugin is not enabled Jun 01 12:24:26 volumio3 volumio[1096]: info: Loading plugin "inputs"... Jun 01 12:24:26 volumio3 volumio[1096]: info: Loading plugin "updater_comm"... Jun 01 12:24:26 volumio3 volumio[1096]: info: Plugin mpdemulation is not enabled Jun 01 12:24:26 volumio3 volumio[1096]: info: Loading plugin "rest_api"... Jun 01 12:24:26 volumio3 volumio[1096]: info: Loading plugin "websocket"... Jun 01 12:24:26 volumio3 volumio[1096]: info: Starting Socket.io Server version 2.3.0 Jun 01 12:24:26 volumio3 volumio[1096]: info: Loading i18n strings for locale ja Jun 01 12:24:26 volumio3 volumio[1096]: Forking 3 albumart workers Jun 01 12:24:26 volumio3 volumio[1096]: Updating browse sources language Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::initPlayerControls Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 12:24:26 volumio3 volumio[1096]: Express server listening on port 3000 Jun 01 12:24:26 volumio3 volumio[1096]: [Metrics] WebUI: 5s 157.12ms Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreStateMachine::resetVolumioState Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreStateMachine::getcurrentVolume Jun 01 12:24:26 volumio3 volumio[1096]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 12:24:26 volumio3 volumio[1096]: info: Volumio Network Manager: Network status updated: 1 Jun 01 12:24:26 volumio3 volumio[1096]: info: Cannot mount NAS 外付HDD at system boot, trial number 1 ,retrying in 5 seconds Jun 01 12:24:27 volumio3 volumio[1096]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Jun 01 12:24:27 volumio3 volumio[1096]: wlan0 Interface doesn't support scanning : Invalid exchange Jun 01 12:24:27 volumio3 volumio[1096]: info: Cannot use regular scanning, forcing with ap-force Jun 01 12:24:27 volumio3 systemd[1]: systemd-timedated.service: Succeeded. Jun 01 12:24:27 volumio3 sudo[1299]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Jun 01 12:24:27 volumio3 sudo[1299]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:27 volumio3 volumio[1096]: Starting albumart workers Jun 01 12:24:27 volumio3 volumio[1096]: Starting albumart workers Jun 01 12:24:27 volumio3 volumio[1096]: Starting albumart workers Jun 01 12:24:30 volumio3 sudo[1299]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreStateMachine::pushState Jun 01 12:24:30 volumio3 volumio[1096]: info: CorePlayQueue::getTrack 0 Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::volumioPushState Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreStateMachine::updateTrackBlock Jun 01 12:24:30 volumio3 volumio[1096]: info: CorePlayQueue::getTrackBlock Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:24:30 volumio3 volumio[1096]: info: Reloading queue from file Jun 01 12:24:30 volumio3 volumio[1096]: info: Setting Device type: Raspberry PI Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreStateMachine::setRepeat true single undefined Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreStateMachine::pushState Jun 01 12:24:30 volumio3 volumio[1096]: info: CorePlayQueue::getTrack 0 Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::volumioPushState Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreStateMachine::setRandom true Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreStateMachine::pushState Jun 01 12:24:30 volumio3 volumio[1096]: info: CorePlayQueue::getTrack 0 Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::volumioPushState Jun 01 12:24:30 volumio3 volumio[1096]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Jun 01 12:24:30 volumio3 volumio[1096]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03112 Jun 01 12:24:30 volumio3 volumio[1096]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Jun 01 12:24:30 volumio3 volumio[1096]: info: Completed loading Core Plugins Jun 01 12:24:30 volumio3 volumio[1096]: info: Preparing to generate the ALSA configuration file Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreStateMachine::pushState Jun 01 12:24:30 volumio3 volumio[1096]: info: CorePlayQueue::getTrack 0 Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::volumioPushState Jun 01 12:24:30 volumio3 volumio[1096]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Jun 01 12:24:30 volumio3 volumio[1096]: info: Reading ALSA contributions from plugins. Jun 01 12:24:30 volumio3 volumio[1096]: info: Discovery: adding 2a285523-0092-4de3-8469-10a0978ef8ac Jun 01 12:24:30 volumio3 volumio[1096]: info: Discovery: Found device Volumio3 Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::volumioGetState Jun 01 12:24:30 volumio3 volumio[1096]: info: CorePlayQueue::getTrack 0 Jun 01 12:24:30 volumio3 volumio[1096]: info: Discovery: this is already registered, 2a285523-0092-4de3-8469-10a0978ef8ac Jun 01 12:24:30 volumio3 volumio[1096]: info: Discovery: Found device Volumio3 Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::volumioGetState Jun 01 12:24:30 volumio3 volumio[1096]: info: CorePlayQueue::getTrack 0 Jun 01 12:24:30 volumio3 volumio[1096]: info: Asound.conf file unchanged, so no further update is needed Jun 01 12:24:30 volumio3 volumio[1096]: info: Output device has changed, restarting MPD Jun 01 12:24:30 volumio3 sudo[1378]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 12:24:30 volumio3 sudo[1378]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:30 volumio3 volumio[1096]: info: ___________ START PLUGINS ___________ Jun 01 12:24:30 volumio3 sudo[1378]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:30 volumio3 volumio[1096]: info: ControllerMpd::onStart: Initializing MPD Jun 01 12:24:30 volumio3 volumio[1096]: info: Creating MPD Configuration file Jun 01 12:24:30 volumio3 sudo[1380]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 12:24:30 volumio3 sudo[1380]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:30 volumio3 systemd[1]: Stopping Music Player Daemon... Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 12:24:30 volumio3 volumio[1096]: info: [1748780670919] CoreMusicLibrary::Adding element DLNAサーバー Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 12:24:30 volumio3 sudo[1384]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 12:24:30 volumio3 sudo[1384]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:30 volumio3 sudo[1384]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:30 volumio3 sudo[1386]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 12:24:30 volumio3 sudo[1386]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 12:24:30 volumio3 volumio[1096]: info: [1748780670941] CoreMusicLibrary::Adding element Last_100 Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 12:24:30 volumio3 volumio[1096]: info: [1748780670943] CoreMusicLibrary::Adding element Webradio Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 12:24:30 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 12:24:30 volumio3 volumio[1096]: info: Initializing BBC Radios Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:24:31 volumio3 systemd[1]: mpd.service: Succeeded. Jun 01 12:24:31 volumio3 systemd[1]: Stopped Music Player Daemon. Jun 01 12:24:31 volumio3 volumio[1096]: info: Creating Spotify config file Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: Volumio Calling Home Jun 01 12:24:31 volumio3 systemd[1]: Starting Music Player Daemon... Jun 01 12:24:31 volumio3 sudo[1399]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 01 12:24:31 volumio3 sudo[1399]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:31 volumio3 sudo[1399]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:31 volumio3 volumio[1096]: info: MPD Permissions set Jun 01 12:24:31 volumio3 volumio[1096]: info: MPD Permissions set Jun 01 12:24:31 volumio3 volumio[1096]: info: Spotify config file written Jun 01 12:24:31 volumio3 sudo[1406]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 01 12:24:31 volumio3 sudo[1406]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:31 volumio3 volumio[1096]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 systemd[1]: Started go-librespot Daemon. Jun 01 12:24:31 volumio3 go-librespot[1409]: Librespot-go daemon starting... Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 sudo[1406]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 12:24:31 volumio3 volumio[1096]: info: CoreCommandRouter::volumioGetState Jun 01 12:24:31 volumio3 volumio[1096]: info: CorePlayQueue::getTrack 0 Jun 01 12:24:31 volumio3 go-librespot[1409]: time="2025-06-01T12:24:31Z" level=info msg="generated new device id: 6816ad2f9cd067d5cce0ddd982e6e6db7ac4fddf" Jun 01 12:24:31 volumio3 volumio[1096]: info: Volumio called home Jun 01 12:24:31 volumio3 go-librespot[1409]: time="2025-06-01T12:24:31Z" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 01 12:24:31 volumio3 go-librespot[1409]: time="2025-06-01T12:24:31Z" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 01 12:24:31 volumio3 go-librespot[1409]: time="2025-06-01T12:24:31Z" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 01 12:24:31 volumio3 go-librespot[1409]: time="2025-06-01T12:24:31Z" level=debug msg="zeroconf server listening on port 43809" Jun 01 12:24:31 volumio3 mpd[1404]: Jun 01 12:24 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 01 12:24:31 volumio3 systemd[1]: Started Music Player Daemon. Jun 01 12:24:31 volumio3 sudo[1380]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:31 volumio3 sudo[1386]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:31 volumio3 volumio[1096]: info: Completed starting Core Plugins Jun 01 12:24:31 volumio3 volumio[1096]: info: ------------------------------------------- Jun 01 12:24:31 volumio3 volumio[1096]: info: ----- MyVolumio plugins startup ---- Jun 01 12:24:31 volumio3 volumio[1096]: info: ------------------------------------------- Jun 01 12:24:31 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 01 12:24:31 volumio3 volumio[1096]: info: MPD running with PID1404 Jun 01 12:24:31 volumio3 volumio[1096]: ,establishing connection Jun 01 12:24:32 volumio3 volumio[1096]: error: MPD error: The expression evaluated to a falsy value: Jun 01 12:24:32 volumio3 volumio[1096]: assert.ok(self.idling) Jun 01 12:24:32 volumio3 volumio[1096]: error: The expression evaluated to a falsy value: Jun 01 12:24:32 volumio3 volumio[1096]: assert.ok(self.idling) Jun 01 12:24:32 volumio3 volumio[1096]: error: MPD error: The expression evaluated to a falsy value: Jun 01 12:24:32 volumio3 volumio[1096]: assert.ok(self.idling) Jun 01 12:24:32 volumio3 volumio[1096]: error: The expression evaluated to a falsy value: Jun 01 12:24:32 volumio3 volumio[1096]: assert.ok(self.idling) Jun 01 12:24:32 volumio3 volumio[1096]: error: updateQueue error: null Jun 01 12:24:32 volumio3 sudo[1429]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft ///\\\\Jinichi_someya\\f /mnt/NAS/外付HDD Jun 01 12:24:32 volumio3 sudo[1429]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:32 volumio3 sudo[1429]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:32 volumio3 volumio[1096]: info: Cannot mount NAS 外付HDD at system boot, trial number 2 ,retrying in 5 seconds Jun 01 12:24:34 volumio3 volumio[1096]: info: go-librespot daemon successfully initialized Jun 01 12:24:37 volumio3 sudo[1451]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft ///\\\\Jinichi_someya\\f /mnt/NAS/外付HDD Jun 01 12:24:37 volumio3 sudo[1451]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:37 volumio3 sudo[1451]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:37 volumio3 volumio[1096]: info: Cannot mount NAS 外付HDD at system boot, trial number 3 ,retrying in 5 seconds Jun 01 12:24:37 volumio3 volumio[1096]: info: Initializing connection to go-librespot Websocket Jun 01 12:24:37 volumio3 go-librespot[1409]: time="2025-06-01T12:24:37Z" level=debug msg="new websocket client" Jun 01 12:24:37 volumio3 volumio[1096]: info: Connection to go-librespot Websocket established Jun 01 12:24:38 volumio3 go-librespot[1409]: time="2025-06-01T12:24:38Z" level=debug msg="obtained new client token: AABbfsKUP7ThqoCCTbUb0xSSxcOkdmbTqFu6oZqgyu+X9b97Ua/DEWnlEKkjvZZ5TYTz/0u40diAyAnaZfmH71NxHaPMD1lr32nF92yVSYeyCpSc8y3liSSvRrEbe8Zf3ep04goSj8x9rv73SB4aE6sjEN+UK4x2jADrxJFM/bgw52+QRDLtGOkyGxl6GgbK5NhgMl6pgvJVOaZeIrO9G+6p/V1Lzpwmp30kJO6aMu19GOy9YQxeoAFh7JhM" Jun 01 12:24:38 volumio3 volumio-remote-updater[533]: [2025-06-01 12:24:38] [connect] Successful connection Jun 01 12:24:38 volumio3 volumio-remote-updater[533]: [2025-06-01 12:24:38] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1748780678 101 Jun 01 12:24:38 volumio3 volumio[1096]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 2 Jun 01 12:24:38 volumio3 go-librespot[1409]: time="2025-06-01T12:24:38Z" level=debug msg="completed keyexchange" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="completed challenge" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="authenticated as 31il6j5oyq72ha55wgz3q67uxufi" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="authenticated as 31il6j5oyq72ha55wgz3q67uxufi" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="dealer connection opened" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=info msg="accepted zeroconf user 31il6j5oyq72ha55wgz3q67uxufi from Galaxy A30" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="received connection id: ZDU1OGZjZmMtODZkNi00NmE2LWJlN2YtM2U0NTg2OWJjNzgyK2RlYWxlcit0Y3A6Ly8wYWM5NDk4ZC5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArMTgzRDA2REZCOEI0RjQyNjU5MDJFOURERUM5MkNGRkQ5Q0I0RjY3ODA2QjFFMEU0RjVFM0VGNjM1ODJFQTc2OQ==" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="put connect state because NEW_DEVICE" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="handling transfer player command from 02438a442c83fd9f46df8cf3b926572dcfcd5e2d" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=trace msg="fetched new page 0 with 33 items (list: 33)" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="loading track spotify:track:7q2FYIpq4CX2Y5IwIrCUym (paused: true, position: 313699ms)" Jun 01 12:24:39 volumio3 ntpd[748]: Soliciting pool server 133.130.121.141 Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=trace msg="emitting websocket event: will_play" Jun 01 12:24:39 volumio3 volumio[1096]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7q2FYIpq4CX2Y5IwIrCUym","play_origin":"playlist"}} Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:7q2FYIpq4CX2Y5IwIrCUym" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="requested aes key for file b608120ee7cace14f891b1d351e4036b173a942a, gid: 7q2FYIpq4CX2Y5IwIrCUym" Jun 01 12:24:39 volumio3 go-librespot[1409]: time="2025-06-01T12:24:39Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1717" Jun 01 12:24:39 volumio3 ntpd[748]: Soliciting pool server 162.159.200.1 Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="fetched first chunk of 26, total size is 13332835 bytes" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="fetched chunk 2/25, size: 524288" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="fetched chunk 1/25, size: 524288" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="fetched chunk 25/25, size: 225635" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1303" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="fetched chunk 23/25, size: 524288" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="fetched chunk 3/25, size: 524288" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="fetched chunk 24/25, size: 524288" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=trace msg="seek to 313699ms (diff: 75ms, samples: 13834125, bytes: 12490005)" Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jun 01 12:24:40 volumio3 volumio[1096]: info: Adding plugin bluetooth to MyMusic Plugins Jun 01 12:24:40 volumio3 volumio[1096]: info: Adding plugin multiroom to MyMusic Plugins Jun 01 12:24:40 volumio3 volumio[1096]: info: Adding plugin metavolumio to MyMusic Plugins Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=info msg="loaded track \"このまま君だけを奪い去りたい\" (uri: spotify:track:7q2FYIpq4CX2Y5IwIrCUym, paused: true, position: 313699ms, duration: 339440ms)" Jun 01 12:24:40 volumio3 volumio[1096]: info: Adding plugin cd_controller to MyMusic Plugins Jun 01 12:24:40 volumio3 volumio[1096]: info: Adding plugin qobuzconnect to MyMusic Plugins Jun 01 12:24:40 volumio3 volumio[1096]: info: Adding plugin smart_inputs to MyMusic Plugins Jun 01 12:24:40 volumio3 volumio[1096]: info: Adding plugin tidalconnect to MyMusic Plugins Jun 01 12:24:40 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=trace msg="emitting websocket event: metadata" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=trace msg="emitting websocket event: active" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="sending successful reply for delaer request" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 01 12:24:40 volumio3 ntpd[748]: Soliciting pool server 160.16.113.133 Jun 01 12:24:40 volumio3 ntpd[748]: Soliciting pool server 167.179.119.205 Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=trace msg="emitting websocket event: paused" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="handling update_context player command from 02438a442c83fd9f46df8cf3b926572dcfcd5e2d" Jun 01 12:24:40 volumio3 kernel: hwmon hwmon1: Undervoltage detected! Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 12:24:40 volumio3 go-librespot[1409]: time="2025-06-01T12:24:40Z" level=debug msg="sending successful reply for delaer request" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=debug msg="handling play player command from 02438a442c83fd9f46df8cf3b926572dcfcd5e2d" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=trace msg="fetched new page 0 with 3 items (list: 3)" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=debug msg="loading track spotify:track:7vevL7YTmVs4q522ueR5KC (paused: false, position: 0ms)" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=trace msg="emitting websocket event: will_play" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:7vevL7YTmVs4q522ueR5KC" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=debug msg="requested aes key for file aa6149271ba5f75030bcacbc5ccd52ab1126be10, gid: 7vevL7YTmVs4q522ueR5KC" Jun 01 12:24:41 volumio3 ntpd[748]: Soliciting pool server 45.77.20.103 Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=debug msg="fetched first chunk of 16, total size is 7908636 bytes" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=info msg="loaded track \"銀河伝説\" (uri: spotify:track:7vevL7YTmVs4q522ueR5KC, paused: false, position: 0ms, duration: 195131ms)" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=debug msg="fetched chunk 1/15, size: 524288" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=debug msg="fetched chunk 3/15, size: 524288" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=trace msg="emitting websocket event: metadata" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=debug msg="sending successful reply for delaer request" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=debug msg="fetched chunk 2/15, size: 524288" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 01 12:24:41 volumio3 go-librespot[1409]: time="2025-06-01T12:24:41Z" level=trace msg="emitting websocket event: playing" Jun 01 12:24:42 volumio3 volumio[1096]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jun 01 12:24:42 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jun 01 12:24:42 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:24:42 volumio3 volumio[1096]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 12:24:42 volumio3 volumio[1096]: info: Starting MyVolumio Remote Streaming Endpoints Jun 01 12:24:42 volumio3 volumio[1096]: info: MyVolumio login type: Token Jun 01 12:24:42 volumio3 volumio[1096]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jun 01 12:24:42 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jun 01 12:24:42 volumio3 ntpd[748]: Soliciting pool server 47.79.37.210 Jun 01 12:24:42 volumio3 ntpd[748]: Soliciting pool server 139.162.81.45 Jun 01 12:24:42 volumio3 ntpd[748]: Soliciting pool server 202.181.103.212 Jun 01 12:24:43 volumio3 ntpd[748]: Soliciting pool server 172.237.12.44 Jun 01 12:24:43 volumio3 ntpd[748]: Soliciting pool server 129.250.35.250 Jun 01 12:24:43 volumio3 volumio[1096]: info: Starting Streaming Service Transparent Proxy Jun 01 12:24:43 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jun 01 12:24:43 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jun 01 12:24:43 volumio3 volumio[1096]: info: Streaming services startup Jun 01 12:24:43 volumio3 volumio[1096]: info: Starting Streaming Daemon Jun 01 12:24:43 volumio3 sudo[1465]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 01 12:24:43 volumio3 sudo[1465]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:43 volumio3 volumio[1096]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jun 01 12:24:43 volumio3 sudo[1465]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:43 volumio3 volumio[1096]: info: Getting Spotify volume Jun 01 12:24:43 volumio3 volumio[1096]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7q2FYIpq4CX2Y5IwIrCUym","name":"このまま君だけを奪い去りたい","artist_names":["Tetsuro Oda"],"album_name":"MELODIES","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02d92192a403b42d8a79088d0d","position":313699,"duration":339440,"release_date":"year:2006 month:9 day:20","track_number":12,"disc_number":1}} Jun 01 12:24:43 volumio3 volumio[1096]: SPOTIFY: received: {"type":"active","data":null} Jun 01 12:24:43 volumio3 volumio[1096]: info: Aligning Spotify Volume to Volumio Volume Jun 01 12:24:43 volumio3 volumio[1096]: info: CoreCommandRouter::volumioGetState Jun 01 12:24:43 volumio3 volumio[1096]: info: CorePlayQueue::getTrack 0 Jun 01 12:24:43 volumio3 volumio[1096]: info: Setting Spotify Volume from Volumio: 72 Jun 01 12:24:43 volumio3 volumio[1096]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:7q2FYIpq4CX2Y5IwIrCUym","play_origin":"playlist"}} Jun 01 12:24:43 volumio3 volumio[1096]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 12:24:43 volumio3 sudo[1473]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft ///\\\\Jinichi_someya\\f /mnt/NAS/外付HDD Jun 01 12:24:43 volumio3 volumio[1096]: TypeError: Cannot read property 'service' of undefined Jun 01 12:24:43 volumio3 volumio[1096]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Jun 01 12:24:43 volumio3 volumio[1096]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Jun 01 12:24:43 volumio3 volumio[1096]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Jun 01 12:24:43 volumio3 volumio[1096]: at WebSocket.emit (events.js:315:20) Jun 01 12:24:43 volumio3 volumio[1096]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1209:20) Jun 01 12:24:43 volumio3 volumio[1096]: at Receiver.emit (events.js:315:20) Jun 01 12:24:43 volumio3 volumio[1096]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:594:14) Jun 01 12:24:43 volumio3 volumio[1096]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jun 01 12:24:43 volumio3 volumio[1096]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jun 01 12:24:43 volumio3 volumio[1096]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jun 01 12:24:43 volumio3 volumio[1096]: at writeOrBuffer (internal/streams/writable.js:358:12) Jun 01 12:24:43 volumio3 volumio[1096]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jun 01 12:24:43 volumio3 volumio[1096]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1303:35) Jun 01 12:24:43 volumio3 volumio[1096]: at Socket.emit (events.js:315:20) Jun 01 12:24:43 volumio3 volumio[1096]: at addChunk (internal/streams/readable.js:309:12) Jun 01 12:24:43 volumio3 volumio[1096]: at readableAddChunk (internal/streams/readable.js:284:9) Jun 01 12:24:43 volumio3 volumio[1096]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 12:24:43 volumio3 sudo[1473]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 01 12:24:43 volumio3 sudo[1473]: pam_unix(sudo:session): session closed for user root Jun 01 12:24:44 volumio3 sudo[1500]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-01 12:23 Jun 01 12:24:44 volumio3 sudo[1500]: 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="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"