net: resolver dials multiple times in parallel, and retries same server before progressing

[rittneje]

What version of Go are you using (go version)?

$ go version
go version go1.12.6 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/jrittner/test"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build901728362=/tmp/go-build -gno-record-gcc-switches"

What did you do?

package main

import (
	"context"
	"log"
	"net"
	"time"
)

func main() {
	log.SetFlags(log.Ldate | log.Ltime | log.Lmicroseconds)

	r := &net.Resolver{
		Dial: func(ctx context.Context, network, address string) (net.Conn, error) {
			log.Printf("dialing %s %s", network, address)
			c, err := (&net.Dialer{}).DialContext(ctx, network, address)
			log.Printf("dialed %s %s: %v", network, address, err)
			return c, err
		},
	}

	start := time.Now()
	ips, err := r.LookupIPAddr(context.Background(), "google.com")
	if err != nil {
		panic(err)
	}
	log.Printf("found %s in %s", ips, time.Since(start))
}

What did you expect to see?

I expected it to try the first DNS address (10.5.6.62), and then the second address (10.1.200.107), and so on. Then it should retry the whole list.

What did you see instead?

It dials the first address twice, then tries the second one twice. Based on the logs, it appears it's actually trying the first address multiple times in parallel.

2019/07/01 17:53:47.573043 dialing udp 10.5.6.62:53
2019/07/01 17:53:47.573134 dialing udp 10.5.6.62:53
2019/07/01 17:53:47.601009 dialed udp 10.5.6.62:53: <nil>
2019/07/01 17:53:47.601536 dialed udp 10.5.6.62:53: <nil>
2019/07/01 17:53:47.613209 dialing udp 10.1.200.107:53
2019/07/01 17:53:47.613244 dialed udp 10.1.200.107:53: <nil>
2019/07/01 17:53:47.613487 dialing udp 10.1.200.107:53
2019/07/01 17:53:47.613520 dialed udp 10.1.200.107:53: <nil>
2019/07/01 17:53:47.625651 found [{172.217.12.174 } {2607:f8b0:4006:81a::200e }] in 52.840456ms

2019/07/01 17:58:20.147380 dialing udp 10.5.6.62:53
2019/07/01 17:58:20.147502 dialed udp 10.5.6.62:53: <nil>
2019/07/01 17:58:20.147588 dialing udp 10.5.6.62:53
2019/07/01 17:58:20.147931 dialed udp 10.5.6.62:53: <nil>
2019/07/01 17:58:20.159991 dialing udp 10.1.200.107:53
2019/07/01 17:58:20.160090 dialed udp 10.1.200.107:53: <nil>
2019/07/01 17:58:20.160454 dialing udp 10.1.200.107:53
2019/07/01 17:58:20.160718 dialed udp 10.1.200.107:53: <nil>
2019/07/01 17:58:20.173992 found [{172.217.12.174 } {2607:f8b0:4006:81a::200e }] in 26.775942ms

[bcmills]

CC @mikioh

[rittneje]

After digging deeper into the implementation of the standard library, I've found the culprit. goLookupIPCNAMEOrder spawns two goroutines - one for A records (IPv4) and one for AAAA records (IPv6). So that would at least explain what I'm seeing. However, I am surprised it does it that way instead of just sending both requests through one network connection.