search

folbricht / routedns

DNS stub resolver, proxy and router with support for DoT, DoH, DoQ, and DTLS
BSD 3-Clause "New" or "Revised" License
466 stars 62 forks source link

panic: runtime error: invalid memory address or nil pointer dereference #198

Open bjester opened 2 years ago

bjester commented 2 years ago

I've been receiving the following error running routedns on a public server with DOH exposed.

Ubuntu 20.04.3 LTS (GNU/Linux 5.4.0-90-generic x86_64) go version go1.17.3 linux/amd64

Dec 20 16:40:25 server routedns[203538]: time="2021-12-20T16:40:25Z" level=info msg="starting listener" addr=":443" id=local-doh protocol=doh
Dec 20 16:40:25 server routedns[203538]: time="2021-12-20T16:40:25Z" level=info msg="starting listener" addr=":53" id=local-udp protocol=udp
Dec 20 16:40:25 server routedns[203538]: time="2021-12-20T16:40:25Z" level=info msg="starting listener" addr=":53" id=local-tcp protocol=tcp
Dec 20 17:06:44 server routedns[203538]: panic: runtime error: invalid memory address or nil pointer dereference
Dec 20 17:06:44 server routedns[203538]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x28 pc=0x817afe]
Dec 20 17:06:44 server routedns[203538]: goroutine 1993 [running]:
Dec 20 17:06:44 server routedns[203538]: github.com/miekg/dns.(*OPT).copy(0xc003b58980)
Dec 20 17:06:44 server routedns[203538]:         /opt/routedns/pkg/mod/github.com/miekg/dns@v1.1.43/ztypes.go:866 +0xfe
Dec 20 17:06:44 server routedns[203538]: github.com/miekg/dns.(*Msg).CopyTo(0xc00577cbd0, 0xc00577cc60)
Dec 20 17:06:44 server routedns[203538]:         /opt/routedns/pkg/mod/github.com/miekg/dns@v1.1.43/msg.go:1076 +0x277
Dec 20 17:06:44 server routedns[203538]: github.com/miekg/dns.(*Msg).Copy(...)
Dec 20 17:06:44 server routedns[203538]:         /opt/routedns/pkg/mod/github.com/miekg/dns@v1.1.43/msg.go:1050
Dec 20 17:06:44 server routedns[203538]: github.com/folbricht/routedns.(*Cache).Resolve(0xc0000b3810, 0xc00017b5f0, {{0xc0037f15cc, 0x8, 0x0}})
Dec 20 17:06:44 server routedns[203538]:         /opt/routedns/pkg/mod/github.com/folbricht/routedns@v0.1.0/cache.go:133 +0x434
Dec 20 17:06:44 server routedns[203538]: github.com/folbricht/routedns.listenHandler.func1({0xb59158, 0xc000157180}, 0xc00017b5f0)
Dec 20 17:06:44 server routedns[203538]:         /opt/routedns/pkg/mod/github.com/folbricht/routedns@v0.1.0/dnslistener.go:71 +0x60b
Dec 20 17:06:44 server routedns[203538]: github.com/miekg/dns.HandlerFunc.ServeDNS(0xc001757500, {0xb59158, 0xc000157180}, 0xc00017b5f0)
Dec 20 17:06:44 server routedns[203538]:         /opt/routedns/pkg/mod/github.com/miekg/dns@v1.1.43/server.go:37 +0x2f
Dec 20 17:06:44 server routedns[203538]: github.com/miekg/dns.(*Server).serveDNS(0xc0000d05a0, {0xc001757500, 0x80, 0xc000090298}, 0xc000157180)
Dec 20 17:06:44 server routedns[203538]:         /opt/routedns/pkg/mod/github.com/miekg/dns@v1.1.43/server.go:651 +0x4da
Dec 20 17:06:44 server routedns[203538]: github.com/miekg/dns.(*Server).serveTCPConn(0xc0000d05a0, 0x0, {0xb592b8, 0xc0000b6728})
Dec 20 17:06:44 server routedns[203538]:         /opt/routedns/pkg/mod/github.com/miekg/dns@v1.1.43/server.go:559 +0x26c
Dec 20 17:06:44 server routedns[203538]: created by github.com/miekg/dns.(*Server).serveTCP
Dec 20 17:06:44 server routedns[203538]:         /opt/routedns/pkg/mod/github.com/miekg/dns@v1.1.43/server.go:460 +0x2d9
folbricht commented 2 years ago

Interesting, does it happen consistently for you or after running it for a bit. Looking at the code suggests it failed because there's an EDNS0 record with a nil value that's attempted to be put in the cache. Not exactly sure where this is happening though. There may be some element between the cache and the resolver that does this. Would you mind sharing the relevant parts of your configuration so I know where to look?

bjester commented 2 years ago

@folbricht It does happen after running for a while, but I have a feeling it's triggered by probing and/or invalid requests. Here's my config


[bootstrap-resolver]
address  = "1.1.1.1:853"
protocol = "dot"

# ============ RESOLVERS ============
[resolvers.cloudflare-a]
address  = "cloudflare-dns.com:853"
bootstrap-address  = "1.1.1.1"
protocol = "dot"

[resolvers.cloudflare-b]
address  = "cloudflare-dns.com:853"
bootstrap-address  = "1.0.0.1"
protocol = "dot"

[resolvers.cloudflare-malware-a]
address  = "cloudflare-dns.com:853"
bootstrap-address  = "1.1.1.2"
protocol = "dot"

[resolvers.cloudflare-malware-b]
address  = "cloudflare-dns.com:853"
bootstrap-address  = "1.0.0.2"
protocol = "dot"

[resolvers.quad9-a]
address = "dns.quad9.net:853"
bootstrap-address = "9.9.9.9"
protocol = "dot"

[resolvers.quad9-b]
address = "dns.quad9.net:853"
bootstrap-address = "149.112.112.112"
protocol = "dot"
# ============ END RESOLVERS ============

# ============ GROUPS ============
[groups.cloudflare-plain]
type      = "fail-rotate"
resolvers = ["cloudflare-a", "cloudflare-b"]

[groups.cloudflare-malware]
type      = "fail-rotate"
resolvers = ["cloudflare-malware-a", "cloudflare-malware-b"]

[groups.cloudflare]
type      = "fail-back"
resolvers = ["cloudflare-malware", "cloudflare-plain"]

[groups.quad9]
type      = "fail-rotate"
resolvers = ["quad9-a", "quad9-b"]

[groups.end-resolvers]
type      = "round-robin"
resolvers = ["cloudflare", "quad9"]
# ============ END GROUPS ============

# ============ BLOCKERS ============
[groups.with-ip-blacklist]
type                = "response-blocklist-ip"
resolvers           = ["end-resolvers"]
blocklist-refresh   = 86400
blocklist-source    = [
   {format = "cidr", source = "./ip-blocklist"},
]

[groups.with-domain-blacklist]
type              = "blocklist-v2"
resolvers         = ["with-ip-blacklist"]
blocklist-refresh = 86400
blocklist-source  = [
   {format = "domain", source = "./blocklist"},
]
allowlist-resolver = "end-resolvers"
allowlist-format = "regexp"
allowlist = [
    '(^|\.)example\.com\.$',
]
# ============ END BLOCKERS ============

# ============ CACHE ============
[groups.deduped]
type = "request-dedup"
resolvers = ["with-domain-blacklist"]

[groups.cached]
type                 = "cache"
resolvers            = ["deduped"]
cache-size           = 10000
cache-negative-ttl   = 10
cache-answer-shuffle = "round-robin"
# ============ END CACHE ============

# ============ LISTENERS ============
[listeners.local-tcp]
address = ":53"
protocol = "tcp"
resolver = "cached"

[listeners.local-udp]
address = ":53"
protocol = "udp"
resolver = "cached"

[listeners.local-doh]
address = ":443"
protocol = "doh"
resolver = "cached"
folbricht commented 2 years ago

Thank you. I put a quick patch on the patch-issue-198 branch that should help you until I have a proper fix. It's only a workaround for now. I'll look deeper, there could well be a bug in the DoT code, it deals with padding in that area so I'll review that part.

folbricht commented 2 years ago

@bjester I did spend some time trying to identify the issue. Found one bug in a related area though I don't think that was it. So I added the fix to the patch-issue-198 branch and also some tracing code. Would you be able to run from this branch for a bit and then grep the logs for the string NILOPTREC and let me know what you see? There's a few tracepoints in the code that'll help narrow it down a bit more. Thanks

bjester commented 2 years ago

@folbricht I've updated my server and I'll let you know if I get any matching logs. Thanks!

bjester commented 2 years ago

@folbricht I got one:

NILOPTREC: found nil options record, ID: p1, QName: <ip (removed)>.in-addr.arpa., QType: PTR
folbricht commented 2 years ago

