diff --git a/grpc/interceptors.go b/grpc/interceptors.go index f97acefa732..fdedc72bbb4 100644 --- a/grpc/interceptors.go +++ b/grpc/interceptors.go @@ -26,6 +26,10 @@ const ( meaningfulWorkOverhead = 100 * time.Millisecond clientRequestTimeKey = "client-request-time" userAgentKey = "acme-client-user-agent" + // We use the "-bin" suffix to tell grpc's metadata package not to require the user-agent + // be printable ASCII. It's rare, but ACME clients can send non-ASCII user-agents. + // Remove `userAgentKey` once this has been deployed. + userAgentKey2 = "acme-client-user-agent-bin" ) type serverInterceptor interface { @@ -91,7 +95,9 @@ func (smi *serverMetadataInterceptor) Unary( return nil, err } } - if len(md[userAgentKey]) > 0 { + if len(md[userAgentKey2]) > 0 { + ctx = web.WithUserAgent(ctx, md[userAgentKey2][0]) + } else if len(md[userAgentKey]) > 0 { ctx = web.WithUserAgent(ctx, md[userAgentKey][0]) } } @@ -276,6 +282,7 @@ func (cmi *clientMetadataInterceptor) Unary( reqMD := metadata.New(map[string]string{ clientRequestTimeKey: nowTS, userAgentKey: web.UserAgent(ctx), + userAgentKey2: web.UserAgent(ctx), }) // Configure the localCtx with the metadata so it gets sent along in the request localCtx = metadata.NewOutgoingContext(localCtx, reqMD) @@ -384,6 +391,7 @@ func (cmi *clientMetadataInterceptor) Stream( reqMD := metadata.New(map[string]string{ clientRequestTimeKey: nowTS, userAgentKey: web.UserAgent(ctx), + userAgentKey2: 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/web/context.go b/web/context.go index 4172ea8c006..c3681be03ac 100644 --- a/web/context.go +++ b/web/context.go @@ -142,6 +142,10 @@ func (th *TopHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { } userAgent := r.Header.Get("User-Agent") + // If someone sends a very long User-Agent we're only interested in logging the beginning. + if len(userAgent) > 100 { + userAgent = userAgent[:100] + "..." + } logEvent := &RequestEvent{ RealIP: realIP, diff --git a/web/context_test.go b/web/context_test.go index ed98597cdc0..e14fe7c4a1f 100644 --- a/web/context_test.go +++ b/web/context_test.go @@ -4,9 +4,11 @@ import ( "bytes" "context" "crypto/tls" + "encoding/json" "fmt" "net/http" "net/http/httptest" + "regexp" "strings" "testing" "time" @@ -39,6 +41,40 @@ func TestLogCode(t *testing.T) { } } +// TestLogUA tests that user-agents are truncated before logging, and faithfully pass along non-ASCII. +func TestLogUA(t *testing.T) { + mockLog := blog.UseMock() + th := NewTopHandler(mockLog, myHandler{}) + req, err := http.NewRequest("GET", "/thisisignored", &bytes.Reader{}) + if err != nil { + t.Fatal(err) + } + req.Header.Add("User-Agent", "🪨"+strings.Repeat("a", 200)) + th.ServeHTTP(httptest.NewRecorder(), req) + + matching := mockLog.GetAllMatching("JSON=") + if len(matching) != 1 { + t.Errorf("Expected exactly one log line. Got: %s", + strings.Join(mockLog.GetAllMatching(".*"), "\n")) + } + re := regexp.MustCompile(`JSON=({.*})$`) + m := re.FindStringSubmatch(matching[0]) + if len(m) < 2 { + t.Fatalf("logging user-agent: no regexp match") + } + var ua struct { + UA string + } + err = json.Unmarshal([]byte(m[1]), &ua) + if err != nil { + t.Fatal(err) + } + expected := "🪨aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa..." + if ua.UA != expected { + t.Errorf("logging user-agent: got %x, want %x", ua.UA, expected) + } +} + type codeHandler struct{} func (ch codeHandler) ServeHTTP(e *RequestEvent, w http.ResponseWriter, r *http.Request) {