-- Logs begin at Thu 2024-08-29 07:51:36 CEST, end at Thu 2024-08-29 08:20:48 CEST. -- Aug 29 08:19:23 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 08:19:23 volumio ntpd[814]: receive: Unexpected origin timestamp 0xea7a8b3b.fcb7b333 does not match aorg 0000000000.00000000 from server@185.19.184.35 xmt 0xea7a916b.2585e689 Aug 29 08:19:23 volumio ntpd[814]: receive: Unexpected origin timestamp 0xea7a8b3b.fcc5ba0a does not match aorg 0000000000.00000000 from server@212.45.144.88 xmt 0xea7a916b.252e9816 Aug 29 08:19:23 volumio ntpd[814]: receive: Unexpected origin timestamp 0xea7a8b3b.fc9303b0 does not match aorg 0000000000.00000000 from server@31.14.133.93 xmt 0xea7a916b.2669e735 Aug 29 08:19:23 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 08:19:23 volumio ntpd[814]: receive: Unexpected origin timestamp 0xea7a8b3b.fca4784d does not match aorg 0000000000.00000000 from server@193.204.114.233 xmt 0xea7a916b.278815ca Aug 29 08:19:23 volumio ntpd[814]: receive: Unexpected origin timestamp 0xea7a8b3b.fcae3658 does not match aorg 0000000000.00000000 from server@93.94.88.51 xmt 0xea7a916b.27e2d92c Aug 29 08:19:23 volumio ntpd[814]: receive: Unexpected origin timestamp 0xea7a8b3b.fcb2f9f3 does not match aorg 0000000000.00000000 from server@93.94.88.50 xmt 0xea7a916b.284a4d15 Aug 29 08:19:23 volumio ntpd[814]: receive: Unexpected origin timestamp 0xea7a8b3b.fcbc59a9 does not match aorg 0000000000.00000000 from server@129.152.16.145 xmt 0xea7a916b.2789af61 Aug 29 08:19:23 volumio ntpd[814]: receive: Unexpected origin timestamp 0xea7a8b3b.fcaa5981 does not match aorg 0000000000.00000000 from server@85.199.214.99 xmt 0xea7a916b.282114ad Aug 29 08:19:23 volumio volumio[1094]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Aug 29 08:19:23 volumio volumio[1094]: error: MyVolumio Plugin failed to authenticate in a timely fashion Aug 29 08:19:23 volumio volumio[1094]: info: Completed starting MyVolumio Plugin Aug 29 08:19:23 volumio volumio[1094]: info: BOOT COMPLETED Aug 29 08:19:23 volumio volumio[1094]: [Metrics] CommandRouter: 55s 588.62ms Aug 29 08:19:23 volumio volumio[1094]: info: CoreCommandRouter::volumiosetStartupVolume Aug 29 08:19:23 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 29 08:19:23 volumio volumio[1094]: info: VolumeController:: Setting startup Volume 10 Aug 29 08:19:23 volumio volumio[1094]: info: VolumeController::SetAlsaVolume10 Aug 29 08:19:23 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 08:19:23 volumio volumio[1094]: info: CoreCommandRouter::Close All Modals sent Aug 29 08:19:23 volumio volumio[1094]: info: CoreCommandRouter::Close All Modals sent Aug 29 08:19:24 volumio volumio[1094]: info: CoreStateMachine::pushState Aug 29 08:19:24 volumio volumio[1094]: info: CorePlayQueue::getTrack 0 Aug 29 08:19:24 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 29 08:19:24 volumio volumio[1094]: info: CoreCommandRouter::volumioPushState Aug 29 08:19:24 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Aug 29 08:19:24 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Aug 29 08:19:25 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 29 08:19:25 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Aug 29 08:19:26 volumio volumio[1094]: info: MYVOLUMIO: Adding device Aug 29 08:19:26 volumio volumio[1094]: info: MYVOLUMIO: Evaluating Server Aug 29 08:19:27 volumio volumio[1386]: .................++++ Aug 29 08:19:27 volumio volumio[1386]: e is 65537 (0x010001) Aug 29 08:19:27 volumio volumio[1386]: writing RSA key Aug 29 08:19:35 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 29 08:19:35 volumio volumio[1094]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 29 08:19:35 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 29 08:19:35 volumio volumio[1094]: info: Received Get System Version Aug 29 08:19:35 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 29 08:19:35 volumio volumio[1094]: info: Received Get System Info Aug 29 08:19:35 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 29 08:19:35 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 29 08:19:35 volumio volumio[1094]: info: Discovery: Getting this device information Aug 29 08:19:35 volumio volumio[1094]: info: CoreCommandRouter::volumioGetState Aug 29 08:19:35 volumio volumio[1094]: info: CorePlayQueue::getTrack 0 Aug 29 08:19:35 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 29 08:19:42 volumio volumio[1094]: info: Setting Geolocation for MyVolumio to eu6 Aug 29 08:19:42 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 08:19:42 volumio volumio[1094]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Aug 29 08:19:43 volumio volumio[1094]: info: Updating MyVolumio device info Aug 29 08:19:43 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 29 08:19:43 volumio volumio[1094]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Aug 29 08:19:55 volumio wpa_supplicant[949]: wlan0: CTRL-EVENT-DISCONNECTED bssid=30:b5:c2:81:10:c4 reason=0 locally_generated=1 Aug 29 08:19:55 volumio dhcpcd[1010]: wlan0: carrier lost Aug 29 08:19:55 volumio wpa_supplicant[949]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Aug 29 08:19:55 volumio avahi-daemon[620]: Withdrawing address record for 192.168.0.217 on wlan0. Aug 29 08:19:55 volumio avahi-daemon[620]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.217. Aug 29 08:19:55 volumio avahi-daemon[620]: Interface wlan0.IPv4 no longer relevant for mDNS. Aug 29 08:19:55 volumio dhcpcd[1010]: wlan0: deleting route to 192.168.0.0/24 Aug 29 08:19:55 volumio dhcpcd[1010]: wlan0: deleting default route via 192.168.0.1 Aug 29 08:19:55 volumio volumio[1094]: info: Discovery: A device disappeared from network Aug 29 08:19:55 volumio volumio[1094]: info: Discovery: Device volumio disappeared from network Aug 29 08:19:55 volumio wpa_supplicant[949]: wlan0: Trying to associate with SSID 'PdB-Iliad' Aug 29 08:19:56 volumio wpa_supplicant[949]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Aug 29 08:19:56 volumio wpa_supplicant[949]: wlan0: Trying to associate with SSID 'PdB-Iliad' Aug 29 08:19:57 volumio dhcpcd[1010]: wlan0: carrier acquired Aug 29 08:19:57 volumio dhcpcd[1010]: wlan0: connected to Access Point `PdB-Iliad' Aug 29 08:19:57 volumio wpa_supplicant[949]: wlan0: Associated with 3a:07:16:6a:57:f4 Aug 29 08:19:57 volumio wpa_supplicant[949]: wlan0: CTRL-EVENT-CONNECTED - Connection to 3a:07:16:6a:57:f4 completed [id=1 id_str=] Aug 29 08:19:57 volumio wpa_supplicant[949]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Aug 29 08:19:57 volumio dhcpcd[1010]: wlan0: IAID eb:e5:0c:6f Aug 29 08:19:57 volumio dhcpcd[1010]: wlan0: carrier lost Aug 29 08:19:57 volumio dhcpcd[1010]: wlan0: carrier acquired Aug 29 08:19:57 volumio dhcpcd[1010]: wlan0: IAID eb:e5:0c:6f Aug 29 08:19:58 volumio dhcpcd[1010]: wlan0: rebinding lease of 192.168.1.170 Aug 29 08:19:58 volumio dhcpcd[1010]: wlan0: soliciting an IPv6 router Aug 29 08:19:59 volumio ntpd[814]: Deleting interface #4 wlan0, 192.168.0.217#123, interface stats: received=0, sent=0, dropped=0, active_time=94 secs Aug 29 08:20:00 volumio volumio[1094]: info: CoreCommandRouter::volumioGetVisibleSources Aug 29 08:20:00 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 29 08:20:00 volumio volumio[1094]: info: CoreCommandRouter::volumioGetQueue Aug 29 08:20:00 volumio volumio[1094]: info: CoreStateMachine::getQueue Aug 29 08:20:00 volumio volumio[1094]: info: CorePlayQueue::getQueue Aug 29 08:20:02 volumio dhcpcd[1010]: wlan0: probing address 192.168.1.170/24 Aug 29 08:20:07 volumio dhcpcd[1010]: wlan0: leased 192.168.1.170 for 43200 seconds Aug 29 08:20:07 volumio avahi-daemon[620]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.170. Aug 29 08:20:07 volumio dhcpcd[1010]: wlan0: adding route to 192.168.1.0/24 Aug 29 08:20:07 volumio dhcpcd[1010]: wlan0: adding default route via 192.168.1.254 Aug 29 08:20:07 volumio avahi-daemon[620]: New relevant interface wlan0.IPv4 for mDNS. Aug 29 08:20:07 volumio avahi-daemon[620]: Registering new address record for 192.168.1.170 on wlan0.IPv4. Aug 29 08:20:08 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 29 08:20:08 volumio volumio[1094]: info: Discovery: adding 11505e53-5a03-45fd-af32-7284db026d32 Aug 29 08:20:08 volumio volumio[1094]: info: Discovery: Found device Volumio Aug 29 08:20:08 volumio volumio[1094]: info: CoreCommandRouter::volumioGetState Aug 29 08:20:08 volumio volumio[1094]: info: CorePlayQueue::getTrack 0 Aug 29 08:20:08 volumio volumio[1094]: info: Preload queue cleared Aug 29 08:20:09 volumio ntpd[814]: Listen normally on 5 wlan0 192.168.1.170:123 Aug 29 08:20:09 volumio ntpd[814]: new interface(s) found: waking up resolver Aug 29 08:20:09 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 29 08:20:09 volumio volumio[1094]: info: Preload queue cleared Aug 29 08:20:11 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 29 08:20:11 volumio volumio[1094]: info: Preload queue cleared Aug 29 08:20:19 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 29 08:20:20 volumio volumio[1094]: info: Preload queue cleared Aug 29 08:20:22 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 29 08:20:23 volumio volumio[1094]: info: Preload queue cleared Aug 29 08:20:23 volumio volumio[1094]: info: Preloading song: upnp/http://192.168.0.251:50001/ContentDirectory/control@22$@1633 Aug 29 08:20:23 volumio volumio[1094]: info: Exploding uri upnp/http://192.168.0.251:50001/ContentDirectory/control@22$@1633 in service upnp_browser Aug 29 08:20:43 volumio kernel: hwmon hwmon1: Voltage normalised Aug 29 08:20:45 volumio kernel: hwmon hwmon1: Undervoltage detected! Aug 29 08:20:46 volumio volumio[1094]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 29 08:20:46 volumio volumio[1094]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 08:20:46 volumio volumio[1094]: TypeError: Cannot read property 'length' of undefined Aug 29 08:20:46 volumio volumio[1094]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Aug 29 08:20:46 volumio volumio[1094]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Aug 29 08:20:46 volumio volumio[1094]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Aug 29 08:20:46 volumio volumio[1094]: at Parser.emit (events.js:315:20) Aug 29 08:20:46 volumio volumio[1094]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Aug 29 08:20:46 volumio volumio[1094]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Aug 29 08:20:46 volumio volumio[1094]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Aug 29 08:20:46 volumio volumio[1094]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Aug 29 08:20:46 volumio volumio[1094]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Aug 29 08:20:46 volumio volumio[1094]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Aug 29 08:20:46 volumio volumio[1094]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Aug 29 08:20:46 volumio volumio[1094]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Aug 29 08:20:46 volumio volumio[1094]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Aug 29 08:20:46 volumio volumio[1094]: at IncomingMessage.emit (events.js:327:22) Aug 29 08:20:46 volumio volumio[1094]: at endReadableNT (internal/streams/readable.js:1327:12) Aug 29 08:20:46 volumio volumio[1094]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Aug 29 08:20:46 volumio volumio[1094]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 29 08:20:47 volumio nmbd[800]: [2024/08/29 08:20:47.241295, 0] ../source3/libsmb/nmblib.c:917(send_udp) Aug 29 08:20:47 volumio nmbd[800]: Packet send failed to 192.168.0.255(138) ERRNO=Network is unreachable Aug 29 08:20:48 volumio sudo[2092]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-29 08:19 Aug 29 08:20:48 volumio sudo[2092]: 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="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"