Thank you. And that's the only one? None that say "p2" or "p3"? That would mean the issue is in the request-dedup component. So if you were to take that out of the chain in the config, it should in theory no longer happen. I'll see if I can figure out where exactly that breaks down.

bjester commented 2 years ago

Gotcha. Yes, only p1 so far. :+1:

cbuijs commented 2 years ago

Still getting it with patch-issue-198 applied, and not getting the NILOPTREC.

Example when I am doing a reverse lookup (the only way I can replicate it), doing dig @192.168.1.1 -x 192.168.1.1 as example:

Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: msg="forwarding unmodified query to resolver" client=192.168.1.182 id=home qname=1.1.168.192.in-addr.arpa. qtype=PTR
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: error: invalid memory address or nil pointer dereference
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: segmentation violation code=0x1 addr=0x0 pc=0x8ba4de]
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: [running]:
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: {{0xc00045c008, 0xc0004b2390, 0xc00039b060}})
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS:  /opt/routedns-i386/blocklist.go:115 +0x25e
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: {{0xc00045c008, 0xc00045c008, 0x0}})
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS:  /opt/routedns-i386/ttl-modifier.go:38 +0x5e
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: {{0xc00045c008, 0x1, 0xc0001140c0}})
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS:  /opt/routedns-i386/replace.go:68 +0x495
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: {{0xc00045c008, 0x7a438f, 0xc00039b7b8}})
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS:  /opt/routedns-i386/router.go:61 +0x302
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: {{0xc00045c008, 0x8, 0xc00039b720}})
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS:  /opt/routedns-i386/edns0-modifier.go:39 +0x7f
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: {{0xc00045c008, 0x8, 0x0}})
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS:  /opt/routedns-i386/request-dedup.go:108 +0x462
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: 0xc000278000)
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS:  /opt/routedns-i386/dnslistener.go:71 +0x60b
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: 0xc0001cc180}, 0xc000278000)
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS:  /opt/routedns-i386/go/pkg/mod/github.com/miekg/dns@v1.1.46-0.20211228135238-0544c8bb118e/server.go:37 +0x2f
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: 0x35, 0x0}, 0xc0001cc180)
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS:  /opt/routedns-i386/go/pkg/mod/github.com/miekg/dns@v1.1.46-0.20211228135238-0544c8bb118e/server.go:651 +0x4da
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: {0xc000286c00, 0x35, 0x200}, {0xb51700, 0xc00009c000}, 0xc00030e060, {0x0, 0x0})
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS:  /opt/routedns-i386/go/pkg/mod/github.com/miekg/dns@v1.1.46-0.20211228135238-0544c8bb118e/server.go:591 +0x185
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS: github.com/miekg/dns.(*Server).serveUDP
Tue Jan 11 11:53:41 2022 user.notice ROUTEDNS:  /opt/routedns-i386/go/pkg/mod/github.com/miekg/dns@v1.1.46-0.20211228135238-0544c8bb118e/server.go:521 +0x485

I have updated the miekg DNS lib to latest version, as it seems to be happening there, with no luck.

I workaround with this to just block all queries ending in .arpa with a static-response (nxdomain).

folbricht commented 2 years ago

Oh, if you have a repro, that would let me fix it. So it's basically all PTR lookups? Do you have anything special in your config that triggers this? Once I can make it happen here I'll be able to fix that.

cbuijs commented 2 years ago

Every Reverse/PTR lookup. Can replicate with below config using latest/greatest of RouteDNS and all modules (I force updated them to latest release, but seems to crash on the standard build as well).

Note: It listens on 192.168.1.1 port 53053, see listeners.do53-udp4

This triggers: dig @192.168.1.1 -p 53053 -x 192.168.1.1

[bootstrap-resolver]
protocol = "doh"
address = "https://family.cloudflare-dns.com:443/dns-query"
bootstrap-address = "1.1.1.3"

[listeners.do53-udp4]
address = "192.168.1.1:53053"
protocol = "udp"
resolver = "edns-ecs-delete"

[groups.edns-ecs-delete]
type = "edns0-modifier"
resolvers = ["cache"]
edns0-op = "delete"
edns0-code = 8

[groups.cache]
type = "cache"
resolvers = ["router"]
cache-size = 4096
cache-negative-ttl = 300
cache-harden-below-nxdomain = true
cache-flush-query = "flush.cache.routedns."

[routers.router]
routes = [
        {name = '(^|\.)home\.$', resolver = "hosts"},
        {name = '(^|\.)(ip6|in-addr)\.arpa\.$', resolver = "hosts"},
        {resolver = "default-ttl"},
]

[groups.hosts]
type = "blocklist-v2"
resolvers = ["nxdomain"]
blocklist-refresh = 15
blocklist-source = [
        {format = "hosts", source = "/etc/hosts"},
]

[groups.default-ttl]
type = "ttl-modifier"
resolvers = ["cloudflare"]
ttl-min = 30
ttl-max = 14400

[resolvers.cloudflare]
protocol = "doh"
address = "https://family.cloudflare-dns.com:443/dns-query"

[groups.nxdomain]
type = "static-responder"
rcode = 3

The /etc/hosts file:

127.0.0.1 localhost
192.168.1.1 routedns.home
192.168.1.2 printer.home

Crash using above config:

TRAC[0000] loading blocklist                             file=/etc/hosts
TRAC[0000] completed loading blocklist                   file=/etc/hosts
INFO[0000] starting listener                             addr="192.168.1.1:53053" id=do53-udp4 protocol=udp
DEBU[0003] received query                                addr="192.168.1.1:53053" client=192.168.1.182 id=do53-udp4 protocol=udp qname=1.1.168.192.in-addr.arpa.
TRAC[0003] forwarding query to resolver                  addr="192.168.1.1:53053" client=192.168.1.182 id=do53-udp4 protocol=udp qname=1.1.168.192.in-addr.arpa. resolver=edns-ecs-delete
DEBU[0003] cache-miss, forwarding                        client=192.168.1.182 id=cache qname=1.1.168.192.in-addr.arpa. qtype=PTR resolver=router
DEBU[0003] routing query to resolver                     client=192.168.1.182 id=router qname=1.1.168.192.in-addr.arpa. qtype=PTR resolver=hosts
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x8ba4de]

goroutine 9 [running]:
github.com/folbricht/routedns.(*Blocklist).Resolve(0xc000153680, 0xc000206240, {{0xc0001515e8, 0x1, 0x203000}})
    /opt/routedns-i386/blocklist.go:115 +0x25e
github.com/folbricht/routedns.(*Router).Resolve(0xc0001a8ff0, 0xc000206240, {{0xc0001515e8, 0x8, 0x49ea66}})
    /opt/routedns-i386/router.go:61 +0x302
github.com/folbricht/routedns.(*Cache).Resolve(0xc00015b810, 0xc000206000, {{0xc0001515e8, 0x7a438f, 0xc00008da68}})
    /opt/routedns-i386/cache.go:121 +0x403
github.com/folbricht/routedns.(*EDNS0Modifier).Resolve(0xc0001a9320, 0xc000206000, {{0xc0001515e8, 0x8, 0x413e06}})
    /opt/routedns-i386/edns0-modifier.go:39 +0x7f
github.com/folbricht/routedns.listenHandler.func1({0xb54a78, 0xc000204000}, 0xc000206000)
    /opt/routedns-i386/dnslistener.go:71 +0x60b
github.com/miekg/dns.HandlerFunc.ServeDNS(0xc00018e400, {0xb54a78, 0xc000204000}, 0xc000206000)
    /opt/routedns-i386/go/pkg/mod/github.com/miekg/dns@v1.1.46-0.20211228135238-0544c8bb118e/server.go:37 +0x2f
github.com/miekg/dns.(*Server).serveDNS(0xc0001999e0, {0xc00018e400, 0x35, 0x8e35da}, 0xc000204000)
    /opt/routedns-i386/go/pkg/mod/github.com/miekg/dns@v1.1.46-0.20211228135238-0544c8bb118e/server.go:651 +0x4da
github.com/miekg/dns.(*Server).serveUDPPacket(0xc0001999e0, 0x0, {0xc00018e400, 0x35, 0x200}, {0xb51700, 0xc00000e680}, 0xc00003d220, {0x0, 0x0})
    /opt/routedns-i386/go/pkg/mod/github.com/miekg/dns@v1.1.46-0.20211228135238-0544c8bb118e/server.go:591 +0x185
created by github.com/miekg/dns.(*Server).serveUDP
    /opt/routedns-i386/go/pkg/mod/github.com/miekg/dns@v1.1.46-0.20211228135238-0544c8bb118e/server.go:521 +0x485
folbricht commented 2 years ago

That's actually a different issue. It was introduced recently with the blocklist logging changes and should be fixed in https://github.com/folbricht/routedns/pull/203 now.

