Reland "Replace log package with fully slog-based system"

This reverts commit 7390cf7.

Author: aarongable

bdns/dns.go

@@ -6,6 +6,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"log/slog"
 	"net"
 	"net/http"
 	"strconv"
@@ -17,7 +18,7 @@ import (
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
 
-	blog "github.com/letsencrypt/boulder/log"
+	"github.com/letsencrypt/boulder/blog"
 	"github.com/letsencrypt/boulder/metrics"
 )
 
@@ -226,7 +227,12 @@ func (c *impl) exchangeOne(ctx context.Context, hostname string, qtype uint16) (
 		}).Observe(rtt.Seconds())
 
 		if err != nil {
-			c.log.Infof("logDNSError chosenServer=[%s] hostname=[%s] queryType=[%s] err=[%s]", chosenServer, hostname, qtypeStr, err)
+			c.log.Info(ctx, "logDNSError",
+				slog.String("chosenServer", chosenServer),
+				slog.String("hostname", hostname),
+				slog.String("qtype", qtypeStr),
+				blog.Error(err),
+			)
 
 			// Check if the error is a network timeout, rather than a local context
 			// timeout. If it is, retry instead of giving up.

bdns/dns_test.go

@@ -22,7 +22,7 @@ import (
 	"github.com/miekg/dns"
 	"github.com/prometheus/client_golang/prometheus"
 
-	blog "github.com/letsencrypt/boulder/log"
+	"github.com/letsencrypt/boulder/blog"
 	"github.com/letsencrypt/boulder/metrics"
 	"github.com/letsencrypt/boulder/test"
 )
@@ -283,7 +283,7 @@ func TestDNSNoServers(t *testing.T) {
 	staticProvider, err := NewStaticProvider([]string{})
 	test.AssertNotError(t, err, "Got error creating StaticProvider")
 
-	obj := New(time.Hour, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.UseMock(), tlsConfig)
+	obj := New(time.Hour, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.NewMock(), tlsConfig)
 
 	_, resolver, err := obj.LookupA(context.Background(), "letsencrypt.org")
 	test.AssertEquals(t, resolver, "")
@@ -306,7 +306,7 @@ func TestDNSOneServer(t *testing.T) {
 	staticProvider, err := NewStaticProvider([]string{dnsLoopbackAddr})
 	test.AssertNotError(t, err, "Got error creating StaticProvider")
 
-	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.UseMock(), tlsConfig)
+	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.NewMock(), tlsConfig)
 
 	_, resolver, err := obj.LookupA(context.Background(), "letsencrypt.org")
 	test.AssertNotError(t, err, "No message")
@@ -317,7 +317,7 @@ func TestDNSDuplicateServers(t *testing.T) {
 	staticProvider, err := NewStaticProvider([]string{dnsLoopbackAddr, dnsLoopbackAddr})
 	test.AssertNotError(t, err, "Got error creating StaticProvider")
 
-	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.UseMock(), tlsConfig)
+	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.NewMock(), tlsConfig)
 
 	_, resolver, err := obj.LookupA(context.Background(), "letsencrypt.org")
 	test.AssertNotError(t, err, "No message")
@@ -328,7 +328,7 @@ func TestDNSServFail(t *testing.T) {
 	staticProvider, err := NewStaticProvider([]string{dnsLoopbackAddr})
 	test.AssertNotError(t, err, "Got error creating StaticProvider")
 
-	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.UseMock(), tlsConfig)
+	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.NewMock(), tlsConfig)
 	bad := "servfail.com"
 
 	_, _, err = obj.LookupTXT(context.Background(), "servfail.com")
@@ -348,7 +348,7 @@ func TestDNSLookupTXT(t *testing.T) {
 	staticProvider, err := NewStaticProvider([]string{dnsLoopbackAddr})
 	test.AssertNotError(t, err, "Got error creating StaticProvider")
 
-	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.UseMock(), tlsConfig)
+	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.NewMock(), tlsConfig)
 
 	_, _, err = obj.LookupTXT(context.Background(), "letsencrypt.org")
 	test.AssertNotError(t, err, "No message")
