From 04dec59c67747911b4188a0bbbbd6194c15ef8d6 Mon Sep 17 00:00:00 2001 From: Jacob Hoffman-Andrews Date: Tue, 14 Jan 2025 13:39:41 -0800 Subject: [PATCH] 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 | 26 ++++++++++---- grpc/interceptors_test.go | 71 +++++++++++++++++++++++++++++++++++++++ ra/ra.go | 4 +++ web/context.go | 24 ++++++++++++- 4 files changed, 117 insertions(+), 8 deletions(-) diff --git a/grpc/interceptors.go b/grpc/interceptors.go index ed69d87f0f2..83ad20ab69f 100644 --- a/grpc/interceptors.go +++ b/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) diff --git a/grpc/interceptors_test.go b/grpc/interceptors_test.go index 1b5415fedcd..4d992c2c73f 100644 --- a/grpc/interceptors_test.go +++ b/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 +} diff --git a/ra/ra.go b/ra/ra.go index afdf1b3b018..2c3c8bab941 100644 --- a/ra/ra.go +++ b/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 { diff --git a/web/context.go b/web/context.go index 36cd28bbf29..6f32a5c28b9 100644 --- a/web/context.go +++ b/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.