The hunt continues...

cbuijs commented 2 years ago

Ah, sorry for the confusion!

The #203 indeed fixes the crashes I was getting. Thanks!!!

charlieporth1 commented 2 years ago

Is this the same issue?

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x18 pc=0x8e9e46]

goroutine 16728 [running]:
github.com/folbricht/routedns.stripPadding(0xc01391c6c0)
    /root/go/src/github.com/folbricht/routedns/padding.go:98 +0xe6
github.com/folbricht/routedns.(*DNSClient).Resolve(0xc000469ec0, 0x7f4b3b8db008, {{0xc019c10c70, 0x406d9d, 0xc000352001}})
    /root/go/src/github.com/folbricht/routedns/dnsclient.go:73 +0x1db
github.com/folbricht/routedns.(*Fastest).Resolve.func1()
    /root/go/src/github.com/folbricht/routedns/fastest.go:42 +0x49
created by github.com/folbricht/routedns.(*Fastest).Resolve
    /root/go/src/github.com/folbricht/routedns/fastest.go:41 +0x665
brotaxt commented 1 year ago

I probably experiencing the same issues. After some time routedns crashes with the following error


Nov 05 22:16:03 hostname_here routedns[650]: time="2022-11-05T22:16:03+01:00" level=info msg="starting listener" addr="[::1]:5353" id=local-doh-behind-proxy_ipv6_tcp protocol=tcp
Nov 05 22:16:03 hostname_here routedns[650]: time="2022-11-05T22:16:03+01:00" level=info msg="starting listener" addr="127.0.0.1:5353" id=local-doh-behind-proxy_ipv4_tcp protocol=tcp
Nov 05 22:16:03 hostname_here routedns[650]: time="2022-11-05T22:16:03+01:00" level=info msg="starting listener" addr="127.0.0.1:5353" id=local-doh-behind-proxy_ipv4_udp protocol=udp
Nov 05 22:16:03 hostname_here routedns[650]: time="2022-11-05T22:16:03+01:00" level=info msg="starting listener" addr="[::1]:5353" id=local-doh-behind-proxy_ipv6_udp protocol=udp
Nov 06 09:52:06 hostname_here routedns[650]: panic: runtime error: invalid memory address or nil pointer dereference
Nov 06 09:52:06 hostname_here routedns[650]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x466776]
Nov 06 09:52:06 hostname_here routedns[650]: goroutine 133667 [running]:
Nov 06 09:52:06 hostname_here routedns[650]: github.com/miekg/dns.packDataOpt({0xc0005ad920?, 0x2, 0x81?}, {0xc000654240, 0x81, 0x81}, 0x0?)
Nov 06 09:52:06 hostname_here routedns[650]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg_helpers.go:454 +0x1d5
Nov 06 09:52:06 hostname_here routedns[650]: github.com/miekg/dns.(*OPT).pack(0x20?, {0xc000654240?, 0x0?, 0x0?}, 0xbc8c2e?, {0x1?, 0x2000029?}, 0x18?)
Nov 06 09:52:06 hostname_here routedns[650]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/zmsg.go:666 +0x3f
Nov 06 09:52:06 hostname_here routedns[650]: github.com/miekg/dns.packRR({0xbd5b20, 0xc000330700}, {0xc000654240, 0x81, 0x81}, 0x0?, {0x0?, 0x0?}, 0x0?)
Nov 06 09:52:06 hostname_here routedns[650]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:597 +0x174
Nov 06 09:52:06 hostname_here routedns[650]: github.com/miekg/dns.(*Msg).packBufferWithCompressionMap(0xc000537c20, {0x0, 0x0, 0x0}, {0x0?, 0x0?}, 0x0?)
Nov 06 09:52:06 hostname_here routedns[650]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:824 +0x3c5
Nov 06 09:52:06 hostname_here routedns[650]: github.com/miekg/dns.(*Msg).PackBuffer(0x20?, {0x0?, 0xc0002811b8?, 0x0?})
Nov 06 09:52:06 hostname_here routedns[650]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:740 +0x93
Nov 06 09:52:06 hostname_here routedns[650]: github.com/miekg/dns.(*Msg).Pack(...)
Nov 06 09:52:06 hostname_here routedns[650]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:728
Nov 06 09:52:06 hostname_here routedns[650]: github.com/folbricht/routedns.(*DoHClient).ResolvePOST(0xc0000f1b90, 0xc00024ee08?)
Nov 06 09:52:06 hostname_here routedns[650]:         /root/routedns/routedns/dohclient.go:120 +0x65
Nov 06 09:52:06 hostname_here routedns[650]: github.com/folbricht/routedns.(*DoHClient).Resolve(0xc0000f1b90, 0xc000415750?, {{0xc0002229fc, 0x4, 0x4}, {0x0, 0x0}})
Nov 06 09:52:06 hostname_here routedns[650]:         /root/routedns/routedns/dohclient.go:110 +0x2bc
Nov 06 09:52:06 hostname_here routedns[650]: github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Nov 06 09:52:06 hostname_here routedns[650]:         /root/routedns/routedns/fastest.go:42 +0x52
Nov 06 09:52:06 hostname_here routedns[650]: created by github.com/folbricht/routedns.(*Fastest).Resolve
Nov 06 09:52:06 hostname_here routedns[650]:         /root/routedns/routedns/fastest.go:41 +0x672
Nov 06 09:52:06 hostname_here systemd[1]: routedns.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Nov 06 09:52:06 hostname_here systemd[1]: routedns.service: Failed with result 'exit-code'.
Nov 06 09:52:07 hostname_here systemd[1]: routedns.service: Service RestartSec=100ms expired, scheduling restart.
Nov 06 09:52:07 hostname_here systemd[1]: routedns.service: Scheduled restart job, restart counter is at 2.
Nov 06 09:52:07 hostname_here systemd[1]: Stopped RouteDNS - DNS stub resolver and router.

my config

title = "RouteDNS configuration"

[resolvers]

  [resolvers.nextdns_ll_secondary]
  address = "https://doh3.dns.nextdns.io/CODE_HERE"
  protocol = "doh"
  transport = "quic"
  bootstrap-address = "199.247.16.158"

  [resolvers.nextdns_ll_primary]
  address = "https://doh3.dns.nextdns.io/CODE_HERE"
  protocol = "doh"
  transport = "quic"
  bootstrap-address = "217.146.22.163"

  [resolvers.nextdns_ll_ipv6_secondary]
  address = "https://doh3.dns.nextdns.io/CODE_HERE"
  protocol = "doh"
  transport = "quic"
  bootstrap-address = "2a05:f480:1800:8ed:5400:2ff:fec8:7e46"

  [resolvers.nextdns_ll_ipv6_primary]
  address = "https://doh3.dns.nextdns.io/CODE_HERE"
  protocol = "doh"
  transport = "quic"
  bootstrap-address = "2a00:11c0:e:ffff:1::d"

[groups]

  [groups.nextdns_cached_ipv4]
  type = "cache"
  cache-size = 0
  resolvers = ["nextdns-updated-ttl_ipv4"]
  gc-period = 180
  ttl-min = 180
  cache-negative-ttl = 180

  [groups.nextdns_cached_ipv6]
  type = "cache"
  cache-size = 0
  resolvers = ["nextdns-updated-ttl_ipv6"]
  gc-period = 180
  ttl-min = 180
  cache-negative-ttl = 180

  [groups.nextdns-updated-ttl_ipv4]
  type = "ttl-modifier"
  resolvers = ["nextdns_failback_ipv4"]
  ttl-min = 360

  [groups.nextdns-updated-ttl_ipv6]
  type = "ttl-modifier"
  resolvers = ["nextdns_failback_ipv6"]
  ttl-min = 360

  [groups.nextdns_failback_ipv4]
  resolvers = ["fastest_ipv4", "fastest_ipv6"]
  type = "fail-back"
  servfail-error = true

  [groups.nextdns_failback_ipv6]
  resolvers = ["fastest_ipv6", "fastest_ipv4"]
  type = "fail-back"
  servfail-error = true

  [groups.fastest_ipv4]
  type   = "fastest"
  resolvers = ["nextdns_ll_primary", "nextdns_ll_secondary"]

  [groups.fastest_ipv6]
  type   = "fastest"
  resolvers = ["nextdns_ll_ipv6_primary", "nextdns_ll_ipv6_secondary"]

[listeners]

  [listeners.local-doh-behind-proxy_ipv4_udp]
  address = "127.0.0.1:5353"
  protocol = "udp"
  resolver = "nextdns_cached_ipv4"

  [listeners.local-doh-behind-proxy_ipv4_tcp]
  address = "127.0.0.1:5353"
  protocol = "tcp"
  resolver = "nextdns_cached_ipv4"

  [listeners.local-doh-behind-proxy_ipv6_udp]
  address = "[::1]:5353"
  protocol = "udp"
  resolver = "nextdns_cached_ipv6"

  [listeners.local-doh-behind-proxy_ipv6_tcp]
  address = "[::1]:5353"
  protocol = "tcp"
  resolver = "nextdns_cached_ipv6"
