feat: log HTTP req/resp and transport protocol (#14)

This diff:

1. modifies dohttps.go to log the HTTP req/resp using httpslog

2. modifies slog.go to log the transport protocol

3. while there, uses netipx to convert `net.Addr` to `netip.AddrPort`

4. while there, updates the dependencies in go.mod/go.sum

dohttps.go

@@ -19,6 +19,7 @@ import (
 	"sync"
 
 	"github.com/miekg/dns"
+	"github.com/rbmk-project/common/httpslog"
 )
 
 // newHTTPRequestWithContext is a helper function that creates a new HTTP request
@@ -133,11 +134,38 @@ func (t *Transport) queryHTTPS(ctx context.Context,
 	}
 	req.Header.Set("content-type", "application/dns-message")
 
-	// 3. Receive the response headers making sure we close
+	// 3. Log the HTTP request we're sending.
+	httpslog.MaybeLogRoundTripStart(
+		t.Logger,
+		netip.MustParseAddrPort("[::]:0"), // not yet known
+		"tcp",
+		netip.MustParseAddrPort("[::]:0"), // not yet known
+		req,
+		t0,
+	)
+
+	// 4. Receive the response headers making sure we close
 	// the body, the response code is 200, and the content type
 	// is the expected one. Since servers always include the
 	// content type, we don't need to be flexible here.
 	httpResp, laddr, raddr, err := t.httpClientDo(req)
+
+	// 5. Log the result of the HTTP transfer.
+	httpslog.MaybeLogRoundTripDone(
+		t.Logger,
+		laddr,
+		"tcp",
+		raddr,
+		req,
+		httpResp,
+		err,
+		t0,
+		t.timeNow(),
+	)
+
+	// 6. Make sure we close the body, the response code is 200,
+	// and the content type is the expected one. Since servers
+	// always include the content type, we don't need to be flexible here.
 	if err != nil {
 		return nil, err
 	}
@@ -149,7 +177,7 @@ func (t *Transport) queryHTTPS(ctx context.Context,
 		return nil, ErrServerMisbehaving
 	}
 
-	// 4. Now that headers are OK, we read the whole raw response
+	// 7. Now that headers are OK, we read the whole raw response
 	// body, decode it, and possibly log it.
 	reader := io.LimitReader(httpResp.Body, int64(edns0MaxResponseSize(query)))
 	rawResp, err := t.readAllContext(ctx, reader, httpResp.Body)

go.mod

@@ -4,8 +4,8 @@ go 1.23.3
 
 require (
 	github.com/miekg/dns v1.1.62
-	github.com/rbmk-project/common v0.4.0
-	github.com/stretchr/testify v1.9.0
+	github.com/rbmk-project/common v0.8.0
+	github.com/stretchr/testify v1.10.0
 	golang.org/x/net v0.31.0
 )
 

go.sum

@@ -6,10 +6,10 @@ github.com/miekg/dns v1.1.62 h1:cN8OuEF1/x5Rq6Np+h1epln8OiyPWV+lROx9LxcGgIQ=
 github.com/miekg/dns v1.1.62/go.mod h1:mvDlcItzm+br7MToIKqkglaGhlFMHJ9DTNNWONWXbNQ=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
-github.com/rbmk-project/common v0.4.0 h1:gw7f/YdPxcUZ81cO9IMzEPDhsc6tOUte1m0OFi6euFg=
-github.com/rbmk-project/common v0.4.0/go.mod h1:uzrFIJl8SEOpgS2pSeBFLUgqc4D1lIcGk/EYuxkFO0U=
-github.com/stretchr/testify v1.9.0 h1:HtqpIVDClZ4nwg75+f6Lvsy/wHu+3BoSGCbBAcpTsTg=
-github.com/stretchr/testify v1.9.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY=
+github.com/rbmk-project/common v0.8.0 h1:drbBLv15jwFcGvmu3/J5Uf5sre9VZvx85tuQRlZEugc=
+github.com/rbmk-project/common v0.8.0/go.mod h1:BsIum8cGFuNxktk3yWVGlr2B18wtyzn3evb3nhvGyig=
+github.com/stretchr/testify v1.10.0 h1:Xv5erBjTwe/5IxqUQTdXv5kgmIvbHo3QQyRwhJsOfJA=
+github.com/stretchr/testify v1.10.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY=
 golang.org/x/mod v0.22.0 h1:D4nJWe9zXqHOmWqj4VMOJhvzj7bEZg4wEYa759z1pH4=
 golang.org/x/mod v0.22.0/go.mod h1:6SkKJ3Xj0I0BrPOZoBy3bdMptDDU9oJrpohJ3eWZ1fY=
 golang.org/x/net v0.31.0 h1:68CPQngjLL0r2AlUKiSxtQFKvzRVbnzLwMUn5SzcLHo=

slog.go

@@ -8,20 +8,19 @@ import (
 	"net"
 	"net/netip"
 	"time"
+
+	"github.com/rbmk-project/common/netipx"
 )
 
-// addrToAddrPort converts a net.Addr to a netip.AddrPort.
-func addrToAddrPort(addr net.Addr) netip.AddrPort {
-	if addr == nil {
-		return netip.AddrPortFrom(netip.IPv6Unspecified(), 0)
-	}
-	if tcp, ok := addr.(*net.TCPAddr); ok {
-		return tcp.AddrPort()
-	}
-	if udp, ok := addr.(*net.UDPAddr); ok {
-		return udp.AddrPort()
-	}
-	return netip.AddrPortFrom(netip.IPv6Unspecified(), 0)
+// addrToAddrPort is an alias for [common.AddrToAddrPort].
+var addrToAddrPort = netipx.AddrToAddrPort
+
+// protocolMap maps the DNS protocol to the corresponding network protocol.
+var protocolMap = map[Protocol]string{
+	ProtocolDoH: "tcp",
+	ProtocolTCP: "tcp",
+	ProtocolDoT: "tcp",
+	ProtocolUDP: "udp",
 }
 
 // maybeLogQuery is a helper function that logs the query if the logger is set
@@ -37,6 +36,7 @@ func (t *Transport) maybeLogQuery(
 			slog.String("serverAddr", addr.Address),
 			slog.String("serverProtocol", string(addr.Protocol)),
 			slog.Time("t", t0),
+			slog.String("protocol", protocolMap[addr.Protocol]),
 		)
 	}
 	return t0
@@ -66,6 +66,7 @@ func (t *Transport) maybeLogResponseAddrPort(ctx context.Context,
 			slog.String("serverProtocol", string(addr.Protocol)),
 			slog.Time("t0", t0),
 			slog.Time("t", t.timeNow()),
+			slog.String("protocol", protocolMap[addr.Protocol]),
 		)
 	}
 }