@@ -363,7 +363,7 @@ func TestDNSLookupA(t *testing.T) {
 	staticProvider, err := NewStaticProvider([]string{dnsLoopbackAddr})
 	test.AssertNotError(t, err, "Got error creating StaticProvider")
 
-	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.UseMock(), tlsConfig)
+	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.NewMock(), tlsConfig)
 
 	for _, tc := range []struct {
 		name      string
@@ -448,7 +448,7 @@ func TestDNSLookupAAAA(t *testing.T) {
 	staticProvider, err := NewStaticProvider([]string{dnsLoopbackAddr})
 	test.AssertNotError(t, err, "Got error creating StaticProvider")
 
-	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.UseMock(), tlsConfig)
+	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.NewMock(), tlsConfig)
 
 	for _, tc := range []struct {
 		name      string
@@ -533,7 +533,7 @@ func TestDNSNXDOMAIN(t *testing.T) {
 	staticProvider, err := NewStaticProvider([]string{dnsLoopbackAddr})
 	test.AssertNotError(t, err, "Got error creating StaticProvider")
 
-	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.UseMock(), tlsConfig)
+	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.NewMock(), tlsConfig)
 	hostname := "nxdomain.letsencrypt.org"
 
 	_, _, err = obj.LookupA(context.Background(), hostname)
@@ -551,7 +551,7 @@ func TestDNSLookupCAA(t *testing.T) {
 	staticProvider, err := NewStaticProvider([]string{dnsLoopbackAddr})
 	test.AssertNotError(t, err, "Got error creating StaticProvider")
 
-	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.UseMock(), tlsConfig)
+	obj := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 1, "", blog.NewMock(), tlsConfig)
 	removeIDExp := regexp.MustCompile(" id: [[:digit:]]+")
 
 	caas, resolver, err := obj.LookupCAA(context.Background(), "bracewel.net")
@@ -759,7 +759,7 @@ func TestRetry(t *testing.T) {
 			staticProvider, err := NewStaticProvider([]string{dnsLoopbackAddr})
 			test.AssertNotError(t, err, "Got error creating StaticProvider")
 
-			testClient := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), tc.maxTries, "", blog.UseMock(), tlsConfig)
+			testClient := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), tc.maxTries, "", blog.NewMock(), tlsConfig)
 			dr := testClient.(*impl)
 			dr.exchanger = tc.te
 			_, _, err = dr.LookupTXT(context.Background(), "example.com")
@@ -796,7 +796,7 @@ func TestRetryMetrics(t *testing.T) {
 	// context itself being cancelled. It should never see the error in the
 	// testExchanger, because the fake exchanger (like the real http package)
 	// checks for cancellation before doing any work.
-	testClient := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 3, "", blog.UseMock(), tlsConfig)
+	testClient := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 3, "", blog.NewMock(), tlsConfig)
 	dr := testClient.(*impl)
 	dr.exchanger = &testExchanger{errs: []error{errors.New("oops")}}
 	ctx, cancel := context.WithCancel(t.Context())
@@ -815,7 +815,7 @@ func TestRetryMetrics(t *testing.T) {
 
 	// Same as above, except rather than cancelling the context ourselves, we
 	// let the go runtime cancel it as a result of a deadline in the past.
-	testClient = New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 3, "", blog.UseMock(), tlsConfig)
+	testClient = New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 3, "", blog.NewMock(), tlsConfig)
 	dr = testClient.(*impl)
 	dr.exchanger = &testExchanger{errs: []error{errors.New("oops")}}
 	ctx, cancel = context.WithTimeout(t.Context(), -10*time.Hour)
@@ -883,7 +883,7 @@ func TestRotateServerOnErr(t *testing.T) {
 	test.AssertNotError(t, err, "Got error creating StaticProvider")
 
 	maxTries := 5
-	client := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), maxTries, "", blog.UseMock(), tlsConfig)
+	client := New(time.Second*10, staticProvider, metrics.NoopRegisterer, clock.NewFake(), maxTries, "", blog.NewMock(), tlsConfig)
 
 	// Configure a mock exchanger that will always return a retryable error for
 	// servers A and B. This will force server "[2606:4700:4700::1111]:53" to do