folbricht commented 1 year ago

Yes, that looks very much like the same issue and it'd be nice if we could figure out where this comes from. I patched the elements in your config to print a specific message into the logs when this happens. Would you be able to run https://github.com/folbricht/routedns/tree/patch-issue-198 for a bit and regularly grep your logs for NILOPTREC? There's also a workaround on this branch that should prevent the panic. Getting a couple of those alerts in the logs would really help tracking this down.

brotaxt commented 1 year ago

I've compiled routedns from the mentioned branch but unfortunately I can't find any NILOPTREC messages in my logs. routedns crashed again today. 

Nov 10 10:22:21 hostname_here routedns[23644]: panic: runtime error: invalid memory address or nil pointer dereference
Nov 10 10:22:21 hostname_here routedns[23644]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x4663b6]
Nov 10 10:22:21 hostname_here routedns[23644]: goroutine 750245 [running]:
Nov 10 10:22:21 hostname_here routedns[23644]: github.com/miekg/dns.packDataOpt({0xc0006278c0, 0x2, 0x27}, {0xc00022f950, 0x81, 0x81}, 0x81)
Nov 10 10:22:21 hostname_here routedns[23644]: #011/root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg_helpers.go:454 +0x1d5
Nov 10 10:22:21 hostname_here routedns[23644]: github.com/miekg/dns.(*OPT).pack(0x27, {0xc00022f950, 0x0, 0x0}, 0xb59aa4, {0x1, 0x800004d00029}, 0xc)
Nov 10 10:22:21 hostname_here routedns[23644]: #011/root/go/pkg/mod/github.com/miekg/dns@v1.1.48/zmsg.go:666 +0x3f
Nov 10 10:22:21 hostname_here routedns[23644]: github.com/miekg/dns.packRR({0xb7e798, 0xc0003e47c0}, {0xc00022f950, 0x81, 0x4}, 0x0, {0x0, 0x0}, 0x4)
Nov 10 10:22:21 hostname_here routedns[23644]: #011/root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:592 +0x171
Nov 10 10:22:21 hostname_here routedns[23644]: github.com/miekg/dns.(*Msg).packBufferWithCompressionMap(0xc0006803f0, {0x0, 0x0, 0x0}, {0x0, 0x0}, 0x27)
Nov 10 10:22:21 hostname_here routedns[23644]: #011/root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:819 +0x3c5
Nov 10 10:22:21 hostname_here routedns[23644]: github.com/miekg/dns.(*Msg).PackBuffer(0xc0006803f0, {0x0, 0x16, 0xc00049a2e8})
Nov 10 10:22:21 hostname_here routedns[23644]: #011/root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:735 +0x93
Nov 10 10:22:21 hostname_here routedns[23644]: github.com/miekg/dns.(*Msg).Pack(...)
Nov 10 10:22:21 hostname_here routedns[23644]: #011/root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:723
Nov 10 10:22:21 hostname_here routedns[23644]: github.com/folbricht/routedns.(*DoHClient).ResolvePOST(0xc0001ec090, 0xc000000005)
Nov 10 10:22:21 hostname_here routedns[23644]: #011/root/routedns_debug/routedns/dohclient.go:121 +0x85
Nov 10 10:22:21 hostname_here routedns[23644]: github.com/folbricht/routedns.(*DoHClient).Resolve(0xc0001ec090, 0x0, {{0xc00003e4e8, 0x4, 0x4}, {0x0, 0x0}})
Nov 10 10:22:21 hostname_here routedns[23644]: #011/root/routedns_debug/routedns/dohclient.go:110 +0x2c5
Nov 10 10:22:21 hostname_here routedns[23644]: github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Nov 10 10:22:21 hostname_here routedns[23644]: #011/root/routedns_debug/routedns/fastest.go:43 +0x63
Nov 10 10:22:21 hostname_here routedns[23644]: created by github.com/folbricht/routedns.(*Fastest).Resolve
Nov 10 10:22:21 hostname_here routedns[23644]: #011/root/routedns_debug/routedns/fastest.go:42 +0x6f2
Nov 10 10:22:21 hostname_here systemd[1]: routedns.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Nov 10 10:22:21 hostname_here systemd[1]: routedns.service: Failed with result 'exit-code'.
Nov 10 10:22:21 hostname_here systemd[1]: routedns.service: Service RestartSec=100ms expired, scheduling restart.
Nov 10 10:22:21 hostname_here systemd[1]: routedns.service: Scheduled restart job, restart counter is at 1.
folbricht commented 1 year ago

Hmm, this is rather surprising, especially since the stacktrace points at this line in the code https://github.com/miekg/dns/blob/v1.1.48/msg_helpers.go#L454 which can't trigger a nil pointer afaikt. I pushed another commit to the branch, this will catch the panic in ResolvePOST() which is where it failed in both your stack traces. It'll then print NILOPTREC, some information about the type of query, a stack trace, as well as recover from the panic (should not cause a crash like that if it happens in the same spot again).

brotaxt commented 1 year ago

Enclosed please find a new error log. Pulled the latest commits from your branch and made a new routedns binary before.

Nov 17 01:33:25 hostname_here.de routedns[6458]: panic: runtime error: invalid memory address or nil pointer dereference
Nov 17 01:33:25 hostname_here.de routedns[6458]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x8 pc=0x8eeb5c]
Nov 17 01:33:25 hostname_here.de routedns[6458]: goroutine 13326 [running]:
Nov 17 01:33:25 hostname_here.de routedns[6458]: github.com/folbricht/routedns.padQuery(0xc0002a4cb0)
Nov 17 01:33:25 hostname_here.de routedns[6458]:         /root/routedns_debug/routedns/padding.go:73 +0x1fc
Nov 17 01:33:25 hostname_here.de routedns[6458]: github.com/folbricht/routedns.(*DoHClient).Resolve(0xc00029e5a0, 0x0, {{0xc00003ea28, 0x4, 0x4}, {0x0, 0x0}})
Nov 17 01:33:25 hostname_here.de routedns[6458]:         /root/routedns_debug/routedns/dohclient.go:106 +0x256
Nov 17 01:33:25 hostname_here.de routedns[6458]: github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Nov 17 01:33:25 hostname_here.de routedns[6458]:         /root/routedns_debug/routedns/fastest.go:43 +0x63
Nov 17 01:33:25 hostname_here.de routedns[6458]: created by github.com/folbricht/routedns.(*Fastest).Resolve
Nov 17 01:33:25 hostname_here.de routedns[6458]:         /root/routedns_debug/routedns/fastest.go:42 +0x6f2
Nov 17 01:33:25 hostname_here.de systemd[1]: routedns.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
folbricht commented 1 year ago

Thank you. This actually failed in a different spot, a little bit earlier. I updated the branch to catch this one as well, and it should be the last possible failure place. If you run this for a bit, it'd be nice if you could grep the logs for NILOPTREC. That'll tell me how often it happens and where.

This more and more looks like a data-race in on of the elements before. The one's in your config that use concurrency are cache and fastest. I'll try to replicate this in my own config

brotaxt commented 1 year ago

Hey @folbricht, here's another one. best regards!

