upstream: imp logging, test

upstream/upstream.go

@@ -292,12 +292,12 @@ func logBegin(upstreamAddress string, n network, req *dns.Msg) {
 }
 
 // Write to log about the result of DNS request
-func logFinish(upstreamAddress string, err error) {
+func logFinish(upstreamAddress string, n network, err error) {
 	status := "ok"
 	if err != nil {
 		status = err.Error()
 	}
-	log.Debug("%s: response: %s", upstreamAddress, status)
+	log.Debug("%s: response received over %s: %s", upstreamAddress, n, status)
 }
 
 // DialerInitializer returns the handler that it creates.  All the subsequent

upstream/upstream_doh.go

@@ -211,9 +211,14 @@ func (p *dnsOverHTTPS) closeClient(client *http.Client) (err error) {
 func (p *dnsOverHTTPS) exchangeHTTPS(client *http.Client, req *dns.Msg) (resp *dns.Msg, err error) {
 	addr := p.Address()
 
-	logBegin(addr, networkTCP, req)
+	n := networkTCP
+	if isHTTP3(client) {
+		n = networkUDP
+	}
+
+	logBegin(addr, n, req)
 	resp, err = p.exchangeHTTPSClient(client, req)
-	logFinish(addr, err)
+	logFinish(addr, n, err)
 
 	return resp, err
 }

upstream/upstream_dot.go

@@ -199,7 +199,7 @@ func (p *dnsOverTLS) exchangeWithConn(conn net.Conn, m *dns.Msg) (reply *dns.Msg
 	addr := p.Address()
 
 	logBegin(addr, networkTCP, m)
-	defer func() { logFinish(addr, err) }()
+	defer func() { logFinish(addr, networkTCP, err) }()
 
 	dnsConn := dns.Conn{Conn: conn}
 

upstream/upstream_plain.go

@@ -99,7 +99,7 @@ func (p *plainDNS) dialExchange(
 	}
 
 	logBegin(addr, network, req)
-	defer func() { logFinish(addr, err) }()
+	defer func() { logFinish(addr, network, err) }()
 
 	ctx := context.Background()
 	conn.Conn, err = dial(ctx, string(network), "")

upstream/upstream_plain_test.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"io"
 	"net"
+	"sync/atomic"
 	"testing"
 	"time"
 
@@ -79,23 +80,30 @@ func TestUpstream_plainDNS_fallback(t *testing.T) {
 	testCases := []struct {
 		udpResp *dns.Msg
 		name    string
+		wantNum int
 	}{{
 		udpResp: goodResp,
 		name:    "all_right",
+		wantNum: 1,
 	}, {
 		udpResp: truncResp,
 		name:    "truncated_response",
+		wantNum: 2,
 	}, {
 		udpResp: badQNameResp,
 		name:    "bad_qname",
+		wantNum: 2,
 	}, {
 		udpResp: badQTypeResp,
 		name:    "bad_qtype",
+		wantNum: 2,
 	}}
 
 	for _, tc := range testCases {
 		t.Run(tc.name, func(t *testing.T) {
+			var reqNum uint32
 			srv := startDNSServer(t, func(w dns.ResponseWriter, _ *dns.Msg) {
+				atomic.AddUint32(&reqNum, 1)
 				resp := goodResp
 				if w.RemoteAddr().Network() == string(networkUDP) {
 					resp = tc.udpResp
@@ -116,6 +124,8 @@ func TestUpstream_plainDNS_fallback(t *testing.T) {
 			resp, err := u.Exchange(req)
 			require.NoError(t, err)
 			requireResponse(t, req, resp)
+
+			assert.Equal(t, tc.wantNum, int(reqNum))
 		})
 	}
 }