@@ -948,7 +948,7 @@ func TestDOHMetric(t *testing.T) {
 	staticProvider, err := NewStaticProvider([]string{dnsLoopbackAddr})
 	test.AssertNotError(t, err, "Got error creating StaticProvider")
 
-	testClient := New(time.Second*11, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 0, "", blog.UseMock(), tlsConfig)
+	testClient := New(time.Second*11, staticProvider, metrics.NoopRegisterer, clock.NewFake(), 0, "", blog.NewMock(), tlsConfig)
 	resolver := testClient.(*impl)
 	resolver.exchanger = &dohAlwaysRetryExchanger{err: &url.Error{Op: "read", Err: testTimeoutError(true)}}
 

blog/attr.go

@@ -0,0 +1,61 @@
+package blog
+
+// This file contains helper functions that can be used throughout the boulder
+// code base to ensure that certain commonly-logged values always have the same
+// key name and value type. This prevents situations like sometimes calling the
+// requesting account "requester" or "acct" or "regID"; or sometimes logging the
+// authz ID as an integer and sometimes as a string.
+//
+// Any time we find ourselves logging the same slog.Attr from 3+ files we
+// should consider adding a helper here instead.
+//
+// Note that several other attr keys are reserved and should not be used:
+//   - "time": used by the slog package
+//   - "level": used by the slog package
+//   - "msg": used by the slog package
+//   - "source": used by the slog package
+//   - "error": used by our blog.Error and blog.AuditError helpers
+//   - "audit": used by our blog.AuditError and blog.AuditInfo helpers
+
+import (
+	"log/slog"
+
+	"github.com/letsencrypt/boulder/identifier"
+)
+
+// Acct returns a slog.Attr whose key is "acct" and whose value is the unique
+// numeric ID of the account.
+func Acct(acctID int64) slog.Attr {
+	return slog.Int64("acct", acctID)
+}
+
+// Order returns a slog.Attr whose key is "order" and whose value is the unique
+// numeric ID of the order.
+func Order(orderID int64) slog.Attr {
+	return slog.Int64("order", orderID)
+}
+
+// Authz returns a slog.Attr whose key is "authz" and whose value is the unique
+// numeric ID of the authz.
+func Authz(authzID int64) slog.Attr {
+	return slog.Int64("authz", authzID)
+}
+
+// Serial returns a slog.Attr whose key is "serial" and whose value is the
+// given string. The argument should be hex-encoded.
+func Serial(serial string) slog.Attr {
+	return slog.String("serial", serial)
+}
+
+// Idents returns a slog.Attr whose key is "idents" and whose value is a list
+// of the given identifiers.
+func Idents(idents ...identifier.ACMEIdentifier) slog.Attr {
+	return slog.Any("idents", idents)
+}
+
+// Error returns a slog.Attr whose key is "error" and whose value is the value
+// from err.Error(). This attribute is used automatically by methods that log
+// at the error level, like blog.Logger.AuditError().
+func Error(err error) slog.Attr {
+	return slog.String("error", err.Error())
+}

blog/attr_test.go

@@ -0,0 +1,89 @@
+package blog
+
+import (
+	"errors"
+	"log/slog"
+	"net/netip"
+	"testing"
+
+	"github.com/letsencrypt/boulder/identifier"
+)
+
+func TestAttrHelpers(t *testing.T) {
+	t.Parallel()
+
+	testCases := []struct {
+		name    string
+		got     slog.Attr
+		wantKey string
+		wantVal slog.Value
+	}{
+		{
+			name:    "Acct",
+			got:     Acct(42),
+			wantKey: "acct",
+			wantVal: slog.Int64Value(42),
+		},
+		{
+			name:    "Order",
+			got:     Order(17),
+			wantKey: "order",
+			wantVal: slog.Int64Value(17),
+		},
+		{
+			name:    "Authz",
+			got:     Authz(99),
+			wantKey: "authz",
+			wantVal: slog.Int64Value(99),
+		},
+		{
+			name:    "Serial",
+			got:     Serial("deadbeef"),
+			wantKey: "serial",
+			wantVal: slog.StringValue("deadbeef"),
+		},
+		{
+			name:    "Error",
+			got:     Error(errors.New("boom")),
+			wantKey: "error",
+			wantVal: slog.StringValue("boom"),
+		},
+	}
+
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) {
+			t.Parallel()
+			if tc.got.Key != tc.wantKey {
+				t.Errorf("attr key = %q, want %q", tc.got.Key, tc.wantKey)
+			}
+			if !tc.got.Value.Equal(tc.wantVal) {
+				t.Errorf("attr value = %v, want %v", tc.got.Value, tc.wantVal)
+			}
+		})
+	}
+}
+
+func TestIdentsAttr(t *testing.T) {
+	t.Parallel()
+
+	// This test is separate from the above because the Idents helper accepts
+	// a variadic number of arguments.
+	attr := Idents(identifier.NewDNS("example.com"), identifier.NewIP(netip.MustParseAddr("12.34.56.78")))
+	if attr.Key != "idents" {
+		t.Errorf("attr key = %q, want %q", attr.Key, "idents")
+	}
+
+	idents, ok := attr.Value.Any().([]identifier.ACMEIdentifier)
+	if !ok {
+		t.Fatalf("idents attr value should be a slice of ACMEIdentifier, got %T", attr.Value.Any())
+	}
+	if len(idents) != 2 {
+		t.Fatalf("got %d idents, want 2", len(idents))
+	}
+	if idents[0].Value != "example.com" {
+		t.Errorf("idents[0].Value = %q, want %q", idents[0].Value, "example.com")
+	}
+	if idents[1].Value != "12.34.56.78" {
+		t.Errorf("idents[1].Value = %q, want %q", idents[1].Value, "12.34.56.78")
+	}
+}