Nov 29 23:50:16 hostname_here.de routedns[10156]: time="2022-11-29T23:50:16+01:00" level=error msg="NILOPTREC: QName: COMPANY_HERE-my.sharepoint.com., QType: A" error="runtime error: invalid memory address or nil pointer dereference"
Nov 29 23:50:16 hostname_here.de routedns[10156]: goroutine 455662 [running]:
Nov 29 23:50:16 hostname_here.de routedns[10156]: runtime/debug.Stack()
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /usr/local/go/src/runtime/debug/stack.go:24 +0x65
Nov 29 23:50:16 hostname_here.de routedns[10156]: runtime/debug.PrintStack()
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /usr/local/go/src/runtime/debug/stack.go:16 +0x19
Nov 29 23:50:16 hostname_here.de routedns[10156]: github.com/folbricht/routedns.(*DoHClient).ResolvePOST.func1()
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /root/routedns/routedns/dohclient.go:132 +0x245
Nov 29 23:50:16 hostname_here.de routedns[10156]: panic({0x9e7ba0, 0xf53ac0})
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /usr/local/go/src/runtime/panic.go:1038 +0x215
Nov 29 23:50:16 hostname_here.de routedns[10156]: github.com/miekg/dns.packDataOpt({0xc00027b360, 0x3, 0x31}, {0xc000696240, 0x81, 0x81}, 0x81)
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg_helpers.go:443 +0x8b
Nov 29 23:50:16 hostname_here.de routedns[10156]: github.com/miekg/dns.(*OPT).pack(0x31, {0xc000696240, 0x0, 0x0}, 0xb59be4, {0x1, 0x2000029}, 0xc)
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/zmsg.go:666 +0x3f
Nov 29 23:50:16 hostname_here.de routedns[10156]: github.com/miekg/dns.packRR({0xb7e938, 0xc0002e79c0}, {0xc000696240, 0x81, 0x4}, 0x0, {0x0, 0x0}, 0xdc)
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:592 +0x171
Nov 29 23:50:16 hostname_here.de routedns[10156]: github.com/miekg/dns.(*Msg).packBufferWithCompressionMap(0xc0004cc900, {0x0, 0x0, 0x0}, {0x0, 0x0}, 0x0)
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:819 +0x3c5
Nov 29 23:50:16 hostname_here.de routedns[10156]: github.com/miekg/dns.(*Msg).PackBuffer(0xc0004cc900, {0x0, 0x16, 0x0})
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:735 +0x93
Nov 29 23:50:16 hostname_here.de routedns[10156]: github.com/miekg/dns.(*Msg).Pack(...)
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:723
Nov 29 23:50:16 hostname_here.de routedns[10156]: github.com/folbricht/routedns.(*DoHClient).ResolvePOST(0xc000280090, 0xc0004cc900)
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /root/routedns/routedns/dohclient.go:139 +0xd2
Nov 29 23:50:16 hostname_here.de routedns[10156]: github.com/folbricht/routedns.(*DoHClient).Resolve(0xc000280090, 0xc0004cc900, {{0xc00003e3c8, 0x4, 0x4}, {0x0, 0x0}})
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /root/routedns/routedns/dohclient.go:119 +0x3a5
Nov 29 23:50:16 hostname_here.de routedns[10156]: github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /root/routedns/routedns/fastest.go:43 +0x63
Nov 29 23:50:16 hostname_here.de routedns[10156]: created by github.com/folbricht/routedns.(*Fastest).Resolve
Nov 29 23:50:16 hostname_here.de routedns[10156]:         /root/routedns/routedns/fastest.go:42 +0x6f2
brotaxt commented 1 year ago 
Dec 19 03:44:07 hostname_here.de routedns[5503]: time="2022-12-19T03:44:07+01:00" level=error msg="NILOPTREC: QName: 72.10.98.141.spam.spamrats.com., QType: A" error="runtime error: invalid memory address or nil point
Dec 19 03:44:08 hostname_here.de routedns[5503]: goroutine 3598281 [running]:
Dec 19 03:44:08 hostname_here.de routedns[5503]: runtime/debug.Stack()
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /usr/local/go/src/runtime/debug/stack.go:24 +0x65
Dec 19 03:44:08 hostname_here.de routedns[5503]: runtime/debug.PrintStack()
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /usr/local/go/src/runtime/debug/stack.go:16 +0x19
Dec 19 03:44:08 hostname_here.de routedns[5503]: github.com/folbricht/routedns.(*DoHClient).ResolvePOST.func1()
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /root/routedns/routedns/dohclient.go:132 +0x245
Dec 19 03:44:08 hostname_here.de routedns[5503]: panic({0x9e7ba0, 0xf53ac0})
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /usr/local/go/src/runtime/panic.go:1038 +0x215
Dec 19 03:44:08 hostname_here.de routedns[5503]: github.com/miekg/dns.packDataOpt({0xc0006a7250, 0x1, 0x30}, {0xc0007983f0, 0x81, 0x81}, 0x81)
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg_helpers.go:454 +0x1d5
Dec 19 03:44:08 hostname_here.de routedns[5503]: github.com/miekg/dns.(*OPT).pack(0x30, {0xc0007983f0, 0x0, 0x0}, 0xb59be4, {0x1, 0x4d00029}, 0x0)
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/zmsg.go:666 +0x3f
Dec 19 03:44:08 hostname_here.de routedns[5503]: github.com/miekg/dns.packRR({0xb7e938, 0xc000142180}, {0xc0007983f0, 0x81, 0xffffffffffffffff}, 0x0, {0x0, 0x0}, 0x10)
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:592 +0x171
Dec 19 03:44:08 hostname_here.de routedns[5503]: github.com/miekg/dns.(*Msg).packBufferWithCompressionMap(0xc00034bb00, {0x0, 0x0, 0x0}, {0x0, 0x0}, 0x0)
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:819 +0x3c5
Dec 19 03:44:08 hostname_here.de routedns[5503]: github.com/miekg/dns.(*Msg).PackBuffer(0xc00034bb00, {0x0, 0x16, 0x0})
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:735 +0x93
Dec 19 03:44:08 hostname_here.de routedns[5503]: github.com/miekg/dns.(*Msg).Pack(...)
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:723
Dec 19 03:44:08 hostname_here.de routedns[5503]: github.com/folbricht/routedns.(*DoHClient).ResolvePOST(0xc000280630, 0xc00034bb00)
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /root/routedns/routedns/dohclient.go:139 +0xd2
Dec 19 03:44:08 hostname_here.de routedns[5503]: github.com/folbricht/routedns.(*DoHClient).Resolve(0xc000280630, 0xc00034bb00, {{0xc0010ae768, 0x4, 0x4}, {0x0, 0x0}})
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /root/routedns/routedns/dohclient.go:119 +0x3a5
Dec 19 03:44:08 hostname_here.de routedns[5503]: github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /root/routedns/routedns/fastest.go:43 +0x63
Dec 19 03:44:08 hostname_here.de routedns[5503]: created by github.com/folbricht/routedns.(*Fastest).Resolve
Dec 19 03:44:08 hostname_here.de routedns[5503]:         /root/routedns/routedns/fastest.go:42 +0x6f2
folbricht commented 1 year ago

Thanks, both of those happened in the same place, both seem to be regular queries and standard A records. I'll review these code-paths again.

If you're able to build your executable with the -race flag that might help identify any race-condition. If the race-detector finds anything, it'll write WARNING to stdout and possibly panic.

folbricht commented 1 year ago

Actually, I'm able to trigger the race-detector myself apparently which should really help debug this.

It doesn't actually panic but write this into the logs

Dec 26 11:31:33 x1 routedns[1432]: ==================
Dec 26 11:31:33 x1 routedns[1432]: WARNING: DATA RACE
Dec 26 11:31:33 x1 routedns[1432]: Read at 0x00c00011bc40 by goroutine 89:
Dec 26 11:31:33 x1 routedns[1432]:   github.com/miekg/dns.(*Msg).CopyTo()
...
folbricht commented 1 year ago

