SIGSEGV in exchangeHTTPSClient

[mnordhoff]

I've been running 29e83b154d8cc505e1a0c33d5a149b0be42ec073 with HTTP/2 and HTTP/3 upstreams for a week. Then this happened:

$ ./dnsproxy --config-path=dnsproxy.yaml
Path: dnsproxy.yaml
2022/09/22 12:55:06 [info] Starting dnsproxy dev
2022/09/22 12:55:06 [info] Starting the DNS proxy server
2022/09/22 12:55:06 [info] DNS cache is enabled
2022/09/22 12:55:06 [info] MaxGoroutines is set to 1000
2022/09/22 12:55:06 [info] Creating the UDP server socket
2022/09/22 12:55:06 [info] Listening to udp://127.0.0.1:1053
2022/09/22 12:55:06 [info] Creating the UDP server socket
2022/09/22 12:55:06 [info] Listening to udp://[::1]:1053
2022/09/22 12:55:06 [info] Creating a TCP server socket
2022/09/22 12:55:06 [info] Listening to tcp://127.0.0.1:1053
2022/09/22 12:55:06 [info] Creating a TCP server socket
2022/09/22 12:55:06 [info] Listening to tcp://[::1]:1053
2022/09/22 12:55:06 [info] Entering the UDP listener loop on [::1]:1053
2022/09/22 12:55:06 [info] Entering the UDP listener loop on 127.0.0.1:1053
2022/09/22 12:55:06 [info] Entering the tcp listener loop on [::1]:1053
2022/09/22 12:55:06 [info] Entering the tcp listener loop on 127.0.0.1:1053
2022/09/22 12:55:33 failed to sufficiently increase receive buffer size (was: 208 kiB, wanted: 2048 kiB, got: 416 kiB). See https://github.com/lucas-clemente/quic-go/wiki/UDP-Receive-Buffer-Size for details.
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x7d90eb]

goroutine 462247 [running]:
github.com/AdguardTeam/dnsproxy/upstream.(*dnsOverHTTPS).exchangeHTTPSClient(0xc000022560, 0xc000186480, 0xc000186480?)
        /home/mnordhoff/src/git/dnsproxy/upstream/upstream_doh.go:161 +0x10b
github.com/AdguardTeam/dnsproxy/upstream.(*dnsOverHTTPS).exchangeHTTPS(0xc000022560, 0xa023c0?)
        /home/mnordhoff/src/git/dnsproxy/upstream/upstream_doh.go:144 +0xaa
github.com/AdguardTeam/dnsproxy/upstream.(*dnsOverHTTPS).Exchange(0xc000022560, 0xc000186480)
        /home/mnordhoff/src/git/dnsproxy/upstream/upstream_doh.go:123 +0x11b
github.com/AdguardTeam/dnsproxy/proxy.exchangeWithUpstream({0xa04860, 0xc000022560}, 0xc000186480)
        /home/mnordhoff/src/git/dnsproxy/proxy/exchange.go:68 +0x72
github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).exchange(0xc000169880, 0xc000186480, {0xc00010d940?, 0xc000784100?, 0x1?})
        /home/mnordhoff/src/git/dnsproxy/proxy/exchange.go:39 +0x228
github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).replyFromUpstream(0xc000169880, 0xc0000a0300)
        /home/mnordhoff/src/git/dnsproxy/proxy/proxy.go:388 +0x118
github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).Resolve(0xc000169880, 0xc0000a0300)
        /home/mnordhoff/src/git/dnsproxy/proxy/proxy.go:471 +0xb4
github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).handleDNSRequest(0xc000169880, 0xc0000a0300)
        /home/mnordhoff/src/git/dnsproxy/proxy/server.go:132 +0x3de
github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).udpHandlePacket(0xc000169880, {0xc0007060c0, 0x22, 0x22}, {0xc0003f4090, 0x10, 0x10}, 0xc0008001b0, 0xc000012628)
        /home/mnordhoff/src/git/dnsproxy/proxy/server_udp.go:109 +0x2cb
github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).udpPacketLoop.func1()
        /home/mnordhoff/src/git/dnsproxy/proxy/server_udp.go:76 +0x4f
created by github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).udpPacketLoop
        /home/mnordhoff/src/git/dnsproxy/proxy/server_udp.go:75 +0x37e

The crash happened about when my Internet connectivity went down for a few minutes, so if there's a race condition when it's reconnecting, or when a connection is being torn down, it may have hit it.

I'm just guessing, but this may need to take the clientGuard lock?

https://github.com/AdguardTeam/dnsproxy/blob/29e83b154d8cc505e1a0c33d5a149b0be42ec073/upstream/upstream_doh.go#L161

dnsproxy.yaml

[mnordhoff]

FYI, my Internet connection went down again, and dnsproxy crashed again.

With a sample size of 2, this bug happens 100% of the time.

Luckily it didn't make it into a release. :-)

My past experience is that my Internet connection is terribly unreliable, and dnsproxy is extremely reliable. Y'all have done a good job on it. :-)

