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 #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.