From 38dab3eeb23be6e2e6a41c5c44db213e665cc9a7 Mon Sep 17 00:00:00 2001 From: Jacob Hoffman-Andrews Date: Wed, 27 Nov 2024 13:51:12 -0800 Subject: [PATCH 1/2] ra: log user-agent --- grpc/interceptors.go | 26 +++++++++++++++++++------- ra/ra.go | 4 ++++ web/context.go | 24 +++++++++++++++++++++++- 3 files changed, 46 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/ra/ra.go b/ra/ra.go index 3c0f53e22a0..af7ce56060d 100644 --- a/ra/ra.go +++ b/ra/ra.go @@ -341,6 +341,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 @@ -967,6 +970,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 a748137a0aa..6c222e790e6 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 @@ -121,13 +137,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. From 48be26bc43fa7c4283d9decba51d2a1ba0201350 Mon Sep 17 00:00:00 2001 From: Jacob Hoffman-Andrews Date: Fri, 20 Dec 2024 13:57:15 -0800 Subject: [PATCH 2/2] grpc: add User-Agent test --- grpc/interceptors_test.go | 71 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 71 insertions(+) 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 +}