@nbd168 , appreciate the helpful tips. Yesterday, I decided to test having everything as it is upstream (and on the latest commit, no workarounds) and do a full clean rebuild, to rule out possible build related issues.
I was up for about 8 hours until the same issue reoccured. DNS requests would no longer go through. I decided to try soft restarting the services unbound, and dnsmasq thinking it might just be an application bug.
Mon Apr 29 22:10:41 2024 user.err ddns-scripts[9480]: cloudflare: BusyBox nslookup error: '1'
Mon Apr 29 22:10:47 2024 user.err ddns-scripts[9481]: cloudflare_v6: BusyBox nslookup error: '1'
Mon Apr 29 22:11:46 2024 user.err ddns-scripts[9480]: cloudflare: BusyBox nslookup error: '1'
Mon Apr 29 22:11:52 2024 user.err ddns-scripts[9481]: cloudflare_v6: BusyBox nslookup error: '1'
Mon Apr 29 22:12:52 2024 user.err ddns-scripts[9480]: cloudflare: BusyBox nslookup error: '1'
Mon Apr 29 22:12:57 2024 user.err ddns-scripts[9481]: cloudflare_v6: BusyBox nslookup error: '1'
Mon Apr 29 22:13:57 2024 user.err ddns-scripts[9480]: cloudflare: BusyBox nslookup error: '1'
Mon Apr 29 22:14:02 2024 user.err ddns-scripts[9481]: cloudflare_v6: BusyBox nslookup error: '1'
# Stopped Unbound
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: service stopped (unbound 1.19.3).
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: server stats for thread 0: 70698 queries, 32435 answers from cache, 38263 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: server stats for thread 0: requestlist max 97 avg 2.17291 exceeded 0 jostled 0
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: average recursion processing time 0.357242 sec
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: histogram of recursion processing times
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: [25%]=0.000492375 median[50%]=0.0059834 [75%]=0.0287856
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: lower(secs) upper(secs) recursions
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.000000 0.000001 349
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.000016 0.000032 5
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.000032 0.000064 8
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.000064 0.000128 53
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.000128 0.000256 741
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.000256 0.000512 9102
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.000512 0.001024 5863
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.001024 0.002048 502
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.002048 0.004096 435
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.004096 0.008192 4476
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.008192 0.016384 4362
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.016384 0.032768 3679
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.032768 0.065536 2966
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.065536 0.131072 4085
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.131072 0.262144 1192
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.262144 0.524288 292
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 0.524288 1.000000 40
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 1.000000 2.000000 8
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 2.000000 4.000000 1
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 4.000000 8.000000 16
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 8.000000 16.000000 26
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 16.000000 32.000000 19
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 32.000000 64.000000 1
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 64.000000 128.000000 11
Mon Apr 29 22:14:10 2024 daemon.info unbound: [11273:0] info: 1024.000000 2048.000000 9
# Immediately after I would get this warning
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.470243] ------------[ cut here ]------------
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.470284] WARNING: CPU: 3 PID: 29 at net/ipv4/af_inet.c:152 inet_sock_destruct+0x19c/0x1a4
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.473939] Modules linked in: act_nssmirred(O) ecm(O) nft_fib_inet nf_flow_table_inet ath11k_ahb(O) ath11k(O) wireguard nft_reject_ipv6 nft_reject_ipv4 nft_reject_inet nft_reject nft_redir nft_quota nft_numgen nft_nat nft_masq nft_log nft_limit nft_hash nft_flow_offload nft_fib_ipv6 nft_fib_ipv4 nft_fib nft_ct nft_chain_nat nf_tables nf_nat nf_flow_table nf_conntrack_netlink nf_conntrack mac80211(O) lz4 libchacha20poly1305 chacha_neon cfg80211(O) tcp_bbr sch_cake qrtr_smd qrtr qmi_helpers(O) poly1305_neon nfnetlink nf_reject_ipv6 nf_reject_ipv4 nf_log_syslog nf_defrag_ipv6 nf_defrag_ipv4 lz4hc_compress lz4_decompress lz4_compress libcurve25519_generic libcrc32c libchacha compat(O) sch_tbf sch_ingress sch_htb sch_hfsc em_u32 cls_u32 cls_route cls_matchall cls_fw cls_flow cls_basic act_skbedit act_mirred act_gact qca_nss_qdisc(O) ledtrig_usbport qca_mcs(O) bonding ifb ip6_udp_tunnel udp_tunnel qca_nss_drv(O) nls_utf8 nls_iso8859_1 nls_cp437 essiv ecdh_generic ecc sha512_generic sha512_arm64 sha2_ce sha256_arm64 sha1_ce
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.474107] seqiv sha3_generic jitterentropy_rng drbg michael_mic kpp hmac geniv des_generic libdes cmac chacha20poly1305 uas usb_storage leds_gpio xhci_plat_hcd xhci_pci xhci_hcd dwc3 dwc3_qcom qca_nss_dp(O) qca_ssdk(O) gpio_button_hotplug(O) vfat fat ext4 mbcache jbd2 crc32c_generic
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.575310] CPU: 3 PID: 29 Comm: ksoftirqd/3 Tainted: G O 6.6.29 #0
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.597548] Hardware name: Dynalink DL-WRX36 (DT)
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.605095] pstate: 20400005 (nzCv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.609960] pc : inet_sock_destruct+0x19c/0x1a4
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.616725] lr : udp_destruct_sock+0x20/0x30
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.621239] sp : ffffffc080e23ca0
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.625750] x29: ffffffc080e23ca0 x28: ffffffc08009d6b4 x27: 000000000000000a
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.628970] x26: ffffff803fddae38 x25: ffffffc080c65f80 x24: 0000000000000000
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.636088] x23: 0000000000000001 x22: ffffffc080e23d78 x21: ffffff800212a700
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.643206] x20: ffffff80041226f8 x19: ffffff8004122640 x18: ffffffc0904bbd00
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.650324] x17: 0000000000000000 x16: ffffffc080868ef8 x15: 0000000000000001
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.657442] x14: 00000000000001c1 x13: 0000007f8b2a2fff x12: 0000000000000006
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.664561] x11: ffffffc080aa1200 x10: 0000000000000000 x9 : ffffff803fdde118
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.671677] x8 : fffffffe005b3f48 x7 : fffffffe00476e48 x6 : 0000000000000000
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.678797] x5 : 00000000ffffffee x4 : ffffffbfbf33d000 x3 : 00000000ffffffed
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.685915] x2 : ffffff8004122728 x1 : 0000000000000000 x0 : 0000000080000000
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.693033] Call trace:
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.700142] inet_sock_destruct+0x19c/0x1a4
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.702402] udp_destruct_sock+0x20/0x30
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.706568] __sk_destruct+0x28/0x198
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.710733] rcu_core+0x1d4/0x53c
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.714293] rcu_core_si+0x10/0x1c
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.717591] __do_softirq+0xf8/0x254
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.720890] run_ksoftirqd+0x38/0x4c
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.724623] smpboot_thread_fn+0x138/0x17c
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.728182] kthread+0xd0/0xd4
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.732087] ret_from_fork+0x10/0x20
Mon Apr 29 22:14:10 2024 kern.warn kernel: [21262.735128] ---[ end trace 0000000000000000 ]---
Mon Apr 29 22:14:15 2024 daemon.info dnsmasq[8007]: exiting on receipt of SIGTERM
Mon Apr 29 22:14:15 2024 daemon.notice unbound: [24663:0] notice: init module 0: iterator
Mon Apr 29 22:14:16 2024 daemon.info unbound: [24663:0] info: start of service (unbound 1.19.3).
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: started, version 2.90 cachesize 150
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: DNS service limited to local subnets
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: compile time options: IPv6 GNU-getopt no-DBus UBus no-i18n no-IDN DHCP DHCPv6 no-Lua no-TFTP no-conntrack no-ipset no-nftset auth cryptohash DNSSEC no-ID loop-detect inotify dumpfile
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: UBus support enabled: connected to system bus
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq-dhcp[25211]: DHCP, IP range 192.168.10.100 -- 192.168.10.255, lease time 12h
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: using nameserver 1.1.1.1#53 for domain ext.ate.cx
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: using only locally-known addresses for test
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: using only locally-known addresses for onion
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: using only locally-known addresses for localhost
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: using only locally-known addresses for local
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: using only locally-known addresses for invalid
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: using only locally-known addresses for bind
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: using only locally-known addresses for orbilogin.com
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: using only locally-known addresses for orbilogin.net
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: using 5 more local addresses
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: read /etc/hosts - 12 names
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: read /etc/hosts.txt - 73 names
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: read /tmp/hosts/dhcp.cfg01411c - 82 names
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq[25211]: read /tmp/hosts/odhcpd - 36 names
Mon Apr 29 22:14:16 2024 daemon.info dnsmasq-dhcp[25211]: read /etc/ethers - 0 addresses
Mon Apr 29 22:15:02 2024 user.err ddns-scripts[9480]: cloudflare: BusyBox nslookup error: '1'
Mon Apr 29 22:15:07 2024 user.err ddns-scripts[9481]: cloudflare_v6: BusyBox nslookup error: '1'
Mon Apr 29 22:16:07 2024 user.err ddns-scripts[9480]: cloudflare: BusyBox nslookup error: '1'
Mon Apr 29 22:16:12 2024 user.err ddns-scripts[9481]: cloudflare_v6: BusyBox nslookup error: '1'
Still no luck getting DNS resolving to work. I thought to try querying DNS servers directly, but it would just hang.
➤ strace nslookup www.google.com 1.1.1.1
execve("/usr/bin/nslookup", ["nslookup", "www.google.com", "1.1.1.1"], 0x7fe8b167b0 /* 38 vars */) = 0
set_tid_address(0x7fad3bde88) = 12228
brk(NULL) = 0x5577491000
brk(0x5577493000) = 0x5577493000
mmap(0x5577491000, 4096, PROT_NONE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x5577491000
openat(AT_FDCWD, "/etc/ld-musl-aarch64.path", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fcntl(3, F_SETFD, FD_CLOEXEC) = 0
fstat(3, {st_mode=S_IFREG|0664, st_size=36, ...}) = 0
read(3, "/lib\n/usr/lib\n/opt/lib\n/opt/usr/"..., 36) = 36
close(3) = 0
openat(AT_FDCWD, "/lib/libgcc_s.so.1", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fcntl(3, F_SETFD, FD_CLOEXEC) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=131088, ...}) = 0
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0\267\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 960) = 960
mmap(NULL, 200704, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x7fad2ea000
mmap(0x7fad319000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x1f000) = 0x7fad319000
close(3) = 0
mprotect(0x7fad319000, 4096, PROT_READ) = 0
mprotect(0x5562803000, 53248, PROT_READ) = 0
prctl(PR_GET_NAME, "nslookup") = 0
getuid() = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fad3b4000
socket(AF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
I was able to query DNS servers directly from clients however. Just not from the router.
Do you think there's a chain effect where a bug in GRO processing of mcast/bcast UDP packets could knock out the ability for the kernel to make any new UDP requests? I might be totally off base, just trying to understand what's happening, or if my issue is even caused by these recent 2 commits.
I will add, at least with these commits, I don't see my previous issue anymore:
[ 1026.294105] pc : __udp_gso_segment+0x378/0x564
[ 1026.300872] lr : __udp_gso_segment+0x348/0x564
Even with my issues, I decided to merge this into my branch. I have a few folks building off my branch so this should hopefully narrow down the bug.
On my personal build, as of 12 hours ago, I'm testing with everything applied as it is upstream, and including your udp_gro_use_fraglist patch from https://nbd.name/p/260b21f3. 