Skip to content
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 8 additions & 2 deletions bdns/dns.go

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do not resolve this comment until given approval by SRE -- this comment blocks merging until resolved.

Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ import (
"errors"
"fmt"
"io"
"log/slog"
"net"
"net/http"
"strconv"
Expand All @@ -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"
)

Expand Down Expand Up @@ -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.
Expand Down
30 changes: 15 additions & 15 deletions bdns/dns_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
)
Expand Down Expand Up @@ -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, "")
Expand All @@ -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")
Expand All @@ -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")
Expand All @@ -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")
Expand All @@ -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")
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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)
Expand All @@ -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")
Expand Down Expand Up @@ -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")
Expand Down Expand Up @@ -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())
Expand All @@ -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)
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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)}}

Expand Down
61 changes: 61 additions & 0 deletions blog/attr.go
Original file line number Diff line number Diff line change
@@ -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())
}
89 changes: 89 additions & 0 deletions blog/attr_test.go
Original file line number Diff line number Diff line change
@@ -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")
}
}
Loading