From 7f9c3e171c2114b377bb9df5c90d4ad12ec9ba57 Mon Sep 17 00:00:00 2001 From: Julien Neuhart Date: Thu, 21 May 2026 18:30:06 +0200 Subject: [PATCH] fix(chromium): downgrade pinning-proxy logs for client-cancelled requests --- pkg/modules/chromium/pinning_proxy.go | 30 ++- pkg/modules/chromium/pinning_proxy_test.go | 242 +++++++++++++++++++++ 2 files changed, 270 insertions(+), 2 deletions(-) diff --git a/pkg/modules/chromium/pinning_proxy.go b/pkg/modules/chromium/pinning_proxy.go index 6e7ad9c7..6e116c02 100644 --- a/pkg/modules/chromium/pinning_proxy.go +++ b/pkg/modules/chromium/pinning_proxy.go @@ -179,7 +179,11 @@ func (p *pinningProxy) handleConnect(w http.ResponseWriter, req *http.Request) { // the CONNECT handling beyond filtering. decision, err := p.decide(req.Context(), "https://"+req.Host, p.allowList, p.denyList, deadline) if err != nil { - p.logger.WarnContext(req.Context(), fmt.Sprintf("CONNECT blocked for '%s': %s", req.Host, err)) + if isClientCancellation(req.Context(), err) { + p.logger.DebugContext(req.Context(), fmt.Sprintf("CONNECT abandoned by client for '%s': %s", req.Host, err)) + } else { + p.logger.WarnContext(req.Context(), fmt.Sprintf("CONNECT blocked for '%s': %s", req.Host, err)) + } http.Error(w, "CONNECT blocked", http.StatusForbidden) return } @@ -254,7 +258,11 @@ func (p *pinningProxy) handleForward(w http.ResponseWriter, req *http.Request) { decision, err := p.decide(req.Context(), req.URL.String(), p.allowList, p.denyList, deadline) if err != nil { - p.logger.WarnContext(req.Context(), fmt.Sprintf("forward blocked for '%s': %s", req.URL, err)) + if isClientCancellation(req.Context(), err) { + p.logger.DebugContext(req.Context(), fmt.Sprintf("forward abandoned by client for '%s': %s", req.URL, err)) + } else { + p.logger.WarnContext(req.Context(), fmt.Sprintf("forward blocked for '%s': %s", req.URL, err)) + } http.Error(w, "request blocked", http.StatusForbidden) return } @@ -326,3 +334,21 @@ func copyHeaders(dst, src http.Header) { } } } + +// isClientCancellation reports whether err originates from the client (for +// example Chromium) closing the connection or letting the request deadline +// pass before the proxy could finish validating the destination. Such +// errors are not policy refusals: the proxy never reached an allow/deny +// rule decision. Callers downgrade these to debug to avoid alarming +// operators with noise from speculative or aborted browser requests. The +// canonical case is a Chromium DNS prefetch that the browser drops before +// the proxy's [outbound.resolveHost] call returns. The [net.DNSError] +// returned by [net.Resolver.LookupNetIP] unwraps to [context.Canceled] or +// [context.DeadlineExceeded] in that case, so an [errors.Is] walk catches +// it. +func isClientCancellation(ctx context.Context, err error) bool { + if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) { + return true + } + return ctx.Err() != nil +} diff --git a/pkg/modules/chromium/pinning_proxy_test.go b/pkg/modules/chromium/pinning_proxy_test.go index 2b60f618..914f61a1 100644 --- a/pkg/modules/chromium/pinning_proxy_test.go +++ b/pkg/modules/chromium/pinning_proxy_test.go @@ -13,6 +13,7 @@ import ( "net/netip" "net/url" "strings" + "sync" "sync/atomic" "testing" "time" @@ -22,6 +23,33 @@ import ( "github.com/gotenberg/gotenberg/v8/pkg/gotenberg" ) +// recordingHandler is a slog.Handler that captures every record emitted +// through it so tests can assert on the level and message of proxy logs. +type recordingHandler struct { + mu sync.Mutex + records []slog.Record +} + +func (h *recordingHandler) Enabled(_ context.Context, _ slog.Level) bool { return true } + +func (h *recordingHandler) Handle(_ context.Context, r slog.Record) error { + h.mu.Lock() + defer h.mu.Unlock() + h.records = append(h.records, r.Clone()) + return nil +} + +func (h *recordingHandler) WithAttrs(_ []slog.Attr) slog.Handler { return h } +func (h *recordingHandler) WithGroup(_ string) slog.Handler { return h } + +func (h *recordingHandler) snapshot() []slog.Record { + h.mu.Lock() + defer h.mu.Unlock() + out := make([]slog.Record, len(h.records)) + copy(out, h.records) + return out +} + func testLogger() *slog.Logger { return slog.New(slog.NewTextHandler(io.Discard, nil)) } @@ -452,6 +480,220 @@ func TestPinningProxy_DNSRebind_SingleResolution(t *testing.T) { } } +// TestPinningProxy_CONNECT_ClientCancellation_LoggedAtDebug verifies that +// when decide fails because the request context was canceled or its +// deadline expired (the canonical case is Chromium dropping a speculative +// CONNECT before the proxy finishes resolving the host), the proxy logs +// at debug and not at warn. Policy refusals must still warn; see +// [TestPinningProxy_CONNECT_BlockedByDecide]. +func TestPinningProxy_CONNECT_ClientCancellation_LoggedAtDebug(t *testing.T) { + rec := &recordingHandler{} + p := newPinningProxy(nil, nil, false, false) + p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { + // Mimic the wrap chain produced by outbound.resolveHost when the + // DNS lookup is canceled mid-flight by Chromium hanging up. + return gotenberg.OutboundDecision{}, fmt.Errorf("validate '%s' host: resolve %q: lookup %s: %w", "https://www.google.com:443", "www.google.com", "www.google.com", context.Canceled) + } + + err := p.Start(slog.New(rec)) + if err != nil { + t.Fatalf("start pinning proxy: %v", err) + } + t.Cleanup(func() { _ = p.Stop(slog.New(rec)) }) + proxyURL := p.URL() + + conn, err := net.Dial("tcp", strings.TrimPrefix(proxyURL, "http://")) + if err != nil { + t.Fatalf("dial proxy: %v", err) + } + defer conn.Close() + _ = conn.SetDeadline(time.Now().Add(5 * time.Second)) + + _, err = fmt.Fprintf(conn, "CONNECT www.google.com:443 HTTP/1.1\r\nHost: www.google.com:443\r\n\r\n") + if err != nil { + t.Fatalf("write CONNECT: %v", err) + } + resp, err := http.ReadResponse(bufio.NewReader(conn), nil) + if err != nil { + t.Fatalf("read response: %v", err) + } + defer resp.Body.Close() + if resp.StatusCode != http.StatusForbidden { + t.Fatalf("status = %d, want 403", resp.StatusCode) + } + + records := rec.snapshot() + var found bool + for _, r := range records { + if !strings.Contains(r.Message, "www.google.com:443") { + continue + } + found = true + if r.Level != slog.LevelDebug { + t.Fatalf("record level = %v, want Debug; message: %s", r.Level, r.Message) + } + if !strings.Contains(r.Message, "abandoned") { + t.Fatalf("message = %q, want it to mention abandoned", r.Message) + } + } + if !found { + t.Fatal("expected a log record mentioning www.google.com:443, found none") + } +} + +// TestPinningProxy_Forward_ClientCancellation_LoggedAtDebug is the +// handleForward equivalent of +// [TestPinningProxy_CONNECT_ClientCancellation_LoggedAtDebug]. Plain +// HTTP forward requests aborted by the client must also log at debug. +func TestPinningProxy_Forward_ClientCancellation_LoggedAtDebug(t *testing.T) { + rec := &recordingHandler{} + p := newPinningProxy(nil, nil, false, false) + p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { + return gotenberg.OutboundDecision{}, fmt.Errorf("validate host: %w", context.DeadlineExceeded) + } + + err := p.Start(slog.New(rec)) + if err != nil { + t.Fatalf("start pinning proxy: %v", err) + } + t.Cleanup(func() { _ = p.Stop(slog.New(rec)) }) + proxyURL := p.URL() + + client := &http.Client{ + Transport: &http.Transport{Proxy: http.ProxyURL(mustParseURL(t, proxyURL))}, + Timeout: 5 * time.Second, + } + resp, err := client.Get("http://www.google.com/") + if err != nil { + t.Fatalf("GET via proxy: %v", err) + } + defer resp.Body.Close() + if resp.StatusCode != http.StatusForbidden { + t.Fatalf("status = %d, want 403", resp.StatusCode) + } + + records := rec.snapshot() + var found bool + for _, r := range records { + if !strings.Contains(r.Message, "www.google.com") { + continue + } + found = true + if r.Level != slog.LevelDebug { + t.Fatalf("record level = %v, want Debug; message: %s", r.Level, r.Message) + } + if !strings.Contains(r.Message, "abandoned") { + t.Fatalf("message = %q, want it to mention abandoned", r.Message) + } + } + if !found { + t.Fatal("expected a log record mentioning www.google.com, found none") + } +} + +// TestPinningProxy_PolicyDenial_LoggedAtWarn protects the existing +// behavior: a deny-list match (or any non-cancellation decide error) must +// still surface at warn level so operators see real refusals. +func TestPinningProxy_PolicyDenial_LoggedAtWarn(t *testing.T) { + rec := &recordingHandler{} + p := newPinningProxy(nil, nil, false, false) + p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { + return gotenberg.OutboundDecision{}, fmt.Errorf("denied: %w", gotenberg.ErrFiltered) + } + + err := p.Start(slog.New(rec)) + if err != nil { + t.Fatalf("start pinning proxy: %v", err) + } + t.Cleanup(func() { _ = p.Stop(slog.New(rec)) }) + proxyURL := p.URL() + + conn, err := net.Dial("tcp", strings.TrimPrefix(proxyURL, "http://")) + if err != nil { + t.Fatalf("dial proxy: %v", err) + } + defer conn.Close() + _ = conn.SetDeadline(time.Now().Add(5 * time.Second)) + + _, err = fmt.Fprintf(conn, "CONNECT denied.example:443 HTTP/1.1\r\nHost: denied.example:443\r\n\r\n") + if err != nil { + t.Fatalf("write CONNECT: %v", err) + } + resp, err := http.ReadResponse(bufio.NewReader(conn), nil) + if err != nil { + t.Fatalf("read response: %v", err) + } + defer resp.Body.Close() + + records := rec.snapshot() + var found bool + for _, r := range records { + if !strings.Contains(r.Message, "denied.example") { + continue + } + found = true + if r.Level != slog.LevelWarn { + t.Fatalf("record level = %v, want Warn; message: %s", r.Level, r.Message) + } + if !strings.Contains(r.Message, "blocked") { + t.Fatalf("message = %q, want it to mention blocked", r.Message) + } + } + if !found { + t.Fatal("expected a log record mentioning denied.example, found none") + } +} + +func TestIsClientCancellation(t *testing.T) { + canceledCtx, cancel := context.WithCancel(context.Background()) + cancel() + + for _, tc := range []struct { + name string + ctx context.Context + err error + want bool + }{ + { + name: "wrapped context.Canceled", + ctx: context.Background(), + err: fmt.Errorf("validate host: %w", context.Canceled), + want: true, + }, + { + name: "wrapped context.DeadlineExceeded", + ctx: context.Background(), + err: fmt.Errorf("validate host: %w", context.DeadlineExceeded), + want: true, + }, + { + name: "request context already done", + ctx: canceledCtx, + err: errors.New("some unrelated error"), + want: true, + }, + { + name: "policy denial", + ctx: context.Background(), + err: fmt.Errorf("denied: %w", gotenberg.ErrFiltered), + want: false, + }, + { + name: "plain dial failure", + ctx: context.Background(), + err: errors.New("connection refused"), + want: false, + }, + } { + t.Run(tc.name, func(t *testing.T) { + got := isClientCancellation(tc.ctx, tc.err) + if got != tc.want { + t.Fatalf("isClientCancellation = %v, want %v", got, tc.want) + } + }) + } +} + func TestPinningProxy_StartTwice(t *testing.T) { p := newPinningProxy(nil, nil, false, false) err := p.Start(testLogger())