slog_test.go

@@ -16,51 +16,6 @@ import (
 	"github.com/stretchr/testify/assert"
 )
 
-func Test_addrToAddrPort(t *testing.T) {
-	tests := []struct {
-		name string
-		addr net.Addr
-		want netip.AddrPort
-	}{
-		{
-			name: "nil address",
-			addr: nil,
-			want: netip.AddrPortFrom(netip.IPv6Unspecified(), 0),
-		},
-
-		{
-			name: "TCP address",
-			addr: &net.TCPAddr{
-				IP:   net.ParseIP("2001:db8::1"),
-				Port: 1234,
-			},
-			want: netip.MustParseAddrPort("[2001:db8::1]:1234"),
-		},
-
-		{
-			name: "UDP address",
-			addr: &net.UDPAddr{
-				IP:   net.ParseIP("2001:db8::2"),
-				Port: 5678,
-			},
-			want: netip.MustParseAddrPort("[2001:db8::2]:5678"),
-		},
-
-		{
-			name: "other address type",
-			addr: &net.UnixAddr{},
-			want: netip.AddrPortFrom(netip.IPv6Unspecified(), 0),
-		},
-	}
-
-	for _, tt := range tests {
-		t.Run(tt.name, func(t *testing.T) {
-			got := addrToAddrPort(tt.addr)
-			assert.Equal(t, tt.want, got)
-		})
-	}
-}
-
 func TestTransport_maybeLogQuery(t *testing.T) {
 	tests := []struct {
 		name       string
@@ -82,7 +37,7 @@ func TestTransport_maybeLogQuery(t *testing.T) {
 				}))
 			},
 			expectTime: time.Date(2020, 1, 1, 0, 0, 0, 0, time.UTC),
