web: user-agent can be non-ASCII (#8723)

We send the user-agent header through grpc as metadata. grpc-go by
default validates metadata values as printable ASCII. We can override
that assumption by naming our header with "-bin".

For a transition period, send and accept both header names. After
deploy, we'll remove the old one.

Also, trim the User-Agent to a max size before logging, and add a
unittest for the max size.

Author: jsha

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)

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,

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) {