I fixed the one data race I was able to reproduce in the request-dedup component (https://github.com/folbricht/routedns/pull/270) It's not entirely clear if this will fix your issue as well but it's worth a try. It's on master and also backported to the patch-issue-198 branch.

brotaxt commented 1 year ago

Got another one :(

Feb 08 08:55:37 hostname.de routedns[13345]: time="2023-02-08T08:55:37+01:00" level=error msg="NILOPTREC: QName: 37.65.125.45.psbl.surriel.com., QType: A" error="runtime error: invalid memory address or nil pointer dere
Feb 08 08:55:37 hostname.de routedns[13345]: goroutine 1540622 [running]:
Feb 08 08:55:37 hostname.de routedns[13345]: runtime/debug.Stack()
Feb 08 08:55:37 hostname.de routedns[13345]:         /usr/local/go/src/runtime/debug/stack.go:24 +0x65
Feb 08 08:55:37 hostname.de routedns[13345]: runtime/debug.PrintStack()
Feb 08 08:55:37 hostname.de routedns[13345]:         /usr/local/go/src/runtime/debug/stack.go:16 +0x19
Feb 08 08:55:37 hostname.de routedns[13345]: github.com/folbricht/routedns.(*DoHClient).ResolvePOST.func1()
Feb 08 08:55:37 hostname.de routedns[13345]:         /root/routedns/routedns/dohclient.go:132 +0x245
Feb 08 08:55:37 hostname.de routedns[13345]: panic({0x9e7ba0, 0xf53ac0})
Feb 08 08:55:37 hostname.de routedns[13345]:         /usr/local/go/src/runtime/panic.go:1038 +0x215
Feb 08 08:55:37 hostname.de routedns[13345]: github.com/miekg/dns.packDataOpt({0xc00020c380, 0x1, 0x2f}, {0xc00088e000, 0x81, 0x81}, 0x81)
Feb 08 08:55:37 hostname.de routedns[13345]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg_helpers.go:454 +0x1d5
Feb 08 08:55:37 hostname.de routedns[13345]: github.com/miekg/dns.(*OPT).pack(0x2f, {0xc00088e000, 0x0, 0x0}, 0xb59c04, {0x1, 0x4d00029}, 0x0)
Feb 08 08:55:37 hostname.de routedns[13345]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/zmsg.go:666 +0x3f
Feb 08 08:55:37 hostname.de routedns[13345]: github.com/miekg/dns.packRR({0xb7e958, 0xc000439040}, {0xc00088e000, 0x81, 0xffffffffffffffff}, 0x0, {0x0, 0x0}, 0x80)
Feb 08 08:55:37 hostname.de routedns[13345]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:592 +0x171
Feb 08 08:55:37 hostname.de routedns[13345]: github.com/miekg/dns.(*Msg).packBufferWithCompressionMap(0xc0002ea750, {0x0, 0x0, 0x0}, {0x0, 0x0}, 0x0)
Feb 08 08:55:37 hostname.de routedns[13345]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:819 +0x3c5
Feb 08 08:55:37 hostname.de routedns[13345]: github.com/miekg/dns.(*Msg).PackBuffer(0xc0002ea750, {0x0, 0x16, 0x0})
Feb 08 08:55:37 hostname.de routedns[13345]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:735 +0x93
Feb 08 08:55:37 hostname.de routedns[13345]: github.com/miekg/dns.(*Msg).Pack(...)
Feb 08 08:55:37 hostname.de routedns[13345]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:723
Feb 08 08:55:37 hostname.de routedns[13345]: github.com/folbricht/routedns.(*DoHClient).ResolvePOST(0xc00015d9e0, 0xc0002ea750)
Feb 08 08:55:37 hostname.de routedns[13345]:         /root/routedns/routedns/dohclient.go:139 +0xd2
Feb 08 08:55:37 hostname.de routedns[13345]: github.com/folbricht/routedns.(*DoHClient).Resolve(0xc00015d9e0, 0xc0002ea750, {{0xc0004ba7cc, 0x10, 0x10}, {0x0, 0x0}})
Feb 08 08:55:37 hostname.de routedns[13345]:         /root/routedns/routedns/dohclient.go:119 +0x3a5
Feb 08 08:55:37 hostname.de routedns[13345]: github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Feb 08 08:55:37 hostname.de routedns[13345]:         /root/routedns/routedns/fastest.go:43 +0x63
Feb 08 08:55:37 hostname.de routedns[13345]: created by github.com/folbricht/routedns.(*Fastest).Resolve
Feb 08 08:55:37 hostname.de routedns[13345]:         /root/routedns/routedns/fastest.go:42 +0x6f2
brotaxt commented 1 year ago

In the meantime its happening every day :-/

Feb 14 19:48:29 hostname.de routedns[24373]: time="2023-02-14T19:48:29+01:00" level=error msg="NILOPTREC: QName: ips1.unifi-ai.
Feb 14 19:48:29 hostname.de routedns[24373]: goroutine 193011 [running]:
Feb 14 19:48:29 hostname.de routedns[24373]: runtime/debug.Stack()
Feb 14 19:48:29 hostname.de routedns[24373]:         /usr/local/go/src/runtime/debug/stack.go:24 +0x65
Feb 14 19:48:29 hostname.de routedns[24373]: runtime/debug.PrintStack()
Feb 14 19:48:29 hostname.de routedns[24373]:         /usr/local/go/src/runtime/debug/stack.go:16 +0x19
Feb 14 19:48:29 hostname.de routedns[24373]: github.com/folbricht/routedns.(*DoHClient).ResolvePOST.func1()
Feb 14 19:48:29 hostname.de routedns[24373]:         /root/routedns/routedns/dohclient.go:132 +0x245
Feb 14 19:48:29 hostname.de routedns[24373]: panic({0x9e7ba0, 0xf53ac0})
Feb 14 19:48:29 hostname.de routedns[24373]:         /usr/local/go/src/runtime/panic.go:1038 +0x215
Feb 14 19:48:29 hostname.de routedns[24373]: github.com/miekg/dns.packDataOpt({0xc0000416c0, 0x2, 0x23}, {0xc000322240, 0x81, 0
Feb 14 19:48:29 hostname.de routedns[24373]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg_helpers.go:454 +0x1d5
Feb 14 19:48:29 hostname.de routedns[24373]: github.com/miekg/dns.(*OPT).pack(0x23, {0xc000322240, 0x0, 0x0}, 0xb59c04, {0x1, 0
Feb 14 19:48:29 hostname.de routedns[24373]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/zmsg.go:666 +0x3f
Feb 14 19:48:29 hostname.de routedns[24373]: github.com/miekg/dns.packRR({0xb7e958, 0xc000678d40}, {0xc000322240, 0x81, 0xfffff
Feb 14 19:48:29 hostname.de routedns[24373]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:592 +0x171
Feb 14 19:48:29 hostname.de routedns[24373]: github.com/miekg/dns.(*Msg).packBufferWithCompressionMap(0xc0002fa990, {0x0, 0x0,
Feb 14 19:48:29 hostname.de routedns[24373]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:819 +0x3c5
Feb 14 19:48:29 hostname.de routedns[24373]: github.com/miekg/dns.(*Msg).PackBuffer(0xc0002fa990, {0x0, 0x16, 0x0})
Feb 14 19:48:29 hostname.de routedns[24373]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:735 +0x93
Feb 14 19:48:29 hostname.de routedns[24373]: github.com/miekg/dns.(*Msg).Pack(...)
Feb 14 19:48:29 hostname.de routedns[24373]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.48/msg.go:723
Feb 14 19:48:29 hostname.de routedns[24373]: github.com/folbricht/routedns.(*DoHClient).ResolvePOST(0xc0001fc750, 0xc0002fa990)
Feb 14 19:48:29 hostname.de routedns[24373]:         /root/routedns/routedns/dohclient.go:139 +0xd2
Feb 14 19:48:29 hostname.de routedns[24373]: github.com/folbricht/routedns.(*DoHClient).Resolve(0xc0001fc750, 0xc0002fa990, {{0
Feb 14 19:48:29 hostname.de routedns[24373]:         /root/routedns/routedns/dohclient.go:119 +0x3a5
Feb 14 19:48:29 hostname.de routedns[24373]: github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Feb 14 19:48:29 hostname.de routedns[24373]:         /root/routedns/routedns/fastest.go:43 +0x63
Feb 14 19:48:29 hostname.de routedns[24373]: created by github.com/folbricht/routedns.(*Fastest).Resolve
Feb 14 19:48:29 hostname.de routedns[24373]:         /root/routedns/routedns/fastest.go:42 +0x6f2
folbricht commented 1 year ago

Are you using the latest commit on the patch-issue-198 branch (could also try master)? The fix there definitely addressed a whole class of issues so I was hoping this one would be fixed too. It was caused by the request-dedup component there. It's possible there another one lurking

brotaxt commented 1 year ago

Yes I'm using the patch-issue-198 branch with latest commits. Could also try the master branch if there is any difference.

folbricht commented 1 year ago

Would you be able to build off master and use the -race flag when building it? Then occasionally grep the logs for WARNING Hopefully the race-detector will help identify the component that's causing it. If it doesn't work I'll run a copy of your config for a while on my own machine.

bjester commented 1 year ago

I've been running the latest/master branch for a while now with my original config and haven't had any anymore panics. Thanks @folbricht !

On an aside, one thing that confused me being less familiar with Go is that trying to update routedns didn't seem to pull in the latest changes/updates. I needed to upgrade to the latest Go version in order for it to pull the actual latest version

folbricht commented 1 year ago

Thanks for testing it. As for the Go version, I wonder what you saw is related to https://github.com/folbricht/routedns/blob/master/go.mod#L3 which specifies the minimum version to build this and I bumped it a couple of months ago.

brotaxt commented 1 year ago

I can confirm that I also got no more crashes with latest master branch build. thank you! @folbricht

brotaxt commented 1 year ago

Got another one :( 

Feb 24 13:04:25 hostname_here.de routedns[13924]: panic: runtime error: invalid memory address or nil pointer dereference
Feb 24 13:04:25 hostname_here.de routedns[13924]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x46a1f6]
Feb 24 13:04:25 hostname_here.de routedns[13924]: goroutine 109850 [running]:
Feb 24 13:04:25 hostname_here.de routedns[13924]: github.com/miekg/dns.packDataOpt({0xc001dc45c0?, 0x2, 0x81?}, {0xc001aa0000, 0x81, 0x81}, 0x0?)
Feb 24 13:04:25 hostname_here.de routedns[13924]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg_helpers.go:454 +0x1ca
Feb 24 13:04:25 hostname_here.de routedns[13924]: github.com/miekg/dns.(*OPT).pack(0x26?, {0xc001aa0000?, 0x0?, 0x7fd88cdfc500?}, 0xc013a0?, {0x1?, 0x2000029?}, 0x18?)
Feb 24 13:04:25 hostname_here.de routedns[13924]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/zmsg.go:666 +0x3f
Feb 24 13:04:25 hostname_here.de routedns[13924]: github.com/miekg/dns.packRR({0xc10ab0, 0xc0008b26c0}, {0xc001aa0000, 0x81, 0x81}, 0x0?, {0x0?, 0x0?}, 0x48?)
Feb 24 13:04:25 hostname_here.de routedns[13924]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:597 +0x174
Feb 24 13:04:25 hostname_here.de routedns[13924]: github.com/miekg/dns.(*Msg).packBufferWithCompressionMap(0xc001de4750, {0x0, 0x0, 0x0}, {0x0?, 0x0?}, 0x0?)
Feb 24 13:04:25 hostname_here.de routedns[13924]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:824 +0x571
Feb 24 13:04:25 hostname_here.de routedns[13924]: github.com/miekg/dns.(*Msg).PackBuffer(0x0?, {0x0?, 0x15?, 0x10001?})
Feb 24 13:04:25 hostname_here.de routedns[13924]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:740 +0x93
Feb 24 13:04:25 hostname_here.de routedns[13924]: github.com/miekg/dns.(*Msg).Pack(...)
Feb 24 13:04:25 hostname_here.de routedns[13924]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:728
Feb 24 13:04:25 hostname_here.de routedns[13924]: github.com/folbricht/routedns.(*DoHClient).ResolveGET(0xc00031c630, 0xc001a1bde8?)
Feb 24 13:04:25 hostname_here.de routedns[13924]:         /root/routedns/routedns/dohclient.go:151 +0x65
Feb 24 13:04:25 hostname_here.de routedns[13924]: github.com/folbricht/routedns.(*DoHClient).Resolve(0xc00031c630, 0x0?, {{0xc000452060, 0x4, 0x4}, {0x0, 0x0}, {0x0, 0x0}, {0xc0002cd41d, ...}})
Feb 24 13:04:25 hostname_here.de routedns[13924]:         /root/routedns/routedns/dohclient.go:113 +0x2a8
Feb 24 13:04:25 hostname_here.de routedns[13924]: github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Feb 24 13:04:25 hostname_here.de routedns[13924]:         /root/routedns/routedns/fastest.go:42 +0x77
Feb 24 13:04:25 hostname_here.de routedns[13924]: created by github.com/folbricht/routedns.(*Fastest).Resolve
Feb 24 13:04:25 hostname_here.de routedns[13924]:         /root/routedns/routedns/fastest.go:41 +0xd7

Do you want me to build off master and use the -race flag? @folbricht

folbricht commented 1 year ago

Yes please. I suspect there were two issues, one of which has been fixed on master, but there must be one more. Running with -race will write some details into the log prefixed with WARNING, it doesn't necessarily trigger a panic like above

brotaxt commented 1 year ago

No panic so far but there are already multiple warnings in the logs 

Mar 05 19:17:00 hostname.de routedns[4255]: ==================
Mar 05 19:17:00 hostname.de routedns[4255]: WARNING: DATA RACE
Mar 05 19:17:00 hostname.de routedns[4255]: Write at 0x00c000639354 by goroutine 62433:
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*OPT).SetExtendedRcode()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/edns.go:163 +0x186
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*Msg).packBufferWithCompressionMap()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:752 +0x131
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*Msg).PackBuffer()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:740 +0x10b
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*Msg).Pack()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:728 +0x6f
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*DoHClient).ResolveGET()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/dohclient.go:151 +0x5b
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*DoHClient).Resolve()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/dohclient.go:113 +0x3a9
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/fastest.go:42 +0xf4
Mar 05 19:17:00 hostname.de routedns[4255]: Previous write at 0x00c000639354 by goroutine 62434:
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*OPT).SetExtendedRcode()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/edns.go:163 +0x186
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*Msg).packBufferWithCompressionMap()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:752 +0x131
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*Msg).PackBuffer()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:740 +0x10b
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*Msg).Pack()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:728 +0x6f
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*DoHClient).ResolveGET()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/dohclient.go:151 +0x5b
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*DoHClient).Resolve()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/dohclient.go:113 +0x3a9
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/fastest.go:42 +0xf4
Mar 05 19:17:00 hostname.de routedns[4255]: Goroutine 62433 (running) created at:
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*Fastest).Resolve()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/fastest.go:41 +0x126
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*FailBack).Resolve()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/failback.go:86 +0x434
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*TTLModifier).Resolve()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/ttl-modifier.go:50 +0x109
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*Cache).Resolve()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/cache.go:162 +0xbb9
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.listenHandler.func1()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/dnslistener.go:80 +0x8c8
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.HandlerFunc.ServeDNS()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:37 +0x4d
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*Server).serveDNS()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:659 +0x85d
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*Server).serveUDPPacket()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:603 +0x37b
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*Server).serveUDP.func3()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:533 +0xf1
Mar 05 19:17:00 hostname.de routedns[4255]: Goroutine 62434 (running) created at:
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*Fastest).Resolve()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/fastest.go:41 +0x126
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*FailBack).Resolve()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/failback.go:86 +0x434
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*TTLModifier).Resolve()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/ttl-modifier.go:50 +0x109
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.(*Cache).Resolve()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/cache.go:162 +0xbb9
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/folbricht/routedns.listenHandler.func1()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/routedns/routedns/dnslistener.go:80 +0x8c8
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.HandlerFunc.ServeDNS()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:37 +0x4d
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*Server).serveDNS()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:659 +0x85d
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*Server).serveUDPPacket()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:603 +0x37b
Mar 05 19:17:00 hostname.de routedns[4255]:   github.com/miekg/dns.(*Server).serveUDP.func3()
Mar 05 19:17:00 hostname.de routedns[4255]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:533 +0xf1
Mar 05 19:17:00 hostname.de routedns[4255]: ==================
folbricht commented 1 year ago

