package chromium import ( "bufio" "context" "errors" "fmt" "io" "log/slog" "net" "net/http" "net/http/httptest" "net/netip" "net/url" "strings" "sync" "sync/atomic" "testing" "time" "github.com/dlclark/regexp2" "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)) } func mustParseURL(t *testing.T, raw string) *url.URL { t.Helper() u, err := url.Parse(raw) if err != nil { t.Fatalf("parse %q: %v", raw, err) } return u } // newRawTCPServer starts a TCP server on 127.0.0.1:0 that calls handle for // every accepted connection. It returns the listener address and a cleanup // function. func newRawTCPServer(t *testing.T, handle func(net.Conn)) (string, func()) { t.Helper() l, err := net.Listen("tcp", "127.0.0.1:0") if err != nil { t.Fatalf("listen: %v", err) } go func() { for { conn, err := l.Accept() if err != nil { return } go handle(conn) } }() return l.Addr().String(), func() { _ = l.Close() } } // newProxyForTest returns a pinning proxy whose decide and dial functions // are set to test stubs. The proxy is started on a loopback ephemeral // port and stopped during test cleanup. func newProxyForTest(t *testing.T, p *pinningProxy) string { t.Helper() err := p.Start(testLogger()) if err != nil { t.Fatalf("start pinning proxy: %v", err) } t.Cleanup(func() { _ = p.Stop(testLogger()) }) return p.URL() } func TestPinningProxy_Forward_Pinned_Success(t *testing.T) { upstream := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { if r.Host != "example.com" { t.Errorf("upstream expected Host=example.com, got %q", r.Host) } _, _ = fmt.Fprint(w, "hello-from-upstream") })) t.Cleanup(upstream.Close) upstreamURL := mustParseURL(t, upstream.URL) var decideCalls atomic.Int32 p := newPinningProxy(nil, nil, false, false, false) p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { decideCalls.Add(1) return gotenberg.OutboundDecision{Pinned: []netip.Addr{netip.MustParseAddr("127.0.0.1")}}, nil } p.dialPinned = func(ctx context.Context, network string, _ []netip.Addr, _ string) (net.Conn, error) { return net.Dial(network, upstreamURL.Host) } proxyURL := newProxyForTest(t, p) client := &http.Client{ Transport: &http.Transport{ Proxy: http.ProxyURL(mustParseURL(t, proxyURL)), }, Timeout: 5 * time.Second, } resp, err := client.Get("http://example.com/") if err != nil { t.Fatalf("GET via proxy: %v", err) } defer resp.Body.Close() body, err := io.ReadAll(resp.Body) if err != nil { t.Fatalf("read body: %v", err) } if resp.StatusCode != http.StatusOK { t.Fatalf("status = %d, want 200", resp.StatusCode) } if string(body) != "hello-from-upstream" { t.Fatalf("body = %q, want %q", body, "hello-from-upstream") } if got := decideCalls.Load(); got != 1 { t.Fatalf("decide called %d times, want 1", got) } } func TestPinningProxy_Forward_BlockedByDecide(t *testing.T) { p := newPinningProxy(nil, nil, false, false, false) p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { return gotenberg.OutboundDecision{}, fmt.Errorf("nope: %w", gotenberg.ErrFiltered) } p.dialPinned = func(_ context.Context, _ string, _ []netip.Addr, _ string) (net.Conn, error) { t.Fatal("dialPinned must not be called when decide returns an error") return nil, errors.New("unreachable") } proxyURL := newProxyForTest(t, p) client := &http.Client{ Transport: &http.Transport{ Proxy: http.ProxyURL(mustParseURL(t, proxyURL)), }, Timeout: 5 * time.Second, } resp, err := client.Get("http://blocked.example/") 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) } } func TestPinningProxy_Forward_Bypass(t *testing.T) { upstream := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { _, _ = fmt.Fprint(w, "bypassed") })) t.Cleanup(upstream.Close) upstreamURL := mustParseURL(t, upstream.URL) var bypassCalls atomic.Int32 p := newPinningProxy(nil, nil, false, false, false) p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { return gotenberg.OutboundDecision{Bypass: true}, nil } p.dialBypass = func(_ context.Context, network, _ string) (net.Conn, error) { bypassCalls.Add(1) return net.Dial(network, upstreamURL.Host) } p.dialPinned = func(_ context.Context, _ string, _ []netip.Addr, _ string) (net.Conn, error) { t.Fatal("dialPinned must not be called on bypass") return nil, errors.New("unreachable") } proxyURL := newProxyForTest(t, p) client := &http.Client{ Transport: &http.Transport{ Proxy: http.ProxyURL(mustParseURL(t, proxyURL)), }, Timeout: 5 * time.Second, } resp, err := client.Get("http://internal.example/") if err != nil { t.Fatalf("GET via proxy: %v", err) } defer resp.Body.Close() if resp.StatusCode != http.StatusOK { t.Fatalf("status = %d, want 200", resp.StatusCode) } if got := bypassCalls.Load(); got != 1 { t.Fatalf("dialBypass called %d times, want 1", got) } } func TestPinningProxy_Forward_StripsHopByHopHeaders(t *testing.T) { var upstreamSawProxyAuth bool upstream := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { if r.Header.Get("Proxy-Authorization") != "" { upstreamSawProxyAuth = true } w.Header().Set("Connection", "close") w.Header().Set("Proxy-Connection", "close") w.Header().Set("X-Downstream", "ok") w.WriteHeader(http.StatusOK) })) t.Cleanup(upstream.Close) upstreamURL := mustParseURL(t, upstream.URL) p := newPinningProxy(nil, nil, false, false, false) p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { return gotenberg.OutboundDecision{Pinned: []netip.Addr{netip.MustParseAddr("127.0.0.1")}}, nil } p.dialPinned = func(ctx context.Context, network string, _ []netip.Addr, _ string) (net.Conn, error) { return net.Dial(network, upstreamURL.Host) } proxyURL := newProxyForTest(t, p) req, err := http.NewRequest(http.MethodGet, "http://example.com/", nil) if err != nil { t.Fatalf("new request: %v", err) } req.Header.Set("Proxy-Authorization", "Basic Zm9vOmJhcg==") client := &http.Client{ Transport: &http.Transport{ Proxy: http.ProxyURL(mustParseURL(t, proxyURL)), }, Timeout: 5 * time.Second, } resp, err := client.Do(req) if err != nil { t.Fatalf("GET via proxy: %v", err) } defer resp.Body.Close() if upstreamSawProxyAuth { t.Fatalf("upstream received Proxy-Authorization, proxy did not strip it") } if resp.Header.Get("Proxy-Connection") != "" { t.Fatalf("response retained Proxy-Connection, proxy did not strip it") } if resp.Header.Get("X-Downstream") != "ok" { t.Fatalf("response missing X-Downstream header") } } func TestPinningProxy_Forward_RejectsNonAbsoluteURL(t *testing.T) { p := newPinningProxy(nil, nil, false, false, false) p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { t.Fatal("decide must not be called for malformed proxy request") return gotenberg.OutboundDecision{}, nil } proxyURL := newProxyForTest(t, p) conn, err := net.Dial("tcp", strings.TrimPrefix(proxyURL, "http://")) if err != nil { t.Fatalf("dial proxy: %v", err) } defer conn.Close() // Send a request with a path-only target, not an absolute URI, which // the proxy should reject with 400. _, err = fmt.Fprint(conn, "GET /path HTTP/1.1\r\nHost: example.com\r\n\r\n") if err != nil { t.Fatalf("write request: %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.StatusBadRequest { t.Fatalf("status = %d, want 400", resp.StatusCode) } } func TestPinningProxy_CONNECT_Pinned_Success(t *testing.T) { upstreamAddr, stop := newRawTCPServer(t, func(c net.Conn) { defer c.Close() _, _ = c.Write([]byte("HI")) buf := make([]byte, 4) n, _ := io.ReadFull(c, buf) _, _ = c.Write(buf[:n]) }) t.Cleanup(stop) var decideCalls atomic.Int32 p := newPinningProxy(nil, nil, false, false, false) p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { decideCalls.Add(1) return gotenberg.OutboundDecision{Pinned: []netip.Addr{netip.MustParseAddr("127.0.0.1")}}, nil } p.dialPinned = func(_ context.Context, network string, _ []netip.Addr, _ string) (net.Conn, error) { return net.Dial(network, upstreamAddr) } proxyURL := newProxyForTest(t, p) // Connect to the proxy, send CONNECT, splice raw bytes. 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 example.com:443 HTTP/1.1\r\nHost: example.com:443\r\n\r\n") if err != nil { t.Fatalf("write CONNECT: %v", err) } br := bufio.NewReader(conn) statusLine, err := br.ReadString('\n') if err != nil { t.Fatalf("read status: %v", err) } if !strings.Contains(statusLine, " 200 ") { t.Fatalf("CONNECT status = %q, want 200", statusLine) } // Consume the blank line after headers. for { line, err := br.ReadString('\n') if err != nil { t.Fatalf("read headers: %v", err) } if line == "\r\n" || line == "\n" { break } } hi := make([]byte, 2) _, err = io.ReadFull(br, hi) if err != nil { t.Fatalf("read greeting: %v", err) } if string(hi) != "HI" { t.Fatalf("greeting = %q, want HI", hi) } _, err = conn.Write([]byte("PONG")) if err != nil { t.Fatalf("write PONG: %v", err) } echo := make([]byte, 4) _, err = io.ReadFull(br, echo) if err != nil { t.Fatalf("read echo: %v", err) } if string(echo) != "PONG" { t.Fatalf("echo = %q, want PONG", echo) } if got := decideCalls.Load(); got != 1 { t.Fatalf("decide called %d times, want 1", got) } } func TestPinningProxy_CONNECT_BlockedByDecide(t *testing.T) { p := newPinningProxy(nil, nil, false, false, false) p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { return gotenberg.OutboundDecision{}, fmt.Errorf("nope: %w", gotenberg.ErrFiltered) } p.dialPinned = func(_ context.Context, _ string, _ []netip.Addr, _ string) (net.Conn, error) { t.Fatal("dialPinned must not be called when decide returns an error") return nil, errors.New("unreachable") } proxyURL := newProxyForTest(t, p) 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 rebind.example:443 HTTP/1.1\r\nHost: rebind.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() if resp.StatusCode != http.StatusForbidden { t.Fatalf("CONNECT status = %d, want 403", resp.StatusCode) } } // TestPinningProxy_DNSRebind_SingleResolution is the regression test for // the DNS rebinding window. It simulates a DNS authority that returns a // public IP on the first lookup and a loopback IP on subsequent lookups. // The proxy must resolve the host exactly once per request and dial the // IP validated at that moment, so that a second resolution by any later // layer cannot pivot the connection to an internal target. func TestPinningProxy_DNSRebind_SingleResolution(t *testing.T) { upstream := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { _, _ = fmt.Fprint(w, "public-upstream") })) t.Cleanup(upstream.Close) upstreamURL := mustParseURL(t, upstream.URL) var lookupCount atomic.Int32 stubDecide := func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { n := lookupCount.Add(1) if n == 1 { // First lookup: returns a public IP, validation passes, the // proxy pins it for the dial. return gotenberg.OutboundDecision{Pinned: []netip.Addr{netip.MustParseAddr("93.184.216.34")}}, nil } // Any subsequent lookup for the same host would return a // loopback IP. This return value must not influence the dial // because the proxy must not call decide again for this request. return gotenberg.OutboundDecision{}, fmt.Errorf("rebind lookup: %w", gotenberg.ErrFiltered) } p := newPinningProxy(nil, nil, false, false, false) p.decide = stubDecide p.dialPinned = func(_ context.Context, network string, addrs []netip.Addr, _ string) (net.Conn, error) { if len(addrs) != 1 || addrs[0].String() != "93.184.216.34" { t.Errorf("dialPinned got addrs %v, want [93.184.216.34]", addrs) } return net.Dial(network, upstreamURL.Host) } proxyURL := newProxyForTest(t, p) client := &http.Client{ Transport: &http.Transport{ Proxy: http.ProxyURL(mustParseURL(t, proxyURL)), }, Timeout: 5 * time.Second, } resp, err := client.Get("http://rebind.example/") if err != nil { t.Fatalf("GET via proxy: %v", err) } defer resp.Body.Close() body, _ := io.ReadAll(resp.Body) if resp.StatusCode != http.StatusOK { t.Fatalf("status = %d, want 200", resp.StatusCode) } if string(body) != "public-upstream" { t.Fatalf("body = %q, want %q", body, "public-upstream") } if got := lookupCount.Load(); got != 1 { t.Fatalf("decide called %d times, want exactly 1 (rebind protection)", got) } } // 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, 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, 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, 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") } } // TestPinningProxy_CONNECT_DialCancellation_LoggedAtDebug verifies that // when the upstream dial fails because the request context was canceled // (typically Chromium dropping a speculative CONNECT before a slow IPv6 // dial completes), the proxy logs at debug rather than warn. Genuine // dial failures must still warn; see // [TestPinningProxy_CONNECT_DialFailure_LoggedAtWarn]. func TestPinningProxy_CONNECT_DialCancellation_LoggedAtDebug(t *testing.T) { rec := &recordingHandler{} p := newPinningProxy(nil, nil, false, false, false) p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { return gotenberg.OutboundDecision{Pinned: []netip.Addr{netip.MustParseAddr("127.0.0.1")}}, nil } p.dialPinned = func(_ context.Context, _ string, _ []netip.Addr, _ string) (net.Conn, error) { // Mimic a dial canceled mid-flight by the client hanging up, // which is what net.Dialer returns when ctx.Err() is Canceled. return nil, fmt.Errorf("dial tcp [2001:4860:482b:7700::]:443: %w", 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.StatusBadGateway { t.Fatalf("status = %d, want 502", resp.StatusCode) } records := rec.snapshot() var found bool for _, r := range records { if !strings.Contains(r.Message, "CONNECT dial") || !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 CONNECT dial for www.google.com:443, found none") } } // TestPinningProxy_CONNECT_DialFailure_LoggedAtWarn guards the existing // behavior: a genuine dial failure (host unreachable, refused, etc.) // must still warn so operators see real problems. func TestPinningProxy_CONNECT_DialFailure_LoggedAtWarn(t *testing.T) { rec := &recordingHandler{} p := newPinningProxy(nil, nil, false, false, false) p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { return gotenberg.OutboundDecision{Pinned: []netip.Addr{netip.MustParseAddr("127.0.0.1")}}, nil } p.dialPinned = func(_ context.Context, _ string, _ []netip.Addr, _ string) (net.Conn, error) { return nil, errors.New("connection refused") } 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 real.example:443 HTTP/1.1\r\nHost: real.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, "CONNECT dial") || !strings.Contains(r.Message, "real.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, "failed") { t.Fatalf("message = %q, want it to mention failed", r.Message) } } if !found { t.Fatal("expected a log record mentioning CONNECT dial for real.example, found none") } } // TestPinningProxy_Forward_RoundTripCancellation_LoggedAtDebug verifies // the handleForward dial-cancellation path: when the inner Transport's // dial returns a canceled error (client hung up mid-dial), the proxy // logs at debug, not warn. Genuine RoundTrip failures still warn. func TestPinningProxy_Forward_RoundTripCancellation_LoggedAtDebug(t *testing.T) { rec := &recordingHandler{} p := newPinningProxy(nil, nil, false, false, false) p.decide = func(_ context.Context, _ string, _, _ []*regexp2.Regexp, _ time.Time) (gotenberg.OutboundDecision, error) { return gotenberg.OutboundDecision{Pinned: []netip.Addr{netip.MustParseAddr("127.0.0.1")}}, nil } p.dialPinned = func(_ context.Context, _ string, _ []netip.Addr, _ string) (net.Conn, error) { return nil, fmt.Errorf("dial tcp [2001:4860::]:80: %w", 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() 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.StatusBadGateway { t.Fatalf("status = %d, want 502", resp.StatusCode) } records := rec.snapshot() var found bool for _, r := range records { if !strings.Contains(r.Message, "forward RoundTrip") || !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 forward RoundTrip for www.google.com, 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, false) err := p.Start(testLogger()) if err != nil { t.Fatalf("first Start: %v", err) } t.Cleanup(func() { _ = p.Stop(testLogger()) }) err = p.Start(testLogger()) if err == nil { t.Fatal("second Start: expected error, got nil") } } func TestPinningProxy_StopIdempotent(t *testing.T) { p := newPinningProxy(nil, nil, false, false, false) // Stop on a never-started proxy is a no-op. if err := p.Stop(testLogger()); err != nil { t.Fatalf("Stop on never-started proxy: %v", err) } if err := p.Start(testLogger()); err != nil { t.Fatalf("Start: %v", err) } if err := p.Stop(testLogger()); err != nil { t.Fatalf("first Stop: %v", err) } if err := p.Stop(testLogger()); err != nil { t.Fatalf("second Stop on stopped proxy: %v", err) } }