-			expectLog:  "{\"level\":\"INFO\",\"msg\":\"dnsQuery\",\"dnsRawQuery\":\"AAAAAA==\",\"serverAddr\":\"8.8.8.8:53\",\"serverProtocol\":\"udp\",\"t\":\"2020-01-01T00:00:00Z\"}\n",
+			expectLog:  "{\"level\":\"INFO\",\"msg\":\"dnsQuery\",\"dnsRawQuery\":\"AAAAAA==\",\"serverAddr\":\"8.8.8.8:53\",\"serverProtocol\":\"udp\",\"t\":\"2020-01-01T00:00:00Z\",\"protocol\":\"udp\"}\n",
 		},
 
 		{
@@ -140,7 +95,7 @@ func TestTransport_maybeLogResponseAddrPort(t *testing.T) {
 			},
 			laddr:     netip.MustParseAddrPort("[2001:db8::1]:1234"),
 			raddr:     netip.MustParseAddrPort("[2001:db8::2]:443"),
-			expectLog: "{\"level\":\"INFO\",\"msg\":\"dnsResponse\",\"localAddr\":\"[2001:db8::1]:1234\",\"dnsRawQuery\":\"AAAAAA==\",\"dnsRawResponse\":\"AQEBAQ==\",\"remoteAddr\":\"[2001:db8::2]:443\",\"serverAddr\":\"8.8.8.8:53\",\"serverProtocol\":\"udp\",\"t0\":\"2020-01-01T00:00:00Z\",\"t\":\"2020-01-01T00:00:11Z\"}\n",
+			expectLog: "{\"level\":\"INFO\",\"msg\":\"dnsResponse\",\"localAddr\":\"[2001:db8::1]:1234\",\"dnsRawQuery\":\"AAAAAA==\",\"dnsRawResponse\":\"AQEBAQ==\",\"remoteAddr\":\"[2001:db8::2]:443\",\"serverAddr\":\"8.8.8.8:53\",\"serverProtocol\":\"udp\",\"t0\":\"2020-01-01T00:00:00Z\",\"t\":\"2020-01-01T00:00:11Z\",\"protocol\":\"udp\"}\n",
 		},
 
 		{
@@ -158,7 +113,7 @@ func TestTransport_maybeLogResponseAddrPort(t *testing.T) {
 			},
 			laddr:     netip.AddrPort{}, // invalid
 			raddr:     netip.AddrPort{}, // invalid
-			expectLog: "{\"level\":\"INFO\",\"msg\":\"dnsResponse\",\"localAddr\":\"[::]:0\",\"dnsRawQuery\":\"AAAAAA==\",\"dnsRawResponse\":\"AQEBAQ==\",\"remoteAddr\":\"[::]:0\",\"serverAddr\":\"8.8.8.8:53\",\"serverProtocol\":\"udp\",\"t0\":\"2020-01-01T00:00:00Z\",\"t\":\"2020-01-01T00:00:11Z\"}\n",
+			expectLog: "{\"level\":\"INFO\",\"msg\":\"dnsResponse\",\"localAddr\":\"[::]:0\",\"dnsRawQuery\":\"AAAAAA==\",\"dnsRawResponse\":\"AQEBAQ==\",\"remoteAddr\":\"[::]:0\",\"serverAddr\":\"8.8.8.8:53\",\"serverProtocol\":\"udp\",\"t0\":\"2020-01-01T00:00:00Z\",\"t\":\"2020-01-01T00:00:11Z\",\"protocol\":\"udp\"}\n",
 		},
 
 		{
@@ -233,7 +188,7 @@ func TestTransport_maybeLogResponseConn(t *testing.T) {
 					}
 				},
 			},
-			expectLog: "{\"level\":\"INFO\",\"msg\":\"dnsResponse\",\"localAddr\":\"[2001:db8::1]:1234\",\"dnsRawQuery\":\"AAAAAA==\",\"dnsRawResponse\":\"AQEBAQ==\",\"remoteAddr\":\"[2001:db8::2]:443\",\"serverAddr\":\"8.8.8.8:53\",\"serverProtocol\":\"udp\",\"t0\":\"2020-01-01T00:00:00Z\",\"t\":\"2020-01-01T00:00:11Z\"}\n",
+			expectLog: "{\"level\":\"INFO\",\"msg\":\"dnsResponse\",\"localAddr\":\"[2001:db8::1]:1234\",\"dnsRawQuery\":\"AAAAAA==\",\"dnsRawResponse\":\"AQEBAQ==\",\"remoteAddr\":\"[2001:db8::2]:443\",\"serverAddr\":\"8.8.8.8:53\",\"serverProtocol\":\"udp\",\"t0\":\"2020-01-01T00:00:00Z\",\"t\":\"2020-01-01T00:00:11Z\",\"protocol\":\"udp\"}\n",
 		},
 
 		{
@@ -257,7 +212,7 @@ func TestTransport_maybeLogResponseConn(t *testing.T) {
 					return &net.UnixAddr{Name: "/tmp/remote.sock", Net: "unix"}
 				},
 			},
-			expectLog: "{\"level\":\"INFO\",\"msg\":\"dnsResponse\",\"localAddr\":\"[::]:0\",\"dnsRawQuery\":\"AAAAAA==\",\"dnsRawResponse\":\"AQEBAQ==\",\"remoteAddr\":\"[::]:0\",\"serverAddr\":\"8.8.8.8:53\",\"serverProtocol\":\"udp\",\"t0\":\"2020-01-01T00:00:00Z\",\"t\":\"2020-01-01T00:00:11Z\"}\n",
+			expectLog: "{\"level\":\"INFO\",\"msg\":\"dnsResponse\",\"localAddr\":\"[::]:0\",\"dnsRawQuery\":\"AAAAAA==\",\"dnsRawResponse\":\"AQEBAQ==\",\"remoteAddr\":\"[::]:0\",\"serverAddr\":\"8.8.8.8:53\",\"serverProtocol\":\"udp\",\"t0\":\"2020-01-01T00:00:00Z\",\"t\":\"2020-01-01T00:00:11Z\",\"protocol\":\"udp\"}\n",
 		},
 
 		{