Edit: All credit to Hurricane Ian. I'm not in any danger, but the infrastructure is shaky.

[mnordhoff]

I can verify that de0dfe9d9d707dbc1301bf12850e753bb226b76e seems to fix this crash, FWIW.

[mnordhoff]

Thank you! :-)

[mnordhoff]

P.S. The hurricane is leaving this area, so I may be unable to do more testing today. :-)

[ameshkov]

No worries, it should be good now, the bug was rather stupid actually :)

[Potterli20]

No worries, it should be good now, the bug was rather stupid actually :)

Oct 01 22:23:47 potter dnsproxy[254890]: panic: net/http: internal error: connCount underflow Oct 01 22:23:47 potter dnsproxy[254890]: goroutine 216915 [running]: Oct 01 22:23:47 potter dnsproxy[254890]: net/http.(Transport).decConnsPerHost(0xc01b9f4b40, {{0x0, 0x0}, {0xc029572300, 0x5}, {0xc02892a820, 0xe}, 0x0}) Oct 01 22:23:47 potter dnsproxy[254890]: /usr/local/go/src/net/http/transport.go:1476 +0x592 Oct 01 22:23:47 potter dnsproxy[254890]: net/http.(Transport).roundTrip(0xc01b9f4b40, 0xc0283b3f00) Oct 01 22:23:47 potter dnsproxy[254890]: /usr/local/go/src/net/http/transport.go:605 +0x88b Oct 01 22:23:47 potter dnsproxy[254890]: net/http.(Transport).RoundTrip(0xc0283b3f00?, 0xa09280?) Oct 01 22:23:47 potter dnsproxy[254890]: /usr/local/go/src/net/http/roundtrip.go:17 +0x19 Oct 01 22:23:47 potter dnsproxy[254890]: net/http.send(0xc0283b3e00, {0xa09280, 0xc01b9f4b40}, {0x92f480?, 0x4b6c01?, 0xcdbf60?}) Oct 01 22:23:47 potter dnsproxy[254890]: /usr/local/go/src/net/http/client.go:251 +0x5f7 Oct 01 22:23:47 potter dnsproxy[254890]: net/http.(Client).send(0xc02c110810, 0xc0283b3e00, {0x0?, 0x40e75f?, 0xcdbf60?}) Oct 01 22:23:47 potter dnsproxy[254890]: /usr/local/go/src/net/http/client.go:175 +0x9b Oct 01 22:23:47 potter dnsproxy[254890]: net/http.(Client).do(0xc02c110810, 0xc0283b3e00) Oct 01 22:23:47 potter dnsproxy[254890]: /usr/local/go/src/net/http/client.go:715 +0x8fc Oct 01 22:23:47 potter dnsproxy[254890]: net/http.(Client).Do(...) Oct 01 22:23:47 potter dnsproxy[254890]: /usr/local/go/src/net/http/client.go:581 Oct 01 22:23:47 potter dnsproxy[254890]: github.com/AdguardTeam/dnsproxy//upstream.(dnsOverHTTPS).exchangeHTTPSClient(0xc000196390, 0xc014f567e0, 0xc02c110810) Oct 01 22:23:47 potter dnsproxy[254890]: /root/dnsproxy/upstream/upstream_doh.go:176 +0x4b2 Oct 01 22:23:47 potter dnsproxy[254890]: github.com/AdguardTeam/dnsproxy//upstream.(dnsOverHTTPS).exchangeHTTPS(0xc000196390, 0xc0283dbf50?) Oct 01 22:23:47 potter dnsproxy[254890]: /root/dnsproxy/upstream/upstream_doh.go:139 +0xaa Oct 01 22:23:47 potter dnsproxy[254890]: github.com/AdguardTeam/dnsproxy//upstream.(*dnsOverHTTPS).Exchange(0xc016c7b4d0?, 0xc014f567e0) Oct 01 22:23:47 potter dnsproxy[254890]: /root/dnsproxy/upstream/upstream_doh.go:107 +0xdb Oct 01 22:23:47 potter dnsproxy[254890]: github.com/AdguardTeam/dnsproxy//upstream.exchangeAsync({0xa0b160, 0xc000196390}, 0xc034462d20?, 0x0?) Oct 01 22:23:47 potter dnsproxy[254890]: /root/dnsproxy/upstream/parallel.go:117 +0x58 Oct 01 22:23:47 potter dnsproxy[254890]: created by github.com/AdguardTeam/dnsproxy//upstream.ExchangeParallel Oct 01 22:23:47 potter dnsproxy[254890]: /root/dnsproxy/upstream/parallel.go:45 +0x18c Oct 01 22:23:48 potter systemd[1]: dnsproxy-dns.service: Main process exited, code=exited, status=2/INVALIDARGUMENT Oct 01 22:23:48 potter systemd[1]: dnsproxy-dns.service: Failed with result 'exit-code'.

[Potterli20]

No worries, it should be good now, the bug was rather stupid actually :)

The latest one has been compiled manually. There are too many connections, and the feeling is easy to repeat.