Perfect, that helped so much! The fix for it should be on the issue-198 branch. Pretty sure this is going to take care of it, but it'd be nice if you could still run it with -race in case there are any others left.

brotaxt commented 1 year ago

another one with latest issue-198 branch

Mar 05 22:29:00 hostname.de routedns[13959]: ==================
Mar 05 22:29:00 hostname.de routedns[13959]: WARNING: DATA RACE
Mar 05 22:29:00 hostname.de routedns[13959]: Write at 0x00c0001200e0 by goroutine 451:
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.quicRestart()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/dohclient.go:390 +0xc92
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*quicConnection).OpenStreamSync()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/dohclient.go:328 +0x1f8
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/quic-go/quic-go/http3.(*client).RoundTripOpt()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/quic-go/quic-go@v0.33.0/http3/client.go:275 +0x7ab
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/quic-go/quic-go/http3.(*RoundTripper).RoundTripOpt()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/quic-go/quic-go@v0.33.0/http3/roundtrip.go:141 +0x947
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/quic-go/quic-go/http3.(*RoundTripper).RoundTrip()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/quic-go/quic-go@v0.33.0/http3/roundtrip.go:155 +0x3a
Mar 05 22:29:00 hostname.de routedns[13959]:   net/http.send()
Mar 05 22:29:00 hostname.de routedns[13959]:       /usr/local/go/src/net/http/client.go:252 +0x942
Mar 05 22:29:00 hostname.de routedns[13959]:   net/http.(*Client).send()
Mar 05 22:29:00 hostname.de routedns[13959]:       /usr/local/go/src/net/http/client.go:176 +0x164
Mar 05 22:29:00 hostname.de routedns[13959]:   net/http.(*Client).do()
Mar 05 22:29:00 hostname.de routedns[13959]:       /usr/local/go/src/net/http/client.go:716 +0x10de
Mar 05 22:29:00 hostname.de routedns[13959]:   net/http.(*Client).Do()
Mar 05 22:29:00 hostname.de routedns[13959]:       /usr/local/go/src/net/http/client.go:582 +0x3bd
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*DoHClient).ResolveGET()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/dohclient.go:174 +0x390
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*DoHClient).Resolve()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/dohclient.go:116 +0x3e6
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/fastest.go:42 +0xf4
Mar 05 22:29:00 hostname.de routedns[13959]: Previous read at 0x00c0001200e0 by goroutine 458:
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*quicConnection).HandshakeComplete()
Mar 05 22:29:00 hostname.de routedns[13959]:       <autogenerated>:1 +0x37
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/quic-go/quic-go/http3.(*client).RoundTripOpt()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/quic-go/quic-go@v0.33.0/http3/client.go:269 +0x52e
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/quic-go/quic-go/http3.(*RoundTripper).RoundTripOpt()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/quic-go/quic-go@v0.33.0/http3/roundtrip.go:141 +0x947
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/quic-go/quic-go/http3.(*RoundTripper).RoundTrip()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/quic-go/quic-go@v0.33.0/http3/roundtrip.go:155 +0x3a
Mar 05 22:29:00 hostname.de routedns[13959]:   net/http.send()
Mar 05 22:29:00 hostname.de routedns[13959]:       /usr/local/go/src/net/http/client.go:252 +0x942
Mar 05 22:29:00 hostname.de routedns[13959]:   net/http.(*Client).send()
Mar 05 22:29:00 hostname.de routedns[13959]:       /usr/local/go/src/net/http/client.go:176 +0x164
Mar 05 22:29:00 hostname.de routedns[13959]:   net/http.(*Client).do()
Mar 05 22:29:00 hostname.de routedns[13959]:       /usr/local/go/src/net/http/client.go:716 +0x10de
Mar 05 22:29:00 hostname.de routedns[13959]:   net/http.(*Client).Do()
Mar 05 22:29:00 hostname.de routedns[13959]:       /usr/local/go/src/net/http/client.go:582 +0x3bd
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*DoHClient).ResolveGET()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/dohclient.go:174 +0x390
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*DoHClient).Resolve()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/dohclient.go:116 +0x3e6
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/fastest.go:42 +0xf4
Mar 05 22:29:00 hostname.de routedns[13959]: Goroutine 451 (running) created at:
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*Fastest).Resolve()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/fastest.go:41 +0x126
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*FailBack).Resolve()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/failback.go:86 +0x434
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*TTLModifier).Resolve()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/ttl-modifier.go:50 +0x109
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*Cache).Resolve()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/cache.go:162 +0xbb9
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.listenHandler.func1()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/dnslistener.go:80 +0x8c8
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/miekg/dns.HandlerFunc.ServeDNS()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:37 +0x4d
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/miekg/dns.(*Server).serveDNS()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:659 +0x85d
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/miekg/dns.(*Server).serveUDPPacket()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:603 +0x37b
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/miekg/dns.(*Server).serveUDP.func3()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:533 +0xf1
Mar 05 22:29:00 hostname.de routedns[13959]: Goroutine 458 (running) created at:
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*Fastest).Resolve()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/fastest.go:41 +0x126
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*FailBack).Resolve()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/failback.go:86 +0x434
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*TTLModifier).Resolve()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/ttl-modifier.go:50 +0x109
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.(*Cache).Resolve()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/cache.go:162 +0xbb9
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/folbricht/routedns.listenHandler.func1()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/routedns/routedns/dnslistener.go:80 +0x8c8
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/miekg/dns.HandlerFunc.ServeDNS()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:37 +0x4d
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/miekg/dns.(*Server).serveDNS()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:659 +0x85d
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/miekg/dns.(*Server).serveUDPPacket()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:603 +0x37b
Mar 05 22:29:00 hostname.de routedns[13959]:   github.com/miekg/dns.(*Server).serveUDP.func3()
Mar 05 22:29:00 hostname.de routedns[13959]:       /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/server.go:533 +0xf1
Mar 05 22:29:00 hostname.de routedns[13959]: ==================
folbricht commented 1 year ago

