net/dns/resolver: log source IP of forwarded queries

When the TS_DEBUG_DNS_FORWARD_SEND envknob is turned on, also log the
source IP:port of the query that tailscaled is forwarding.

Updates tailscale/corp#35374

Signed-off-by: Andrew Dunham <[email protected]>

net/dns/resolver/forwarder.go

@@ -526,9 +526,9 @@ func (f *forwarder) send(ctx context.Context, fq *forwardQuery, rr resolverAndDe
 	if f.verboseFwd {
 		id := forwarderCount.Add(1)
 		domain, typ, _ := nameFromQuery(fq.packet)
-		f.logf("forwarder.send(%q, %d, %v, %d) [%d] ...", rr.name.Addr, fq.txid, typ, len(domain), id)
+		f.logf("forwarder.send(%q, %d, %v, %d) from %v [%d] ...", rr.name.Addr, fq.txid, typ, len(domain), fq.src, id)
 		defer func() {
-			f.logf("forwarder.send(%q, %d, %v, %d) [%d] = %v, %v", rr.name.Addr, fq.txid, typ, len(domain), id, len(ret), err)
+			f.logf("forwarder.send(%q, %d, %v, %d) from %v [%d] = %v, %v", rr.name.Addr, fq.txid, typ, len(domain), fq.src, id, len(ret), err)
 		}()
 	}
 	if strings.HasPrefix(rr.name.Addr, "http://") {
@@ -904,6 +904,7 @@ type forwardQuery struct {
 	txid   txid
 	packet []byte
 	family string // "tcp" or "udp"
+	src    netip.AddrPort
 
 	// closeOnCtxDone lets send register values to Close if the
 	// caller's ctx expires. This avoids send from allocating its
@@ -988,6 +989,7 @@ func (f *forwarder) forwardWithDestChan(ctx context.Context, query packet, respo
 		txid:           getTxID(query.bs),
 		packet:         query.bs,
 		family:         query.family,
+		src:            query.addr,
 		closeOnCtxDone: new(closePool),
 	}
 	defer fq.closeOnCtxDone.Close()

net/dns/resolver/forwarder_test.go

@@ -864,3 +864,49 @@ func TestNXDOMAINIncludesQuestion(t *testing.T) {
 		t.Errorf("invalid response\ngot: %+v\nwant: %+v", res, response)
 	}
 }
+
+func TestForwarderVerboseLogs(t *testing.T) {
+	const domain = "test.tailscale.com."
+	response := makeTestResponse(t, domain, dns.RCodeServerFailure)
+	request := makeTestRequest(t, domain)
+
+	port := runDNSServer(t, nil, response, func(isTCP bool, gotRequest []byte) {
+		if !bytes.Equal(request, gotRequest) {
+			t.Errorf("invalid request\ngot: %+v\nwant: %+v", gotRequest, request)
+		}
+	})
+
+	var (
+		mu     sync.Mutex // protects following
+		done   bool
+		logBuf bytes.Buffer
+	)
+	fwdLogf := func(format string, args ...any) {
+		mu.Lock()
+		defer mu.Unlock()
+		if done {
+			return // no logging after test is done
+		}
+
+		t.Logf("[forwarder] "+format, args...)
+		fmt.Fprintf(&logBuf, format+"\n", args...)
+	}
+	t.Cleanup(func() {
+		mu.Lock()
+		done = true
+		mu.Unlock()
+	})
+
+	_, err := runTestQuery(t, request, func(f *forwarder) {
+		f.logf = fwdLogf
+		f.verboseFwd = true
+	}, port)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	logStr := logBuf.String()
+	if !strings.Contains(logStr, "forwarder.send(") {
+		t.Errorf("expected forwarding log, got:\n%s", logStr)
+	}
+}