ra: log User-Agent (#7908)

In the WFE, store the User-Agent in a `context.Context` object. In our
gRPC interceptors, pass that field in a Metadata header, and re-add it
to `Context` on the server side.

Add a test in the gRPC interceptors that User-Agent is properly
propagated.

Note: this adds a new `setup()` function for the gRPC tests that is
currently only used by the new test. I'll upload another PR shortly that
expands the use of that function to more tests.

Fixes https://github.com/letsencrypt/boulder/issues/7792

grpc/interceptors.go

@@ -18,12 +18,14 @@ import (
 
 	"github.com/letsencrypt/boulder/cmd"
 	berrors "github.com/letsencrypt/boulder/errors"
+	"github.com/letsencrypt/boulder/web"
 )
 
 const (
 	returnOverhead         = 20 * time.Millisecond
 	meaningfulWorkOverhead = 100 * time.Millisecond
 	clientRequestTimeKey   = "client-request-time"
+	userAgentKey           = "acme-client-user-agent"
 )
 
 type serverInterceptor interface {
@@ -82,10 +84,15 @@ func (smi *serverMetadataInterceptor) Unary(
 	// timestamp embedded in it. It's okay if the timestamp is missing, since some
 	// clients (like nomad's health-checker) don't set it.
 	md, ok := metadata.FromIncomingContext(ctx)
-	if ok && len(md[clientRequestTimeKey]) > 0 {
-		err := smi.checkLatency(md[clientRequestTimeKey][0])
-		if err != nil {
-			return nil, err
+	if ok {
+		if len(md[clientRequestTimeKey]) > 0 {
+			err := smi.checkLatency(md[clientRequestTimeKey][0])
+			if err != nil {
+				return nil, err
+			}
+		}
+		if len(md[userAgentKey]) > 0 {
+			ctx = web.WithUserAgent(ctx, md[userAgentKey][0])
 		}
 	}
 
@@ -270,8 +277,10 @@ func (cmi *clientMetadataInterceptor) Unary(
 	// Convert the current unix nano timestamp to a string for embedding in the grpc metadata
 	nowTS := strconv.FormatInt(cmi.clk.Now().UnixNano(), 10)
 	// Create a grpc/metadata.Metadata instance for the request metadata.
-	// Initialize it with the request time.
-	reqMD := metadata.New(map[string]string{clientRequestTimeKey: nowTS})
+	reqMD := metadata.New(map[string]string{
+		clientRequestTimeKey: nowTS,
+		userAgentKey:         web.UserAgent(ctx),
+	})
 	// Configure the localCtx with the metadata so it gets sent along in the request
 	localCtx = metadata.NewOutgoingContext(localCtx, reqMD)
 
@@ -380,7 +389,10 @@ func (cmi *clientMetadataInterceptor) Stream(
 	nowTS := strconv.FormatInt(cmi.clk.Now().UnixNano(), 10)
 	// Create a grpc/metadata.Metadata instance for the request metadata.
 	// Initialize it with the request time.
-	reqMD := metadata.New(map[string]string{clientRequestTimeKey: nowTS})
+	reqMD := metadata.New(map[string]string{
+		clientRequestTimeKey: nowTS,
+		userAgentKey:         web.UserAgent(ctx),
+	})
 	// Configure the localCtx with the metadata so it gets sent along in the request
 	localCtx = metadata.NewOutgoingContext(localCtx, reqMD)
 

grpc/interceptors_test.go

@@ -28,6 +28,7 @@ import (
 	"github.com/letsencrypt/boulder/grpc/test_proto"
 	"github.com/letsencrypt/boulder/metrics"
 	"github.com/letsencrypt/boulder/test"
+	"github.com/letsencrypt/boulder/web"
 )
 
 var fc = clock.NewFake()
@@ -524,3 +525,73 @@ func TestServiceAuthChecker(t *testing.T) {
 	err = ac.checkContextAuth(ctx, "/package.ServiceName/Method/")
 	test.AssertNotError(t, err, "checking allowed cert")
 }
+
+// testUserAgentServer stores the last value it saw in the user agent field of its context.
+type testUserAgentServer struct {
+	test_proto.UnimplementedChillerServer
+
+	lastSeenUA string
+}
+
+// Chill implements ChillerServer.Chill
+func (s *testUserAgentServer) Chill(ctx context.Context, in *test_proto.Time) (*test_proto.Time, error) {
+	s.lastSeenUA = web.UserAgent(ctx)
+	return nil, nil
+}
+
+func TestUserAgentMetadata(t *testing.T) {
+	server := new(testUserAgentServer)
+	client, stop := setup(t, server)
+	defer stop()
+
+	testUA := "test UA"
+	ctx := web.WithUserAgent(context.Background(), testUA)
+
+	_, err := client.Chill(ctx, &test_proto.Time{})
+	if err != nil {
+		t.Fatalf("calling c.Chill: %s", err)
+	}
+
+	if server.lastSeenUA != testUA {
+		t.Errorf("last seen User-Agent on server side was %q, want %q", server.lastSeenUA, testUA)
+	}
+}
+
+func setup(t *testing.T, server test_proto.ChillerServer) (test_proto.ChillerClient, func()) {
+	clk := clock.NewFake()
+	serverMetricsVal, err := newServerMetrics(metrics.NoopRegisterer)
+	test.AssertNotError(t, err, "creating server metrics")
+	clientMetricsVal, err := newClientMetrics(metrics.NoopRegisterer)
+	test.AssertNotError(t, err, "creating client metrics")
+
+	lis, err := net.Listen("tcp", ":0")
+	if err != nil {
+		log.Fatalf("failed to listen: %v", err)
+	}
+	port := lis.Addr().(*net.TCPAddr).Port
+
+	si := newServerMetadataInterceptor(serverMetricsVal, clk)
+	s := grpc.NewServer(grpc.UnaryInterceptor(si.Unary))
+	test_proto.RegisterChillerServer(s, server)
+
+	go func() {
+		start := time.Now()
+		err := s.Serve(lis)
+		if err != nil && !strings.HasSuffix(err.Error(), "use of closed network connection") {
+			t.Logf("s.Serve: %v after %s", err, time.Since(start))
+		}
+	}()
+
+	ci := &clientMetadataInterceptor{
+		timeout: 30 * time.Second,
+		metrics: clientMetricsVal,
+		clk:     clock.NewFake(),
+	}
+	conn, err := grpc.Dial(net.JoinHostPort("localhost", strconv.Itoa(port)),
+		grpc.WithTransportCredentials(insecure.NewCredentials()),
+		grpc.WithUnaryInterceptor(ci.Unary))
+	if err != nil {
+		t.Fatalf("did not connect: %v", err)
+	}
+	return test_proto.NewChillerClient(conn), s.Stop
+}

ra/ra.go

@@ -324,6 +324,9 @@ type certificateRequestEvent struct {
 	// of FQDNs as a previous certificate (from any account) and contains the
 	// notBefore of the most recent such certificate.
 	PreviousCertificateIssued time.Time `json:",omitempty"`
+	// UserAgent is the User-Agent header from the ACME client (provided to the
+	// RA via gRPC metadata).
+	UserAgent string
 }
 
 // certificateRevocationEvent is a struct for holding information that is logged
@@ -847,6 +850,7 @@ func (ra *RegistrationAuthorityImpl) FinalizeOrder(ctx context.Context, req *rap
 		OrderID:     req.Order.Id,
 		Requester:   req.Order.RegistrationID,
 		RequestTime: ra.clk.Now(),
+		UserAgent:   web.UserAgent(ctx),
 	}
 	csr, err := ra.validateFinalizeRequest(ctx, req, &logEvent)
 	if err != nil {

web/context.go

@@ -16,6 +16,22 @@ import (
 	blog "github.com/letsencrypt/boulder/log"
 )
 
+type userAgentContextKey struct{}
+
+func UserAgent(ctx context.Context) string {
+	// The below type assertion is safe because this context key can only be
+	// set by this package and is only set to a string.
+	val, ok := ctx.Value(userAgentContextKey{}).(string)
+	if !ok {
+		return ""
+	}
+	return val
+}
+
+func WithUserAgent(ctx context.Context, ua string) context.Context {
+	return context.WithValue(ctx, userAgentContextKey{}, ua)
+}
+
 // RequestEvent is a structured record of the metadata we care about for a
 // single web request. It is generated when a request is received, passed to
 // the request handler which can populate its fields as appropriate, and then
@@ -126,13 +142,19 @@ func (th *TopHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		realIP = "0.0.0.0"
 	}
 
+	userAgent := r.Header.Get("User-Agent")
+
 	logEvent := &RequestEvent{
 		RealIP:    realIP,
 		Method:    r.Method,
-		UserAgent: r.Header.Get("User-Agent"),
+		UserAgent: userAgent,
 		Origin:    r.Header.Get("Origin"),
 		Extra:     make(map[string]interface{}),
 	}
+
+	ctx := WithUserAgent(r.Context(), userAgent)
+	r = r.WithContext(ctx)
+
 	if !features.Get().PropagateCancels {
 		// We specifically override the default r.Context() because we would prefer
 		// for clients to not be able to cancel our operations in arbitrary places.