Perfect, this issue was just introduced. Pushed a fix to the same branch just now.

brotaxt commented 1 year ago

Perfect, this issue was just introduced. Pushed a fix to the same branch just now.

Hm the latest commit does seem to break something. After some time routedns can't resolve any requests. 

error="query for '3-courier.push.apple.com.' timed out" id=local-doh-behind-proxy_ipv4 path=/dns-query protocol=doh qname=3-courier.push.apple.com. qtype=A
error="query for 'gateway.icloud.com.' timed out" id=local-doh-behind-proxy_ipv6 path=/dns-query protocol=doh qname=gateway.icloud.com. qtype=A
error="query for 'websitereview.corp.apple.com.' timed out" id=local-doh-behind-proxy_ipv4 path=/dns-query protocol=doh qname=websitereview.corp.apple.com. qtype=HTTPS
error="query for 'websitereview.corp.apple.com.' timed out" id=local-doh-behind-proxy_ipv4 path=/dns-query protocol=doh qname=websitereview.corp.apple.com. qtype=A
mattkeenan commented 1 year ago

Hmmm I wonder if it's live locking. Do you have any loops in your routing?

folbricht commented 1 year ago

Oops, sorry for that. I reverted the last commit. The caller seems to already hold the lock, so the race is happening somewhere else. Will need look at this again.

brotaxt commented 1 year ago

Got another one with latest master branch :(

Mar 28 05:55:49 HOSTNAME routedns[14490]: panic: runtime error: invalid memory address or nil pointer dereference
Mar 28 05:55:49 HOSTNAME routedns[14490]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x46a221]
Mar 28 05:55:49 HOSTNAME routedns[14490]: goroutine 203907 [running]:
Mar 28 05:55:49 HOSTNAME routedns[14490]: github.com/miekg/dns.packDataOpt({0xc00051fa70?, 0x1, 0x81?}, {0xc00052c510, 0x81, 0x81}, 0x0?)
Mar 28 05:55:49 HOSTNAME routedns[14490]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg_helpers.go:454 +0x1ca
Mar 28 05:55:49 HOSTNAME routedns[14490]: github.com/miekg/dns.(*OPT).pack(0x30?, {0xc00052c510?, 0x0?, 0xc00055cf00?}, 0xc05228?, {0x1?, 0x4d00029?}, 0x0?)
Mar 28 05:55:49 HOSTNAME routedns[14490]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/zmsg.go:666 +0x3f
Mar 28 05:55:49 HOSTNAME routedns[14490]: github.com/miekg/dns.packRR({0xc149b0, 0xc00055cf00}, {0xc00052c510, 0x81, 0x81}, 0x0?, {0x0?, 0x0?}, 0x7c?)
Mar 28 05:55:49 HOSTNAME routedns[14490]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:597 +0x174
Mar 28 05:55:49 HOSTNAME routedns[14490]: github.com/miekg/dns.(*Msg).packBufferWithCompressionMap(0xc0003ab9e0, {0x0, 0x0, 0x0}, {0x0?, 0x0?}, 0x30?)
Mar 28 05:55:49 HOSTNAME routedns[14490]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:824 +0x571
Mar 28 05:55:49 HOSTNAME routedns[14490]: github.com/miekg/dns.(*Msg).PackBuffer(0x0?, {0x0?, 0xc00051f910?, 0x0?})
Mar 28 05:55:49 HOSTNAME routedns[14490]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:740 +0x93
Mar 28 05:55:49 HOSTNAME routedns[14490]: github.com/miekg/dns.(*Msg).Pack(...)
Mar 28 05:55:49 HOSTNAME routedns[14490]:         /root/go/pkg/mod/github.com/miekg/dns@v1.1.50/msg.go:728
Mar 28 05:55:49 HOSTNAME routedns[14490]: github.com/folbricht/routedns.(*DoHClient).ResolveGET(0xc0001f8750, 0xc0006e0de8?)
Mar 28 05:55:49 HOSTNAME routedns[14490]:         /root/routedns/routedns/dohclient.go:160 +0x5e
Mar 28 05:55:49 HOSTNAME routedns[14490]: github.com/folbricht/routedns.(*DoHClient).Resolve(0xc0001f8750, 0xc00013d6c0?, {{0xc00003b8a0, 0x4, 0x4}, {0x0, 0x0}, {0x0, 0x0}, {0xc0001ad471, ...}})
Mar 28 05:55:49 HOSTNAME routedns[14490]:         /root/routedns/routedns/dohclient.go:118 +0x2a8
Mar 28 05:55:49 HOSTNAME routedns[14490]: github.com/folbricht/routedns.(*Fastest).Resolve.func1()
Mar 28 05:55:49 HOSTNAME routedns[14490]:         /root/routedns/routedns/fastest.go:42 +0x77
Mar 28 05:55:49 HOSTNAME routedns[14490]: created by github.com/folbricht/routedns.(*Fastest).Resolve
Mar 28 05:55:49 HOSTNAME routedns[14490]:         /root/routedns/routedns/fastest.go:41 +0xd7
root@HOSTNAME:~# /opt/routedns/routedns --versionb
Error: unknown flag: --versionb
root@HOSTNAME:~# /opt/routedns/routedns --version
Build:  11
Build Time:  Sun Mar 26 10:46:06 UTC 2023
Version:  v0.1.31
folbricht commented 1 year ago

https://github.com/folbricht/routedns/pull/290 (which I just merged) should help somewhat, there's one more issue in QUIC that I need to find.

folbricht commented 1 year ago

All of the known race conditions should be addressed on master. Not sure if there's one more lurking somewhere. Would you be able to run it off master with -race to see if anything shows with your config?

brotaxt commented 1 year ago

Until today I've used the master version from two weeks ago and I couldn't notice any further crashes. I've just build a new version from the master branch right now, I'll keep an eye on the logs.