-- Logs begin at Sun 2024-07-14 01:01:25 +09, end at Sun 2024-07-14 01:03:37 +09. -- Jul 14 01:02:01 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Jul 14 01:02:04 volumio sshd[970]: Accepted password for volumio from 192.168.0.12 port 60676 ssh2 Jul 14 01:02:04 volumio sshd[970]: pam_unix(sshd:session): session opened for user volumio by (uid=0) Jul 14 01:02:04 volumio systemd[1]: Created slice User Slice of UID 1000. Jul 14 01:02:04 volumio systemd[1]: Starting User Runtime Directory /run/user/1000... Jul 14 01:02:04 volumio systemd-logind[664]: New session 1 of user volumio. Jul 14 01:02:04 volumio systemd[1]: Started User Runtime Directory /run/user/1000. Jul 14 01:02:04 volumio systemd[1]: Starting User Manager for UID 1000... Jul 14 01:02:04 volumio systemd[1220]: pam_unix(systemd-user:session): session opened for user volumio by (uid=0) Jul 14 01:02:05 volumio systemd[1220]: Reached target Timers. Jul 14 01:02:05 volumio systemd[1220]: Listening on GnuPG cryptographic agent (ssh-agent emulation). Jul 14 01:02:05 volumio systemd[1220]: Listening on GnuPG cryptographic agent and passphrase cache. Jul 14 01:02:05 volumio systemd[1220]: Listening on GnuPG cryptographic agent and passphrase cache (restricted). Jul 14 01:02:05 volumio systemd[1220]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers). Jul 14 01:02:05 volumio systemd[1220]: Listening on GnuPG network certificate management daemon. Jul 14 01:02:05 volumio systemd[1220]: Listening on Sound System. Jul 14 01:02:05 volumio systemd[1220]: Reached target Paths. Jul 14 01:02:05 volumio systemd[1220]: Starting D-Bus User Message Bus Socket. Jul 14 01:02:05 volumio systemd[1220]: Listening on D-Bus User Message Bus Socket. Jul 14 01:02:05 volumio systemd[1220]: Reached target Sockets. Jul 14 01:02:05 volumio systemd[1220]: Reached target Basic System. Jul 14 01:02:05 volumio systemd[1]: Started User Manager for UID 1000. Jul 14 01:02:05 volumio systemd[1220]: Starting Music Player Daemon... Jul 14 01:02:05 volumio systemd[1]: Started Session 1 of user volumio. Jul 14 01:02:05 volumio mpd[1231]: exception: failed to open log file "/var/log/mpd.log" (config line 7): Permission denied Jul 14 01:02:05 volumio systemd[1220]: mpd.service: Main process exited, code=exited, status=1/FAILURE Jul 14 01:02:05 volumio systemd[1220]: mpd.service: Failed with result 'exit-code'. Jul 14 01:02:05 volumio systemd[1220]: Failed to start Music Player Daemon. Jul 14 01:02:05 volumio systemd[1220]: Reached target Default. Jul 14 01:02:05 volumio systemd[1220]: Startup finished in 868ms. Jul 14 01:02:06 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 14 01:02:06 volumio volumio[901]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Jul 14 01:02:06 volumio volumio[901]: info: CoreCommandRouter::volumioGetState Jul 14 01:02:06 volumio volumio[901]: info: CorePlayQueue::getTrack 0 Jul 14 01:02:08 volumio sudo[1243]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/sbin/ifconfig Jul 14 01:02:08 volumio sudo[1243]: pam_unix(sudo:session): session opened for user root by volumio(uid=0) Jul 14 01:02:08 volumio sudo[1243]: pam_unix(sudo:session): session closed for user root Jul 14 01:02:09 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 14 01:02:09 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 14 01:02:09 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jul 14 01:02:09 volumio volumio-remote-updater[648]: No test mode Jul 14 01:02:09 volumio volumio-remote-updater[648]: No alpha test mode Jul 14 01:02:09 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Jul 14 01:02:10 volumio volumio[901]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Jul 14 01:02:10 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Jul 14 01:02:11 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 14 01:02:11 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 14 01:02:11 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Jul 14 01:02:11 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jul 14 01:02:11 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jul 14 01:02:11 volumio volumio[901]: info: CoreCommandRouter::volumioGetBrowseSources Jul 14 01:02:11 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 14 01:02:12 volumio volumio[901]: error: MyVolumio Plugin failed to authenticate in a timely fashion Jul 14 01:02:12 volumio volumio[901]: info: Completed starting MyVolumio Plugin Jul 14 01:02:12 volumio volumio[901]: info: BOOT COMPLETED Jul 14 01:02:12 volumio volumio[901]: [Metrics] CommandRouter: 36s 591.58ms Jul 14 01:02:12 volumio volumio[901]: info: CoreCommandRouter::volumiosetStartupVolume Jul 14 01:02:12 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 14 01:02:12 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 14 01:02:12 volumio volumio[901]: info: CoreCommandRouter::Close All Modals sent Jul 14 01:02:12 volumio volumio[901]: info: CoreCommandRouter::Close All Modals sent Jul 14 01:02:12 volumio volumio[901]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav Jul 14 01:02:12 volumio volumio[901]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Jul 14 01:02:12 volumio volumio[901]: aplay: main:828: audio open error: No such device Jul 14 01:02:13 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Jul 14 01:02:13 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jul 14 01:02:13 volumio volumio[901]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Jul 14 01:02:24 volumio sudo[1250]: pam_unix(sudo:auth): authentication failure; logname=volumio uid=1000 euid=0 tty=/dev/pts/0 ruser=volumio rhost= user=volumio Jul 14 01:02:34 volumio sudo[1250]: volumio : 3 incorrect password attempts ; TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=systemclt start dhcpcd Jul 14 01:02:36 volumio ntpd[830]: Soliciting pool server 202.182.111.234 Jul 14 01:02:37 volumio ntpd[830]: Soliciting pool server 150.249.188.191 Jul 14 01:02:38 volumio ntpd[830]: Soliciting pool server 162.159.200.123 Jul 14 01:02:39 volumio ntpd[830]: Soliciting pool server 172.105.204.105 Jul 14 01:02:39 volumio ntpd[830]: Soliciting pool server 133.243.238.243 Jul 14 01:02:39 volumio ntpd[830]: Soliciting pool server 133.243.238.163 Jul 14 01:02:40 volumio ntpd[830]: Soliciting pool server 160.16.113.133 Jul 14 01:02:40 volumio ntpd[830]: Soliciting pool server 18.180.64.47 Jul 14 01:02:40 volumio ntpd[830]: Soliciting pool server 202.181.103.212 Jul 14 01:02:41 volumio ntpd[830]: Soliciting pool server 162.159.200.1 Jul 14 01:02:41 volumio ntpd[830]: Soliciting pool server 108.160.132.224 Jul 14 01:02:41 volumio ntpd[830]: Soliciting pool server 162.159.200.1 Jul 14 01:02:41 volumio ntpd[830]: Soliciting pool server 133.130.121.141 Jul 14 01:02:42 volumio ntpd[830]: Soliciting pool server 129.250.35.251 Jul 14 01:02:42 volumio ntpd[830]: Soliciting pool server 45.76.221.157 Jul 14 01:02:42 volumio ntpd[830]: Soliciting pool server 129.250.35.250 Jul 14 01:02:43 volumio ntpd[830]: Soliciting pool server 2400:8902:e001:347:0:a789:b456:c123 Jul 14 01:02:43 volumio ntpd[830]: Soliciting pool server 167.179.119.205 Jul 14 01:03:12 volumio ntpd[830]: receive: Unexpected origin timestamp 0xea3d23a3.4bc848fb does not match aorg 0000000000.00000000 from server@133.243.238.163 xmt 0xea3d23c0.4c948497 Jul 14 01:03:13 volumio ntpd[830]: Soliciting pool server 45.77.20.103 Jul 14 01:03:21 volumio sudo[1290]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/systemctl start dhcpcd Jul 14 01:03:21 volumio sudo[1290]: pam_unix(sudo:session): session opened for user root by volumio(uid=0) Jul 14 01:03:21 volumio sudo[1290]: pam_unix(sudo:session): session closed for user root Jul 14 01:03:30 volumio sudo[1294]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/systemctl start hostapd Jul 14 01:03:30 volumio sudo[1294]: pam_unix(sudo:session): session opened for user root by volumio(uid=0) Jul 14 01:03:30 volumio systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator... Jul 14 01:03:30 volumio hostapd[1297]: Configuration file: /etc/hostapd/hostapd.conf Jul 14 01:03:30 volumio hostapd[1297]: wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE Jul 14 01:03:30 volumio hostapd[1297]: wlan0: Could not connect to kernel driver Jul 14 01:03:30 volumio hostapd[1297]: Using interface wlan0 with hwaddr e4:5f:01:ef:09:c8 and ssid "music_play" Jul 14 01:03:30 volumio dhcpcd[712]: wlan0: carrier acquired Jul 14 01:03:30 volumio hostapd[1297]: wlan0: interface state COUNTRY_UPDATE->ENABLED Jul 14 01:03:30 volumio hostapd[1297]: wlan0: AP-ENABLED Jul 14 01:03:30 volumio systemd[1]: Started Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Jul 14 01:03:30 volumio dhcpcd[712]: wlan0: IAID 01:ef:09:c8 Jul 14 01:03:30 volumio dhcpcd[712]: wlan0: probing address 10.0.0.1/24 Jul 14 01:03:30 volumio sudo[1294]: pam_unix(sudo:session): session closed for user root Jul 14 01:03:31 volumio dhcpcd[712]: wlan0: soliciting an IPv6 router Jul 14 01:03:35 volumio dhcpcd[712]: wlan0: using static address 10.0.0.1/24 Jul 14 01:03:35 volumio avahi-daemon[660]: Joining mDNS multicast group on interface wlan0.IPv4 with address 10.0.0.1. Jul 14 01:03:35 volumio dhcpcd[712]: wlan0: adding route to 10.0.0.0/24 Jul 14 01:03:35 volumio avahi-daemon[660]: New relevant interface wlan0.IPv4 for mDNS. Jul 14 01:03:35 volumio avahi-daemon[660]: Registering new address record for 10.0.0.1 on wlan0.IPv4. Jul 14 01:03:36 volumio volumio[901]: info: Discovery: this is already registered, 94d7b86c-0867-4fca-be30-93c1554a4c70 Jul 14 01:03:36 volumio volumio[901]: info: Discovery: Found device Volumio Jul 14 01:03:36 volumio volumio[901]: info: CoreCommandRouter::volumioGetState Jul 14 01:03:36 volumio volumio[901]: info: CorePlayQueue::getTrack 0 Jul 14 01:03:36 volumio volumio[901]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 14 01:03:36 volumio volumio[901]: Error: The value NaN is not a number Jul 14 01:03:36 volumio volumio[901]: at Config.forceToType (/volumio/node_modules/v-conf/index.js:322:20) Jul 14 01:03:36 volumio volumio[901]: at Config.set (/volumio/node_modules/v-conf/index.js:153:25) Jul 14 01:03:36 volumio volumio[901]: at ControllerVolumioDiscovery.updateMultiroomDevice (/volumio/app/plugins/system_controller/volumiodiscovery/index.js:323:25) Jul 14 01:03:36 volumio volumio[901]: at ControllerVolumioDiscovery.connectToRemoteVolumio (/volumio/app/plugins/system_controller/volumiodiscovery/index.js:273:10) Jul 14 01:03:36 volumio volumio[901]: at Browser. (/volumio/app/plugins/system_controller/volumiodiscovery/index.js:192:12) Jul 14 01:03:36 volumio volumio[901]: at Browser.emit (events.js:315:20) Jul 14 01:03:36 volumio volumio[901]: at on_resolver_done (/volumio/node_modules/mdns/lib/browser.js:31:14) Jul 14 01:03:36 volumio volumio[901]: at next (/volumio/node_modules/mdns/lib/browser.js:106:7) Jul 14 01:03:36 volumio volumio[901]: at Array.makeAddressesUnique (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:177:5) Jul 14 01:03:36 volumio volumio[901]: at next (/volumio/node_modules/mdns/lib/browser.js:109:21) Jul 14 01:03:36 volumio volumio[901]: at /volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:160:11 Jul 14 01:03:36 volumio volumio[901]: at getaddrinfo_complete (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:108:7) Jul 14 01:03:36 volumio volumio[901]: at GetAddrInfoReqWrap.oncomplete (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:120:9) Jul 14 01:03:36 volumio volumio[901]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 14 01:03:37 volumio sudo[1329]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-14 01:02 Jul 14 01:03:37 volumio sudo[1329]: 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="4b122b2365bb8c09786cd63b50d1ea6db780eb4e" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="49f98390f2d84c6549f33dc85b694fbd99e4c720" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 04 Jun 2024 08:41:12 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="8e78a6e3f56f1bcbbd1760812129a8e9"