Replace log package with fully slog-based system (#8606)

Replace our //log package with a new //blog package, based on the go
stdlib's slog (structured logging) library. This makes all of our log
lines uniformly json (or structured text in test envs), for ease of
parsing by systems like clickhouse.

The new package has a very similar API to the old one: new loggers are
built by cmd/shell.go and stored on our various "impl" structs. When we
want to log a line, we call a method with the desired log level. In
fact, the new logger type (blog.Logger) has the same name as the old
one, so most struct definitions and constructor arguments don't even
need to be updated.

The changes come in both how we use the logger, and what its output
looks like.

The most obvious change is that all logging calls now take a context as
their first argument. The blog package provides utilities to store
key-value pairs (slog.Attr) on a context, and the blog.Logger will
extract those attributes from the context and include them in the log
output. This makes it very easy to ensure that all log lines after a
certain point (e.g. after the request has been parsed and we've
identified the user and order in question) include relevant identify
details (e.g. the regID and orderID).

More subtly, we no longer ever log fmt.Sprintf-formatted strings or
large "auditEvent" structs. Instead, all of those fields are either
attached to the context (if relevant to multiple potential log lines) or
included as slog.Attrs in the log call itself. This removes the need for
our old log.Info / log.Infof / log.InfoObject variants: everything is
plain messages and attributes.

As before, all log messages include the log level, the current time, the
program being run, the hostname the program is running on, and several
other universally-relevant details. However, these are now presented as
key-value pairs like any other attribute, rather than as unkeyed tags at
the beginning of the message.

All logs are written as either text (for tests) or json (for production
code), tagged with the `[AUDIT]` tag, and checksummed. This means that
our existing log routing and validation should continue to work
unchanged.

> [!NOTE]
> Notes for reviewers:
> - This is a very large PR. I suggest reviewing it one commit at a time
to keep things reasonable. Each commit in the stack is logically scoped
to a single subdirectory for ease of reviewing. However, don't expect
code to compile or tests to pass at intermediate points in the commit
stack, if you check it out locally.
> - This change removes the stdout/stderr split and level-based
coloration from our non-syslog output. We've decided this is explicitly
desirable for prod, and at least temporarily acceptable for integration
tests.
> - Sometimes we log in-memory structures, like identifiers or
validation records. In the JSON output, this works great: they get
serialized to json. In the text output, this works less great: they get
pushed through `fmt.Sprint("%v")`, which is somewhat readable but rarely
optimal. I'm not aware of any good workarounds for this.
> - One drawback of collecting attributes on the context is that it's
not always obvious to the code reader (or writer) which attributes have
already been added to the context, and therefore don't need to be added
again. In writing this PR, several times I had log output like `acct=123
acct=123` because I'd added the same attribute twice in two different
places. I'm not sure if this is a problem worth solving, or if it is,
what the best approach might be.

> [!WARNING]
> **Open question**: As mentioned above, these logs include universal
information like the program name and hostname. Because syslog adds
similar tags of its own, this may mean that syslog-based production logs
have redundant information in them. Are these attributes useful? Should
we just remove them?

Future work that we may want to do, but is not included in this change:
- gRPC server interceptors to attach the service and method name as
attributes to all incoming contexts
- gRPC client/server interceptors to propagate certain well-known (e.g.
acct, serial) attributes across the gRPC boundary
- restore coloration (or even weirder formatting) to integration test
log output, for ease of local debugging

Fixes #8557

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")
+	}
+}