-- Logs begin at Thu 2019-02-14 14:11:59 +04, end at Fri 2025-03-07 19:48:57 +04. -- Mar 07 19:47:01 volumioavi ntpd[825]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Mar 07 19:47:02 volumioavi go-librespot[1226]: time="2025-03-07T19:47:02+04:00" level=error msg="failed receiving dealer message" error="failed to get reader: WebSocket closed: sent close frame: status = StatusServiceRestart and reason = \"\"" Mar 07 19:47:02 volumioavi go-librespot[1226]: time="2025-03-07T19:47:02+04:00" level=debug msg="renewing login5 access token" Mar 07 19:47:07 volumioavi volumio[1017]: info: MRS: Found cast device: SHIELD-Android-TV-813580c23a3cb9b61f5247fe1953a058 Mar 07 19:47:07 volumioavi volumio[1017]: info: MRS: Found cast device: SHIELD-Android-TV-a005a5a23c7cd054e50c37b20429ba26 Mar 07 19:47:27 volumioavi go-librespot[1226]: time="2025-03-07T19:47:27+04:00" level=error msg="did not receive last pong from dealer, 90s passed" Mar 07 19:47:29 volumioavi ntpd[825]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Mar 07 19:47:31 volumioavi go-librespot[1226]: time="2025-03-07T19:47:31+04:00" level=debug msg="renewing login5 access token" Mar 07 19:47:45 volumioavi volumiossh-tunnel[10593]: Timeout, server as2.myvolumio.org not responding. Mar 07 19:47:45 volumioavi autossh[10595]: ssh exited with error status 255; restarting ssh Mar 07 19:47:45 volumioavi autossh[10595]: starting ssh (count 3) Mar 07 19:47:45 volumioavi autossh[10595]: ssh child pid is 16529 Mar 07 19:47:49 volumioavi volumio[1017]: verbose: New Socket.io Connection to 192.168.115.3:3000 from 192.168.115.101 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Mar 07 19:47:49 volumioavi volumio[1017]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Mar 07 19:47:49 volumioavi volumio[1017]: info: CoreCommandRouter::volumioGetState Mar 07 19:47:49 volumioavi volumio[1017]: info: CorePlayQueue::getTrack 0 Mar 07 19:47:49 volumioavi volumio[1017]: verbose: New Socket.io Connection to 192.168.115.3 from 192.168.115.112 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:135.0) Gecko/20100101 Firefox/135.0 Engine version: 3 Transport: polling Total Clients: 7 Mar 07 19:47:49 volumioavi volumio[1017]: verbose: New Socket.io Connection to 192.168.115.3 from 192.168.115.112 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:135.0) Gecko/20100101 Firefox/135.0 Engine version: 3 Transport: polling Total Clients: 8 Mar 07 19:47:49 volumioavi volumio[1017]: verbose: New Socket.io Connection to 192.168.115.3 from 192.168.115.112 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:135.0) Gecko/20100101 Firefox/135.0 Engine version: 3 Transport: polling Total Clients: 9 Mar 07 19:47:50 volumioavi volumio[1017]: info: Discovery: adding 06e39b70-c61b-428c-96af-9ac745155797 Mar 07 19:47:50 volumioavi volumio[1017]: info: Discovery: Found device VolumioAvi Mar 07 19:47:50 volumioavi volumio[1017]: info: CoreCommandRouter::volumioGetState Mar 07 19:47:50 volumioavi volumio[1017]: info: CorePlayQueue::getTrack 0 Mar 07 19:47:50 volumioavi go-librespot[1226]: time="2025-03-07T19:47:50+04:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.115.3:54226->34.158.255.62:4070: read: connection reset by peer" Mar 07 19:47:50 volumioavi volumio[1017]: info: [squeezelite_mc] 'client' notification received from LMS (192.168.115.224); type is 'disconnect' Mar 07 19:47:50 volumioavi volumio[1017]: info: CoreCommandRouter::volumioGetState Mar 07 19:47:50 volumioavi volumio[1017]: info: CorePlayQueue::getTrack 0 Mar 07 19:47:50 volumioavi volumio[1017]: info: [squeezelite_mc] 'client' notification received from LMS (192.168.115.224); type is 'disconnect' Mar 07 19:47:50 volumioavi go-librespot[1226]: time="2025-03-07T19:47:50+04:00" level=debug msg="authenticated as tjh431buwf471lmsrkm5umbes" Mar 07 19:47:50 volumioavi go-librespot[1226]: time="2025-03-07T19:47:50+04:00" level=debug msg="completed keyexchange" Mar 07 19:47:51 volumioavi go-librespot[1226]: time="2025-03-07T19:47:51+04:00" level=debug msg="re-established dealer connection" Mar 07 19:47:51 volumioavi go-librespot[1226]: time="2025-03-07T19:47:51+04:00" level=debug msg="received connection id: YTBiYWRiMGYtNzE5My00ZWQ1LWJlYmEtYjI2MzkwMGY5MTkxK2RlYWxlcit0Y3A6Ly8wYWM5NDllNi5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArNjg5RDE0NzU5NzA2RDc4MDA0RkU0RjkxMTA0NzhFNUU5NzJEMUYyRTExQ0E1OTg3NTE5QkFDRDFFREIzMkQyRg==" Mar 07 19:47:51 volumioavi volumio[1017]: info: [squeezelite_mc] 'client' notification received from LMS (192.168.115.224); type is 'connect' Mar 07 19:47:51 volumioavi volumio[1017]: info: [squeezelite_mc] Getting players connected to LMS (192.168.115.224) Mar 07 19:47:51 volumioavi volumio[1017]: info: [squeezelite_mc] Players connected to LMS (192.168.115.224): [{"id":"40:62:31:12:68:76","uuid":null,"ip":"192.168.115.101","name":"MC-VolumioTom","server":{"ip":"192.168.115.224","name":"LMS","ver":"9.0.1","uuid":"0cc9d0f4-00c8-4426-869c-243a6e2b7975","jsonPort":"9000","cliPort":"9090"}}] Mar 07 19:47:51 volumioavi go-librespot[1226]: time="2025-03-07T19:47:51+04:00" level=debug msg="completed challenge" Mar 07 19:47:51 volumioavi go-librespot[1226]: time="2025-03-07T19:47:51+04:00" level=debug msg="put connect state because NEW_DEVICE" Mar 07 19:47:51 volumioavi go-librespot[1226]: time="2025-03-07T19:47:51+04:00" level=debug msg="authenticated as tjh431buwf471lmsrkm5umbes" Mar 07 19:47:51 volumioavi go-librespot[1226]: time="2025-03-07T19:47:51+04:00" level=debug msg="re-established accesspoint connection" Mar 07 19:47:51 volumioavi go-librespot[1226]: time="2025-03-07T19:47:51+04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 07 19:47:51 volumioavi go-librespot[1226]: time="2025-03-07T19:47:51+04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 07 19:47:51 volumioavi go-librespot[1226]: time="2025-03-07T19:47:51+04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 07 19:47:51 volumioavi go-librespot[1226]: time="2025-03-07T19:47:51+04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 07 19:47:51 volumioavi go-librespot[1226]: time="2025-03-07T19:47:51+04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 07 19:47:51 volumioavi ntpd[825]: Soliciting pool server 2001:ac8:81:65:0:2:0:2 Mar 07 19:47:51 volumioavi volumiossh-tunnel[10593]: Warning: Permanently added '[as2.myvolumio.org]:2222,[165.232.189.9]:2222' (RSA) to the list of known hosts. Mar 07 19:47:51 volumioavi volumio[1017]: verbose: New Socket.io Connection to 192.168.115.3 from 192.168.115.112 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:135.0) Gecko/20100101 Firefox/135.0 Engine version: 3 Transport: polling Total Clients: 10 Mar 07 19:47:51 volumioavi volumio[1017]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 07 19:47:51 volumioavi volumio[1017]: info: CoreCommandRouter::volumioGetVisibleSources Mar 07 19:47:51 volumioavi volumio[1017]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 07 19:47:51 volumioavi volumio[1017]: info: CoreCommandRouter::volumioGetState Mar 07 19:47:51 volumioavi volumio[1017]: info: CorePlayQueue::getTrack 0 Mar 07 19:47:51 volumioavi volumio[1017]: info: CoreCommandRouter::volumioGetState Mar 07 19:47:51 volumioavi volumio[1017]: info: CorePlayQueue::getTrack 0 Mar 07 19:47:51 volumioavi volumio[1017]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 07 19:47:51 volumioavi volumio[1017]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 07 19:47:51 volumioavi volumio[1017]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Mar 07 19:47:51 volumioavi volumio[1017]: info: Received Get System Info Mar 07 19:47:51 volumioavi volumio[1017]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 07 19:47:51 volumioavi volumio[1017]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 07 19:47:51 volumioavi volumio[1017]: info: Discovery: Getting this device information Mar 07 19:47:51 volumioavi volumio[1017]: info: CoreCommandRouter::volumioGetState Mar 07 19:47:51 volumioavi volumio[1017]: info: CorePlayQueue::getTrack 0 Mar 07 19:47:51 volumioavi volumio[1017]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 07 19:47:51 volumioavi volumio[1017]: info: CoreCommandRouter::volumioGetState Mar 07 19:47:51 volumioavi volumio[1017]: info: CorePlayQueue::getTrack 0 Mar 07 19:47:51 volumioavi volumio[1017]: info: Listing playlists Mar 07 19:47:52 volumioavi volumiossh-tunnel[10593]: Warning: remote port forwarding failed for listen port 8091 Mar 07 19:47:52 volumioavi volumio[1017]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 07 19:47:52 volumioavi volumio[1017]: info: [squeezelite_mc] 'client' notification received from LMS (192.168.115.224); type is 'connect' Mar 07 19:47:52 volumioavi volumio[1017]: info: [squeezelite_mc] Getting players connected to LMS (192.168.115.224) Mar 07 19:47:52 volumioavi volumio[1017]: info: [squeezelite_mc] Players connected to LMS (192.168.115.224): [{"id":"40:62:31:12:68:76","uuid":null,"ip":"192.168.115.101","name":"MC-VolumioTom","server":{"ip":"192.168.115.224","name":"LMS","ver":"9.0.1","uuid":"0cc9d0f4-00c8-4426-869c-243a6e2b7975","jsonPort":"9000","cliPort":"9090"}},{"id":"d8:3a:dd:d9:e6:d3","uuid":null,"ip":"192.168.115.3","name":"MC-VolumioAvi","server":{"ip":"192.168.115.224","name":"LMS","ver":"9.0.1","uuid":"0cc9d0f4-00c8-4426-869c-243a6e2b7975","jsonPort":"9000","cliPort":"9090"}}] Mar 07 19:47:52 volumioavi volumio[1017]: info: [squeezelite_mc] Player found: {"id":"d8:3a:dd:d9:e6:d3","uuid":null,"ip":"192.168.115.3","name":"MC-VolumioAvi","server":{"ip":"192.168.115.224","name":"LMS","ver":"9.0.1","uuid":"0cc9d0f4-00c8-4426-869c-243a6e2b7975","jsonPort":"9000","cliPort":"9090"}} Mar 07 19:47:53 volumioavi volumio[1017]: (node:1017) UnhandledPromiseRejectionWarning: TypeError: Cannot read property '0' of undefined Mar 07 19:47:53 volumioavi volumio[1017]: at PlayerStatusMonitor._PlayerStatusMonitor_parsePlayerStatusResult (/data/plugins/music_service/squeezelite_mc/dist/lib/PlayerStatusMonitor.js:180:37) Mar 07 19:47:53 volumioavi volumio[1017]: at PlayerStatusMonitor._PlayerStatusMonitor_getStatusAndEmit (/data/plugins/music_service/squeezelite_mc/dist/lib/PlayerStatusMonitor.js:118:129) Mar 07 19:47:53 volumioavi volumio[1017]: at runMicrotasks () Mar 07 19:47:53 volumioavi volumio[1017]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Mar 07 19:47:53 volumioavi volumio[1017]: at async PlayerStatusMonitor.start (/data/plugins/music_service/squeezelite_mc/dist/lib/PlayerStatusMonitor.js:47:9) Mar 07 19:47:53 volumioavi volumio[1017]: at async PlayerFinder. (/data/plugins/music_service/squeezelite_mc/dist/index.js:686:13) Mar 07 19:47:53 volumioavi volumio[1017]: (node:1017) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 5) Mar 07 19:47:55 volumioavi volumio[1017]: info: Executing endpoint metavolumio Mar 07 19:47:55 volumioavi volumio[1017]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 07 19:47:55 volumioavi volumio[1017]: info: Executing endpoint metavolumio Mar 07 19:47:55 volumioavi volumio[1017]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 07 19:47:55 volumioavi volumio[1017]: info: Executing endpoint metavolumio Mar 07 19:47:55 volumioavi volumio[1017]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Mar 07 19:47:56 volumioavi volumio[1017]: info: MRS: Found cast device: Google-TV-Streamer-d93f5c4db63cf55ec2da4b0de2891cf5 Mar 07 19:48:16 volumioavi ntpd[825]: Soliciting pool server 2001:ac8:81:65:0:2:0:3 Mar 07 19:48:18 volumioavi volumio[1017]: info: Discovery: adding e807ec30-74e6-469e-9cbc-c83dfe51a9fe Mar 07 19:48:18 volumioavi volumio[1017]: info: Discovery: Found device VolumioTom Mar 07 19:48:18 volumioavi volumio[1017]: info: Discovery: Connecting to remote: 192.168.115.101 Mar 07 19:48:18 volumioavi volumio[1017]: info: MRS: Pushing audio output on request Mar 07 19:48:18 volumioavi volumio[1017]: info: MRS: Pushing multiroomSync output Mar 07 19:48:18 volumioavi volumio[1017]: info: Discovery: Connected to remote: 192.168.115.101 Mar 07 19:48:51 volumioavi wpa_supplicant[921]: wlan0: Associated with 60:83:e7:80:a3:cb Mar 07 19:48:51 volumioavi dhcpcd[932]: wlan0: carrier lost Mar 07 19:48:51 volumioavi wpa_supplicant[921]: wlan0: CTRL-EVENT-CONNECTED - Connection to 60:83:e7:80:a3:cb completed [id=0 id_str=] Mar 07 19:48:51 volumioavi wpa_supplicant[921]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Mar 07 19:48:51 volumioavi avahi-daemon[692]: Withdrawing address record for 192.168.115.3 on wlan0. Mar 07 19:48:51 volumioavi avahi-daemon[692]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.115.3. Mar 07 19:48:51 volumioavi avahi-daemon[692]: Interface wlan0.IPv4 no longer relevant for mDNS. Mar 07 19:48:51 volumioavi dhcpcd[932]: wlan0: deleting route to 192.168.115.0/24 Mar 07 19:48:51 volumioavi dhcpcd[932]: wlan0: deleting default route via 192.168.115.1 Mar 07 19:48:51 volumioavi volumio[1017]: info: Discovery: A device disappeared from network Mar 07 19:48:51 volumioavi volumio[1017]: info: Discovery: Device volumiotom disappeared from network Mar 07 19:48:51 volumioavi volumio[1017]: info: Discovery: Disconnected from remote: 192.168.115.101 Mar 07 19:48:51 volumioavi volumio[1017]: info: Discovery: A device disappeared from network Mar 07 19:48:51 volumioavi volumio[1017]: info: Discovery: Device volumioavi disappeared from network Mar 07 19:48:51 volumioavi dhcpcd[932]: wlan0: carrier acquired Mar 07 19:48:51 volumioavi dhcpcd[932]: wlan0: IAID dd:d9:e6:d3 Mar 07 19:48:51 volumioavi dhcpcd[932]: wlan0: probing address 192.168.115.3/24 Mar 07 19:48:51 volumioavi dhcpcd[932]: wlan0: soliciting an IPv6 router Mar 07 19:48:52 volumioavi ntpd[825]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Mar 07 19:48:53 volumioavi ntpd[825]: Deleting interface #6 wlan0, 192.168.115.3#123, interface stats: received=3, sent=9, dropped=0, active_time=161 secs Mar 07 19:48:53 volumioavi ntpd[825]: 47.91.111.180 local addr 192.168.115.3 -> Mar 07 19:48:53 volumioavi ntpd[825]: 109.196.101.121 local addr 192.168.115.3 -> Mar 07 19:48:53 volumioavi ntpd[825]: 5.32.10.107 local addr 192.168.115.3 -> Mar 07 19:48:55 volumioavi nmbd[779]: [2025/03/07 19:48:55.247450, 0] ../source3/libsmb/nmblib.c:917(send_udp) Mar 07 19:48:55 volumioavi nmbd[779]: Packet send failed to 192.168.115.234(35657) ERRNO=Network is unreachable Mar 07 19:48:55 volumioavi nmbd[779]: [2025/03/07 19:48:55.247599, 0] ../source3/nmbd/nmbd_packets.c:1027(reply_netbios_packet) Mar 07 19:48:55 volumioavi nmbd[779]: reply_netbios_packet: send_packet to IP 192.168.115.234 port 35657 failed Mar 07 19:48:56 volumioavi volumio[1017]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 07 19:48:56 volumioavi volumio[1017]: Error: send ENETUNREACH 255.255.255.255:3483 Mar 07 19:48:56 volumioavi volumio[1017]: at doSend (dgram.js:692:16) Mar 07 19:48:56 volumioavi volumio[1017]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Mar 07 19:48:56 volumioavi volumio[1017]: at afterDns (dgram.js:638:5) Mar 07 19:48:56 volumioavi volumio[1017]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Mar 07 19:48:56 volumioavi volumio[1017]: errno: -101, Mar 07 19:48:56 volumioavi volumio[1017]: code: 'ENETUNREACH', Mar 07 19:48:56 volumioavi volumio[1017]: syscall: 'send', Mar 07 19:48:56 volumioavi volumio[1017]: address: '255.255.255.255', Mar 07 19:48:56 volumioavi volumio[1017]: port: 3483 Mar 07 19:48:56 volumioavi volumio[1017]: } Mar 07 19:48:56 volumioavi volumio[1017]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 07 19:48:57 volumioavi dhcpcd[932]: wlan0: using static address 192.168.115.3/24 Mar 07 19:48:57 volumioavi avahi-daemon[692]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.115.3. Mar 07 19:48:57 volumioavi dhcpcd[932]: wlan0: adding route to 192.168.115.0/24 Mar 07 19:48:57 volumioavi dhcpcd[932]: wlan0: adding default route via 192.168.115.1 Mar 07 19:48:57 volumioavi avahi-daemon[692]: New relevant interface wlan0.IPv4 for mDNS. Mar 07 19:48:57 volumioavi avahi-daemon[692]: Registering new address record for 192.168.115.3 on wlan0.IPv4. Mar 07 19:48:57 volumioavi sudo[16631]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-07 19:47 Mar 07 19:48:57 volumioavi sudo[16631]: 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:01:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e0a6dc7e914e3fb93cbf2123f2f73eac"