From 77ce1b4ce1e598583a762dbdf347364b7798444d Mon Sep 17 00:00:00 2001
From: Josef Strzibny <strzibny@strzibny.name>
Date: Fri, 9 Oct 2026 13:40:54 +0200
Subject: [PATCH 1/7] Add --debug option

---
 README.md             |  16 +++++
 pkg/api/client.go     |  16 ++++-
 pkg/api/debug.go      | 154 ++++++++++++++++++++++++++++++++++++++++++
 pkg/api/debug_test.go |  88 ++++++++++++++++++++++++
 pkg/cmd/root.go       |  34 +++++++++-
 pkg/cmd/root_test.go  |  31 +++++++++
 6 files changed, 335 insertions(+), 4 deletions(-)
 create mode 100644 pkg/api/debug.go
 create mode 100644 pkg/api/debug_test.go

diff --git a/README.md b/README.md
index 9bf506c..8079cbb 100644
--- a/README.md
+++ b/README.md
@@ -119,6 +119,22 @@ Prints the CLI version, as `--version` does.
   # Or set it once for the shell session
   export SERPAPI_TIMEOUT=120
   ```
+- `--debug`: trace each request on stderr (env `SERPAPI_DEBUG=1`): DNS, TCP connect, TLS handshake, time to first byte, response status and headers (including `Serpapi-Search-Id` and `X-Request-Id`), and body size, so you can see whether time went to connecting, waiting for SerpApi to answer, or downloading the body. Each line carries a UTC timestamp and the seconds elapsed since the request started, to correlate with `search_metadata.created_at` and `processed_at`; the API key is redacted; stdout is untouched, so `--jq` and piping still work.
+  ```bash
+  serpapi search --debug engine=google_ai_mode q="..." > result.json
+  ```
+  ```
+  [debug] 2026-10-09T11:01:53.569Z + 0.000s GET https://serpapi.com/search.json?api_key=[REDACTED]&engine=google&q=coffee
+  [debug] 2026-10-09T11:01:53.569Z + 0.000s Timeout: 60s
+  [debug] 2026-10-09T11:01:53.597Z + 0.028s DNS resolved: 162.159.142.21, 172.66.2.17
+  [debug] 2026-10-09T11:01:53.611Z + 0.042s Connected: tcp 162.159.142.21:443
+  [debug] 2026-10-09T11:01:53.643Z + 0.074s TLS handshake done: TLS 1.3, ALPN="h2"
+  [debug] 2026-10-09T11:01:53.644Z + 0.075s Request sent, waiting for response headers
+  [debug] 2026-10-09T11:01:54.421Z + 0.852s First response byte received
+  [debug] 2026-10-09T11:01:54.421Z + 0.852s Response: HTTP/2.0 200 OK
+  [debug] 2026-10-09T11:01:54.421Z + 0.852s   Serpapi-Search-Id: 6ac8c9a14a616bad61f13c29
+  [debug] 2026-10-09T11:01:54.422Z + 0.853s Body received: 57483 bytes
+  ```
 
 ## Configuration
 
diff --git a/pkg/api/client.go b/pkg/api/client.go
index 0245e1d..75a181d 100644
--- a/pkg/api/client.go
+++ b/pkg/api/client.go
@@ -9,6 +9,7 @@ import (
 	"io"
 	"net"
 	"net/http"
+	"net/http/httptrace"
 	"net/url"
 	"strconv"
 	"strings"
@@ -36,6 +37,9 @@ type Client struct {
 	apiKey  string
 	baseURL string
 	http    *http.Client
+
+	// debug, if set, receives a trace of each request; see WithDebug.
+	debug io.Writer
 }
 
 // Option configures a Client.
@@ -93,22 +97,32 @@ func (c *Client) get(ctx context.Context, endpoint string, params map[string]str
 	}
 	u.RawQuery = q.Encode()
 
+	tr := c.newTracer()
+	if tr != nil {
+		ctx = httptrace.WithClientTrace(ctx, tr.clientTrace())
+	}
+
 	req, err := http.NewRequestWithContext(ctx, http.MethodGet, u.String(), nil)
 	if err != nil {
 		return nil, &clierrors.NetworkError{Message: "Invalid request: " + endpoint, Cause: err}
 	}
 	req.Header.Set("User-Agent", userAgent())
+	tr.logRequest(req, c.http.Timeout)
 
 	resp, err := c.http.Do(req)
 	if err != nil {
+		tr.logf("Request failed: %v", err)
 		return nil, c.networkError(endpoint, err)
 	}
 	defer resp.Body.Close()
+	tr.logResponse(resp)
 
 	body, err := io.ReadAll(io.LimitReader(resp.Body, int64(maxResponseBytes)+1))
 	if err != nil {
+		tr.logf("Read body failed: %v", err)
 		return nil, c.networkError(endpoint, err)
 	}
+	tr.logf("Body received: %d bytes", len(body))
 
 	if resp.StatusCode != http.StatusOK {
 		message := fmt.Sprintf("HTTP %d: %s", resp.StatusCode, http.StatusText(resp.StatusCode))
@@ -134,7 +148,7 @@ func (c *Client) networkError(endpoint string, err error) error {
 	if c.http.Timeout > 0 && (errors.Is(err, context.DeadlineExceeded) || (errors.As(err, &netErr) && netErr.Timeout())) {
 		return &clierrors.NetworkError{
 			Message: fmt.Sprintf("Request to %s timed out after %s. Slow engines, such as google_ai_mode, and no_cache=true can take longer: "+
-				"retry with a higher --timeout, such as --timeout %d, or 0 to wait indefinitely. "+
+				"retry with a higher --timeout, such as --timeout %d, or 0 to wait indefinitely, or run with --debug to see where time was spent. "+
 				"The search may still finish on SerpApi's side, count against your searches and be available in your search archive",
 				endpoint, seconds(c.http.Timeout), suggestedTimeout(c.http.Timeout)),
 			Cause: cause,
diff --git a/pkg/api/debug.go b/pkg/api/debug.go
new file mode 100644
index 0000000..9373763
--- /dev/null
+++ b/pkg/api/debug.go
@@ -0,0 +1,154 @@
+package api
+
+import (
+	"crypto/tls"
+	"fmt"
+	"io"
+	"net/http"
+	"net/http/httptrace"
+	"sort"
+	"strings"
+	"sync"
+	"time"
+
+	clierrors "github.com/serpapi/serpapi-cli/pkg/errors"
+)
+
+// WithDebug traces each request to w: DNS, connect, TLS, first byte, status
+// and headers. Passing a nil w disables it.
+func WithDebug(w io.Writer) Option {
+	return func(c *Client) {
+		c.debug = w
+	}
+}
+
+// tracer writes timestamped request-lifecycle events. A nil *tracer is a
+// valid no-op so call sites don't need to guard on whether debug is enabled.
+type tracer struct {
+	w     io.Writer
+	start time.Time
+	mu    sync.Mutex
+}
+
+func (c *Client) newTracer() *tracer {
+	if c.debug == nil {
+		return nil
+	}
+	return &tracer{w: c.debug, start: time.Now()}
+}
+
+// logf writes one line: wall-clock UTC time (to correlate with server-side
+// created_at/processed_at), elapsed since the request started, and the
+// message with any api_key value redacted.
+func (t *tracer) logf(format string, args ...any) {
+	if t == nil {
+		return
+	}
+	now := time.Now()
+	msg := clierrors.RedactAPIKey(fmt.Sprintf(format, args...))
+	t.mu.Lock()
+	defer t.mu.Unlock()
+	fmt.Fprintf(t.w, "[debug] %s +%6.3fs %s\n",
+		now.UTC().Format("2006-01-02T15:04:05.000Z"), now.Sub(t.start).Seconds(), msg)
+}
+
+// clientTrace returns httptrace hooks that report each connection phase.
+// DNS/connect hooks are not fired for connections made via an HTTP proxy;
+// GotConn still is, which is why the proxy is logged separately in get.
+func (t *tracer) clientTrace() *httptrace.ClientTrace {
+	if t == nil {
+		return nil
+	}
+	return &httptrace.ClientTrace{
+		DNSStart: func(info httptrace.DNSStartInfo) {
+			t.logf("DNS lookup: %s", info.Host)
+		},
+		DNSDone: func(info httptrace.DNSDoneInfo) {
+			if info.Err != nil {
+				t.logf("DNS failed: %v", info.Err)
+				return
+			}
+			addrs := make([]string, 0, len(info.Addrs))
+			for _, a := range info.Addrs {
+				addrs = append(addrs, a.String())
+			}
+			t.logf("DNS resolved: %s", strings.Join(addrs, ", "))
+		},
+		ConnectStart: func(network, addr string) {
+			t.logf("Connecting: %s %s", network, addr)
+		},
+		ConnectDone: func(network, addr string, err error) {
+			if err != nil {
+				t.logf("Connect failed: %s %s: %v", network, addr, err)
+				return
+			}
+			t.logf("Connected: %s %s", network, addr)
+		},
+		TLSHandshakeStart: func() {
+			t.logf("TLS handshake started")
+		},
+		TLSHandshakeDone: func(state tls.ConnectionState, err error) {
+			if err != nil {
+				t.logf("TLS handshake failed: %v", err)
+				return
+			}
+			t.logf("TLS handshake done: %s, ALPN=%q", tls.VersionName(state.Version), state.NegotiatedProtocol)
+		},
+		GotConn: func(info httptrace.GotConnInfo) {
+			remote := "unknown"
+			if info.Conn != nil && info.Conn.RemoteAddr() != nil {
+				remote = info.Conn.RemoteAddr().String()
+			}
+			if info.Reused {
+				t.logf("Using connection: %s (reused, idle %s)", remote, info.IdleTime.Round(time.Millisecond))
+				return
+			}
+			t.logf("Using connection: %s (new)", remote)
+		},
+		WroteRequest: func(info httptrace.WroteRequestInfo) {
+			if info.Err != nil {
+				t.logf("Write request failed: %v", info.Err)
+				return
+			}
+			t.logf("Request sent, waiting for response headers")
+		},
+		GotFirstResponseByte: func() {
+			t.logf("First response byte received")
+		},
+	}
+}
+
+// logRequest reports what is about to be sent.
+func (t *tracer) logRequest(req *http.Request, timeout time.Duration) {
+	if t == nil {
+		return
+	}
+	t.logf("GET %s", req.URL.String())
+	t.logf("User-Agent: %s", req.UserAgent())
+	if timeout > 0 {
+		t.logf("Timeout: %gs", timeout.Seconds())
+	} else {
+		t.logf("Timeout: disabled")
+	}
+	if proxyURL, err := http.ProxyFromEnvironment(req); err == nil && proxyURL != nil {
+		t.logf("Proxy: %s", proxyURL.Redacted())
+	}
+}
+
+// logResponse reports the status line and headers in a stable order.
+func (t *tracer) logResponse(resp *http.Response) {
+	if t == nil || resp == nil {
+		return
+	}
+	t.logf("Response: %s %s", resp.Proto, resp.Status)
+	names := make([]string, 0, len(resp.Header))
+	for name := range resp.Header {
+		names = append(names, name)
+	}
+	sort.Strings(names)
+	for _, name := range names {
+		for _, value := range resp.Header[name] {
+			t.logf("  %s: %s", name, value)
+		}
+	}
+}
diff --git a/pkg/api/debug_test.go b/pkg/api/debug_test.go
new file mode 100644
index 0000000..2e3b105
--- /dev/null
+++ b/pkg/api/debug_test.go
@@ -0,0 +1,88 @@
+package api
+
+import (
+	"bytes"
+	"context"
+	"net/http"
+	"strings"
+	"testing"
+	"time"
+)
+
+func newDebugServer(t *testing.T, w *bytes.Buffer) *Client {
+	t.Helper()
+	srv := newTestServer(t, func(rw http.ResponseWriter, r *http.Request) {
+		rw.Header().Set("Content-Type", "application/json")
+		rw.Header().Set("Serpapi-Search-Id", "abc123")
+		_, _ = rw.Write([]byte(`{"ok":true}`))
+	})
+	return New("secret_key", WithBaseURL(srv.URL), WithTimeout(5*time.Second), WithDebug(w))
+}
+
+func TestDebugDisabledByDefault(t *testing.T) {
+	var buf bytes.Buffer
+	client := newDebugServer(t, &buf)
+	WithDebug(nil)(client)
+
+	if _, err := client.Search(context.Background(), map[string]string{"q": "x"}); err != nil {
+		t.Fatalf("unexpected error: %v", err)
+	}
+	if buf.Len() != 0 {
+		t.Fatalf("expected no debug output, got:\n%s", buf.String())
+	}
+}
+
+func TestDebugTraceCoversRequestLifecycle(t *testing.T) {
+	var buf bytes.Buffer
+	client := newDebugServer(t, &buf)
+
+	if _, err := client.Search(context.Background(), map[string]string{"q": "x"}); err != nil {
+		t.Fatalf("unexpected error: %v", err)
+	}
+	out := buf.String()
+
+	for _, want := range []string{
+		"GET http",
+		"Timeout: 5s",
+		"Connecting:",
+		"Connected:",
+		"Using connection:",
+		"Request sent, waiting for response headers",
+		"First response byte received",
+		"Response: HTTP/1.1 200 OK",
+		"Serpapi-Search-Id: abc123",
+		"Body received: 11 bytes",
+	} {
+		if !strings.Contains(out, want) {
+			t.Errorf("debug output missing %q:\n%s", want, out)
+		}
+	}
+	if strings.Contains(out, "secret_key") || !strings.Contains(out, "api_key=[REDACTED]") {
+		t.Errorf("debug output must redact the API key:\n%s", out)
+	}
+	for _, line := range strings.Split(strings.TrimSpace(out), "\n") {
+		if !strings.HasPrefix(line, "[debug] ") {
+			t.Errorf("every debug line should be prefixed, got %q", line)
+		}
+	}
+}
+
+func TestDebugTraceReportsTimeout(t *testing.T) {
+	var buf bytes.Buffer
+	client := newSlowServer(t, 5*time.Second, 50*time.Millisecond)
+	WithDebug(&buf)(client)
+
+	if _, err := client.Search(context.Background(), map[string]string{"q": "x"}); err == nil {
+		t.Fatal("expected timeout error")
+	}
+	out := buf.String()
+	if !strings.Contains(out, "Request sent, waiting for response headers") {
+		t.Errorf("expected trace to show request was sent before the stall:\n%s", out)
+	}
+	if !strings.Contains(out, "Request failed:") || !strings.Contains(out, "Timeout exceeded") {
+		t.Errorf("expected trace to report the failure:\n%s", out)
+	}
+	if strings.Contains(out, "First response byte received") {
+		t.Errorf("no response byte should have arrived:\n%s", out)
+	}
+}
diff --git a/pkg/cmd/root.go b/pkg/cmd/root.go
index c3e980b..d726aad 100644
--- a/pkg/cmd/root.go
+++ b/pkg/cmd/root.go
@@ -33,11 +33,16 @@ var (
 	fieldsFlag  string
 	jqFlag      string
 	timeoutFlag string
+	debugFlag   bool
 
 	// requestTimeout is --timeout, else SERPAPI_TIMEOUT, as validateGlobalFlags
 	// resolved it for this run.
 	requestTimeout = api.DefaultTimeout
 
+	// debugRequests is --debug, else SERPAPI_DEBUG, as validateGlobalFlags
+	// resolved it for this run.
+	debugRequests bool
+
 	// clientOptions are applied to every client after the defaults; tests use
 	// it to point the CLI at a local server.
 	clientOptions []api.Option
@@ -233,6 +238,8 @@ func init() {
 	pf.StringVar(&timeoutFlag, "timeout", "", fmt.Sprintf(
 		"HTTP request timeout in seconds, such as 120, or a duration, such as 2m; 0 waits indefinitely (default %d; env SERPAPI_TIMEOUT)",
 		int(api.DefaultTimeout/time.Second)))
+	pf.BoolVar(&debugFlag, "debug", false,
+		"trace each request on stderr: DNS, connect, TLS, first byte and headers (env SERPAPI_DEBUG=1)")
 
 	rootCmd.PersistentPreRunE = validateGlobalFlags
 
@@ -275,6 +282,7 @@ func validateGlobalFlags(cmd *cobra.Command, _ []string) error {
 		return err
 	}
 	requestTimeout = timeout
+	debugRequests = resolveDebug()
 	if fieldsFlag != "" && cmd != searchCmd {
 		return &clierrors.UsageError{Message: "--fields works only with search; use --jq to filter " + cmd.Name() + " output"}
 	}
@@ -322,6 +330,19 @@ func parseTimeout(raw, source string) (time.Duration, error) {
 	return d, nil
 }
 
+// resolveDebug returns --debug, else whether SERPAPI_DEBUG is set to anything
+// but an off value (empty, 0, false, no, off).
+func resolveDebug() bool {
+	if debugFlag {
+		return true
+	}
+	switch strings.ToLower(strings.TrimSpace(os.Getenv("SERPAPI_DEBUG"))) {
+	case "", "0", "false", "no", "off":
+		return false
+	}
+	return true
+}
+
 // resolveAPIKey returns the first non-empty key from --api-key, the
 // environment, then the config file.
 func resolveAPIKey() (string, error) {
@@ -337,13 +358,20 @@ func resolveAPIKey() (string, error) {
 }
 
 func newClient(apiKey string) *api.Client {
-	opts := append([]api.Option{api.WithTimeout(requestTimeout)}, clientOptions...)
-	return api.New(apiKey, opts...)
+	opts := []api.Option{api.WithTimeout(requestTimeout)}
+	if debugRequests {
+		opts = append(opts, api.WithDebug(rootCmd.ErrOrStderr()))
+	}
+	return api.New(apiKey, append(opts, clientOptions...)...)
 }
 
 // withSpinner shows a spinner on an interactive stderr while fn runs and
-// clears it before the caller prints anything.
+// clears it before the caller prints anything. In debug mode the trace
+// replaces it, so its redraws don't interleave with the trace lines.
 func withSpinner[T any](label string, fn func() (T, error)) (T, error) {
+	if debugRequests {
+		return fn()
+	}
 	sp := spinner.New(label)
 	sp.Start()
 	defer sp.Stop()
diff --git a/pkg/cmd/root_test.go b/pkg/cmd/root_test.go
index 471af0a..2492042 100644
--- a/pkg/cmd/root_test.go
+++ b/pkg/cmd/root_test.go
@@ -9,6 +9,37 @@ import (
 	clierrors "github.com/serpapi/serpapi-cli/pkg/errors"
 )
 
+func TestResolveDebug(t *testing.T) {
+	tests := []struct {
+		name string
+		flag bool
+		env  string
+		want bool
+	}{
+		{name: "default off"},
+		{name: "flag on", flag: true, want: true},
+		{name: "env 1", env: "1", want: true},
+		{name: "env true", env: "true", want: true},
+		{name: "env 0", env: "0"},
+		{name: "env false", env: "FALSE"},
+		{name: "env off", env: "off"},
+		{name: "env blank", env: "  "},
+		{name: "flag wins over env 0", flag: true, env: "0", want: true},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			debugFlag = tt.flag
+			t.Cleanup(func() { debugFlag = false })
+			t.Setenv("SERPAPI_DEBUG", tt.env)
+
+			if got := resolveDebug(); got != tt.want {
+				t.Errorf("expected %v, got %v", tt.want, got)
+			}
+		})
+	}
+}
+
 func TestResolveTimeout(t *testing.T) {
 	tests := []struct {
 		name    string

From 906d9685d1a69d08c9dbba74cf8f8542b945c51e Mon Sep 17 00:00:00 2001
From: Josef Strzibny <strzibny@strzibny.name>
Date: Fri, 9 Oct 2026 14:01:07 +0200
Subject: [PATCH 2/7] Add server timeline and local address to debug output

---
 README.md             |  25 ++++----
 pkg/api/client.go     |  27 +++++++--
 pkg/api/debug.go      |  98 ++++++++++++++++++++++++++++--
 pkg/api/debug_test.go | 134 ++++++++++++++++++++++++++++++++++++++++++
 pkg/cmd/root.go       |   2 +-
 5 files changed, 264 insertions(+), 22 deletions(-)

diff --git a/README.md b/README.md
index 8079cbb..67b107f 100644
--- a/README.md
+++ b/README.md
@@ -119,22 +119,25 @@ Prints the CLI version, as `--version` does.
   # Or set it once for the shell session
   export SERPAPI_TIMEOUT=120
   ```
-- `--debug`: trace each request on stderr (env `SERPAPI_DEBUG=1`): DNS, TCP connect, TLS handshake, time to first byte, response status and headers (including `Serpapi-Search-Id` and `X-Request-Id`), and body size, so you can see whether time went to connecting, waiting for SerpApi to answer, or downloading the body. Each line carries a UTC timestamp and the seconds elapsed since the request started, to correlate with `search_metadata.created_at` and `processed_at`; the API key is redacted; stdout is untouched, so `--jq` and piping still work.
+- `--debug`: trace each request on stderr (env `SERPAPI_DEBUG=1`): DNS, TCP connect (local and remote address), TLS handshake, time to first byte, response status and headers (including `Serpapi-Search-Id` and `X-Request-Id`), body size, and, for searches, the server's `search_metadata` timeline correlated with the client's, so you can see whether a long wait happened before SerpApi created the search (network path, proxy, queueing), during processing (slow engine), or after processing finished. Each line carries a UTC timestamp and the seconds elapsed since the request started; the API key is redacted; stdout is untouched, so `--jq` and piping still work.
   ```bash
   serpapi search --debug engine=google_ai_mode q="..." > result.json
   ```
   ```
-  [debug] 2026-10-09T11:01:53.569Z + 0.000s GET https://serpapi.com/search.json?api_key=[REDACTED]&engine=google&q=coffee
-  [debug] 2026-10-09T11:01:53.569Z + 0.000s Timeout: 60s
-  [debug] 2026-10-09T11:01:53.597Z + 0.028s DNS resolved: 162.159.142.21, 172.66.2.17
-  [debug] 2026-10-09T11:01:53.611Z + 0.042s Connected: tcp 162.159.142.21:443
-  [debug] 2026-10-09T11:01:53.643Z + 0.074s TLS handshake done: TLS 1.3, ALPN="h2"
-  [debug] 2026-10-09T11:01:53.644Z + 0.075s Request sent, waiting for response headers
-  [debug] 2026-10-09T11:01:54.421Z + 0.852s First response byte received
-  [debug] 2026-10-09T11:01:54.421Z + 0.852s Response: HTTP/2.0 200 OK
-  [debug] 2026-10-09T11:01:54.421Z + 0.852s   Serpapi-Search-Id: 6ac8c9a14a616bad61f13c29
-  [debug] 2026-10-09T11:01:54.422Z + 0.853s Body received: 57483 bytes
+  [debug] 2026-10-09T11:50:54.272Z + 0.000s GET https://serpapi.com/search.json?api_key=[REDACTED]&engine=google&q=coffee
+  [debug] 2026-10-09T11:50:54.272Z + 0.000s Timeout: 60s
+  [debug] 2026-10-09T11:50:54.300Z + 0.028s DNS resolved: 162.159.142.21, 172.66.2.17
+  [debug] 2026-10-09T11:50:54.346Z + 0.074s TLS handshake done: TLS 1.3, ALPN="h2"
+  [debug] 2026-10-09T11:50:54.413Z + 0.141s Using connection: 192.168.1.20:62494 -> 162.159.142.21:443 (new)
+  [debug] 2026-10-09T11:50:54.414Z + 0.142s Request sent, waiting for response headers
+  [debug] 2026-10-09T11:50:55.227Z + 0.955s First response byte received
+  [debug] 2026-10-09T11:50:55.227Z + 0.955s Response: HTTP/2.0 200 OK
+  [debug] 2026-10-09T11:50:55.227Z + 0.955s   Serpapi-Search-Id: 6ac8d51eaf5fdcac5434ae91
+  [debug] 2026-10-09T11:50:55.234Z + 0.962s Body received: 57483 bytes
+  [debug] 2026-10-09T11:50:55.234Z + 0.962s Server search: id=6ac8d51eaf5fdcac5434ae91 status=Success total_time_taken=0.5s
+  [debug] 2026-10-09T11:50:55.234Z + 0.962s Server timeline: created_at=11:50:54Z (+0.0s after request sent), processed_at=11:50:54Z (+0.0s processing), headers received +1.2s after processed_at
   ```
+  Server timestamps have one-second resolution, so sub-second deltas in the `Server timeline` line are noise. When the client waited noticeably longer than `total_time_taken`, a `Note:` line points at the phase that dominated.
 
 ## Configuration
 
diff --git a/pkg/api/client.go b/pkg/api/client.go
index 75a181d..4be6e0c 100644
--- a/pkg/api/client.go
+++ b/pkg/api/client.go
@@ -86,6 +86,12 @@ func userAgent() string {
 
 // get performs a GET request and returns the body of a 200 response verbatim.
 func (c *Client) get(ctx context.Context, endpoint string, params map[string]string) ([]byte, error) {
+	return c.getTraced(ctx, endpoint, params, c.newTracer())
+}
+
+// getTraced is get with a caller-supplied tracer, so Search can keep logging
+// against the same timeline after the body is read.
+func (c *Client) getTraced(ctx context.Context, endpoint string, params map[string]string, tr *tracer) ([]byte, error) {
 	u, err := url.Parse(c.baseURL + endpoint)
 	if err != nil {
 		return nil, &clierrors.NetworkError{Message: "Invalid URL: " + err.Error(), Cause: err}
@@ -97,7 +103,6 @@ func (c *Client) get(ctx context.Context, endpoint string, params map[string]str
 	}
 	u.RawQuery = q.Encode()
 
-	tr := c.newTracer()
 	if tr != nil {
 		ctx = httptrace.WithClientTrace(ctx, tr.clientTrace())
 	}
@@ -191,7 +196,11 @@ func errorMessage(body []byte) string {
 }
 
 func (c *Client) getJSON(ctx context.Context, endpoint string, params map[string]string) (json.RawMessage, error) {
-	body, err := c.get(ctx, endpoint, params)
+	return c.getJSONTraced(ctx, endpoint, params, c.newTracer())
+}
+
+func (c *Client) getJSONTraced(ctx context.Context, endpoint string, params map[string]string, tr *tracer) (json.RawMessage, error) {
+	body, err := c.getTraced(ctx, endpoint, params, tr)
 	if err != nil {
 		return nil, err
 	}
@@ -217,13 +226,23 @@ func (c *Client) searchParams(params map[string]string) map[string]string {
 
 // Search performs a search request. If the client has an API key it is added to params.
 func (c *Client) Search(ctx context.Context, params map[string]string) (json.RawMessage, error) {
-	return c.getObject(ctx, "/search.json", c.searchParams(params))
+	tr := c.newTracer()
+	body, err := c.getObjectTraced(ctx, "/search.json", c.searchParams(params), tr)
+	if err != nil {
+		return nil, err
+	}
+	tr.logSearchMetadata(body)
+	return body, nil
 }
 
 // getObject is getJSON for endpoints that answer with a JSON object, so a
 // stray null or array is an error rather than an empty-looking success.
 func (c *Client) getObject(ctx context.Context, endpoint string, params map[string]string) (json.RawMessage, error) {
-	body, err := c.getJSON(ctx, endpoint, params)
+	return c.getObjectTraced(ctx, endpoint, params, c.newTracer())
+}
+
+func (c *Client) getObjectTraced(ctx context.Context, endpoint string, params map[string]string, tr *tracer) (json.RawMessage, error) {
+	body, err := c.getJSONTraced(ctx, endpoint, params, tr)
 	if err != nil {
 		return nil, err
 	}
diff --git a/pkg/api/debug.go b/pkg/api/debug.go
index 9373763..2758128 100644
--- a/pkg/api/debug.go
+++ b/pkg/api/debug.go
@@ -2,6 +2,7 @@ package api
 
 import (
 	"crypto/tls"
+	"encoding/json"
 	"fmt"
 	"io"
 	"net/http"
@@ -15,7 +16,7 @@ import (
 )
 
 // WithDebug traces each request to w: DNS, connect, TLS, first byte, status
-// and headers. Passing a nil w disables it.
+// and headers, and the search_metadata timeline. Passing a nil w disables it.
 func WithDebug(w io.Writer) Option {
 	return func(c *Client) {
 		c.debug = w
@@ -28,6 +29,11 @@ type tracer struct {
 	w     io.Writer
 	start time.Time
 	mu    sync.Mutex
+
+	// Captured so the server-side search_metadata timestamps can be
+	// correlated with the client-side timeline afterwards.
+	sentAt      time.Time
+	firstByteAt time.Time
 }
 
 func (c *Client) newTracer() *tracer {
@@ -95,24 +101,35 @@ func (t *tracer) clientTrace() *httptrace.ClientTrace {
 			t.logf("TLS handshake done: %s, ALPN=%q", tls.VersionName(state.Version), state.NegotiatedProtocol)
 		},
 		GotConn: func(info httptrace.GotConnInfo) {
-			remote := "unknown"
-			if info.Conn != nil && info.Conn.RemoteAddr() != nil {
-				remote = info.Conn.RemoteAddr().String()
+			local, remote := "unknown", "unknown"
+			if info.Conn != nil {
+				if a := info.Conn.LocalAddr(); a != nil {
+					local = a.String()
+				}
+				if a := info.Conn.RemoteAddr(); a != nil {
+					remote = a.String()
+				}
 			}
 			if info.Reused {
-				t.logf("Using connection: %s (reused, idle %s)", remote, info.IdleTime.Round(time.Millisecond))
+				t.logf("Using connection: %s -> %s (reused, idle %s)", local, remote, info.IdleTime.Round(time.Millisecond))
 				return
 			}
-			t.logf("Using connection: %s (new)", remote)
+			t.logf("Using connection: %s -> %s (new)", local, remote)
 		},
 		WroteRequest: func(info httptrace.WroteRequestInfo) {
 			if info.Err != nil {
 				t.logf("Write request failed: %v", info.Err)
 				return
 			}
+			t.mu.Lock()
+			t.sentAt = time.Now()
+			t.mu.Unlock()
 			t.logf("Request sent, waiting for response headers")
 		},
 		GotFirstResponseByte: func() {
+			t.mu.Lock()
+			t.firstByteAt = time.Now()
+			t.mu.Unlock()
 			t.logf("First response byte received")
 		},
 	}
@@ -152,3 +169,72 @@ func (t *tracer) logResponse(resp *http.Response) {
 		}
 	}
 }
+
+// searchMetadataTimeLayout matches search_metadata.created_at / processed_at,
+// e.g. "2026-10-09 11:01:54 UTC". Second resolution only.
+const searchMetadataTimeLayout = "2006-01-02 15:04:05 MST"
+
+// logSearchMetadata correlates the server-side search_metadata timestamps
+// with the client-side timeline so a stall can be attributed to one of:
+//   - before the server created the search (network, edge, queueing)
+//   - server processing (created_at -> processed_at)
+//   - after processing finished but before headers were sent
+//
+// Server timestamps have 1s resolution, so sub-second deltas are noise.
+func (t *tracer) logSearchMetadata(body []byte) {
+	if t == nil {
+		return
+	}
+	var envelope struct {
+		Metadata struct {
+			ID             string  `json:"id"`
+			Status         string  `json:"status"`
+			CreatedAt      string  `json:"created_at"`
+			ProcessedAt    string  `json:"processed_at"`
+			TotalTimeTaken float64 `json:"total_time_taken"`
+		} `json:"search_metadata"`
+	}
+	if json.Unmarshal(body, &envelope) != nil || envelope.Metadata.ID == "" {
+		return
+	}
+	m := envelope.Metadata
+
+	t.mu.Lock()
+	sentAt, firstByteAt := t.sentAt, t.firstByteAt
+	t.mu.Unlock()
+
+	t.logf("Server search: id=%s status=%s total_time_taken=%gs", m.ID, m.Status, m.TotalTimeTaken)
+
+	createdAt, err1 := time.Parse(searchMetadataTimeLayout, m.CreatedAt)
+	processedAt, err2 := time.Parse(searchMetadataTimeLayout, m.ProcessedAt)
+	if err1 != nil || err2 != nil || sentAt.IsZero() || firstByteAt.IsZero() {
+		t.logf("Server timeline: created_at=%q processed_at=%q (could not correlate)", m.CreatedAt, m.ProcessedAt)
+		return
+	}
+
+	t.logf("Server timeline: created_at=%s (%s after request sent), processed_at=%s (%s processing), headers received %s after processed_at",
+		createdAt.Format("15:04:05Z"), signedSeconds(createdAt.Sub(sentAt)),
+		processedAt.Format("15:04:05Z"), signedSeconds(processedAt.Sub(createdAt)),
+		signedSeconds(firstByteAt.Sub(processedAt)))
+
+	// Flag the phase that dominated when the wait was noticeably longer than
+	// the server's own processing time. 2s absorbs the 1s timestamp
+	// resolution plus typical network latency.
+	const slack = 2 * time.Second
+	waited := firstByteAt.Sub(sentAt)
+	if waited <= time.Duration(m.TotalTimeTaken*float64(time.Second))+slack {
+		return
+	}
+	switch {
+	case createdAt.Sub(sentAt) > slack:
+		t.logf("Note: most of the wait (%s) happened before the server created the search; suspect network path, proxy, or server-side queueing rather than the search engine", signedSeconds(createdAt.Sub(sentAt)))
+	case firstByteAt.Sub(processedAt) > slack:
+		t.logf("Note: the server finished processing %s before headers arrived; suspect response delivery path", signedSeconds(firstByteAt.Sub(processedAt)))
+	}
+}
+
+// signedSeconds formats d as e.g. "+1.2s" or "-0.4s". The sign is kept
+// because clock skew between client and server can make deltas negative.
+func signedSeconds(d time.Duration) string {
+	return fmt.Sprintf("%+.1fs", d.Seconds())
+}
diff --git a/pkg/api/debug_test.go b/pkg/api/debug_test.go
index 2e3b105..dd9ce21 100644
--- a/pkg/api/debug_test.go
+++ b/pkg/api/debug_test.go
@@ -3,7 +3,9 @@ package api
 import (
 	"bytes"
 	"context"
+	"fmt"
 	"net/http"
+	"regexp"
 	"strings"
 	"testing"
 	"time"
@@ -60,6 +62,10 @@ func TestDebugTraceCoversRequestLifecycle(t *testing.T) {
 	if strings.Contains(out, "secret_key") || !strings.Contains(out, "api_key=[REDACTED]") {
 		t.Errorf("debug output must redact the API key:\n%s", out)
 	}
+	// Local and remote addresses are both reported, e.g. "127.0.0.1:54321 -> 127.0.0.1:8080 (new)".
+	if !regexp.MustCompile(`Using connection: 127\.0\.0\.1:\d+ -> 127\.0\.0\.1:\d+ \(new\)`).MatchString(out) {
+		t.Errorf("expected local -> remote address pair:\n%s", out)
+	}
 	for _, line := range strings.Split(strings.TrimSpace(out), "\n") {
 		if !strings.HasPrefix(line, "[debug] ") {
 			t.Errorf("every debug line should be prefixed, got %q", line)
@@ -86,3 +92,131 @@ func TestDebugTraceReportsTimeout(t *testing.T) {
 		t.Errorf("no response byte should have arrived:\n%s", out)
 	}
 }
+
+// newMetadataServer serves a search response whose created_at/processed_at
+// are stamped at request arrival, so the correlation line has real values.
+func newMetadataServer(t *testing.T, w *bytes.Buffer, processing time.Duration) *Client {
+	t.Helper()
+	srv := newTestServer(t, func(rw http.ResponseWriter, r *http.Request) {
+		created := time.Now().UTC()
+		processed := created.Add(processing)
+		rw.Header().Set("Content-Type", "application/json")
+		fmt.Fprintf(rw, `{"search_metadata":{"id":"abc123","status":"Success","created_at":%q,"processed_at":%q,"total_time_taken":%g}}`,
+			created.Format(searchMetadataTimeLayout), processed.Format(searchMetadataTimeLayout), processing.Seconds())
+	})
+	return New("secret_key", WithBaseURL(srv.URL), WithTimeout(10*time.Second), WithDebug(w))
+}
+
+func TestDebugCorrelatesSearchMetadata(t *testing.T) {
+	var buf bytes.Buffer
+	client := newMetadataServer(t, &buf, 1*time.Second)
+
+	if _, err := client.Search(context.Background(), map[string]string{"q": "x"}); err != nil {
+		t.Fatalf("unexpected error: %v", err)
+	}
+	out := buf.String()
+	for _, want := range []string{
+		"Server search: id=abc123 status=Success total_time_taken=1s",
+		"Server timeline: created_at=",
+		"after request sent",
+		"(+1.0s processing)",
+		"headers received",
+	} {
+		if !strings.Contains(out, want) {
+			t.Errorf("debug output missing %q:\n%s", want, out)
+		}
+	}
+	if strings.Contains(out, "Note:") {
+		t.Errorf("fast response should not trigger a stall note:\n%s", out)
+	}
+}
+
+// stallTracer builds a tracer with a fixed client-side timeline and a body
+// whose server timestamps are offset from it, without any real waiting.
+func stallTracer(w *bytes.Buffer, preCreate, processing, postProcess time.Duration) (*tracer, []byte) {
+	sentAt := time.Date(2026, 10, 9, 12, 0, 0, 0, time.UTC)
+	created := sentAt.Add(preCreate)
+	processed := created.Add(processing)
+	firstByte := processed.Add(postProcess)
+
+	tr := &tracer{w: w, start: sentAt, sentAt: sentAt, firstByteAt: firstByte}
+	body := fmt.Appendf(nil, `{"search_metadata":{"id":"abc123","status":"Success","created_at":%q,"processed_at":%q,"total_time_taken":%g}}`,
+		created.Format(searchMetadataTimeLayout), processed.Format(searchMetadataTimeLayout), processing.Seconds())
+	return tr, body
+}
+
+func TestDebugFlagsStallBeforeSearchCreation(t *testing.T) {
+	var buf bytes.Buffer
+	// The customer's scenario: 9s of processing but headers arrive ~30s after
+	// sending, with the gap entirely before the server created the search.
+	tr, body := stallTracer(&buf, 21*time.Second, 9*time.Second, 0)
+	tr.logSearchMetadata(body)
+
+	out := buf.String()
+	if !strings.Contains(out, "created_at=12:00:21Z (+21.0s after request sent)") {
+		t.Errorf("expected 21s pre-creation gap:\n%s", out)
+	}
+	if !strings.Contains(out, "(+9.0s processing)") {
+		t.Errorf("expected 9s processing:\n%s", out)
+	}
+	if !strings.Contains(out, "Note: most of the wait (+21.0s) happened before the server created the search") {
+		t.Errorf("expected pre-creation stall note:\n%s", out)
+	}
+}
+
+func TestDebugFlagsStallAfterProcessing(t *testing.T) {
+	var buf bytes.Buffer
+	tr, body := stallTracer(&buf, 0, 2*time.Second, 15*time.Second)
+	tr.logSearchMetadata(body)
+
+	out := buf.String()
+	if !strings.Contains(out, "headers received +15.0s after processed_at") {
+		t.Errorf("expected 15s post-processing gap:\n%s", out)
+	}
+	if !strings.Contains(out, "Note: the server finished processing +15.0s before headers arrived") {
+		t.Errorf("expected post-processing stall note:\n%s", out)
+	}
+}
+
+func TestDebugNoStallNoteWhenServerProcessingDominates(t *testing.T) {
+	var buf bytes.Buffer
+	// Slow, but honestly slow: the engine took 40s and that's all we waited.
+	tr, body := stallTracer(&buf, 0, 40*time.Second, 500*time.Millisecond)
+	tr.logSearchMetadata(body)
+
+	if strings.Contains(buf.String(), "Note:") {
+		t.Errorf("slow engine should not be flagged as a client/network stall:\n%s", buf.String())
+	}
+}
+
+func TestDebugSearchMetadataUnparseableIsReported(t *testing.T) {
+	var buf bytes.Buffer
+	srv := newTestServer(t, func(rw http.ResponseWriter, r *http.Request) {
+		rw.Header().Set("Content-Type", "application/json")
+		_, _ = rw.Write([]byte(`{"search_metadata":{"id":"abc123","status":"Success","created_at":"soon","processed_at":"later","total_time_taken":0.5}}`))
+	})
+	client := New("k", WithBaseURL(srv.URL), WithTimeout(5*time.Second), WithDebug(&buf))
+
+	if _, err := client.Search(context.Background(), map[string]string{"q": "x"}); err != nil {
+		t.Fatalf("unexpected error: %v", err)
+	}
+	out := buf.String()
+	if !strings.Contains(out, "Server search: id=abc123") {
+		t.Errorf("id should still be reported:\n%s", out)
+	}
+	if !strings.Contains(out, "could not correlate") {
+		t.Errorf("expected graceful fallback for bad timestamps:\n%s", out)
+	}
+}
+
+func TestDebugNoMetadataLineForNonSearchEndpoints(t *testing.T) {
+	var buf bytes.Buffer
+	client := newDebugServer(t, &buf)
+
+	if _, err := client.Account(context.Background()); err != nil {
+		t.Fatalf("unexpected error: %v", err)
+	}
+	if strings.Contains(buf.String(), "Server search:") {
+		t.Errorf("account endpoint should not emit search correlation:\n%s", buf.String())
+	}
+}
diff --git a/pkg/cmd/root.go b/pkg/cmd/root.go
index d726aad..b4e01c3 100644
--- a/pkg/cmd/root.go
+++ b/pkg/cmd/root.go
@@ -239,7 +239,7 @@ func init() {
 		"HTTP request timeout in seconds, such as 120, or a duration, such as 2m; 0 waits indefinitely (default %d; env SERPAPI_TIMEOUT)",
 		int(api.DefaultTimeout/time.Second)))
 	pf.BoolVar(&debugFlag, "debug", false,
-		"trace each request on stderr: DNS, connect, TLS, first byte and headers (env SERPAPI_DEBUG=1)")
+		"trace each request on stderr: DNS, connect, TLS, first byte, headers and the server timeline (env SERPAPI_DEBUG=1)")
 
 	rootCmd.PersistentPreRunE = validateGlobalFlags
 

From 3c60b35faad3fd6f3a8d2478ec990640913a7d64 Mon Sep 17 00:00:00 2001
From: Josef Strzibny <strzibny@strzibny.name>
Date: Mon, 12 Oct 2026 08:57:08 +0200
Subject: [PATCH 3/7] Change wording to direct users to focus on checking VPN,
 proxy, and connectivity

---
 README.md              | 10 +++++-----
 pkg/api/client.go      | 10 +++++-----
 pkg/api/client_test.go |  6 +++---
 pkg/api/debug.go       |  6 +++---
 pkg/api/debug_test.go  |  8 ++++----
 pkg/cmd/edge_test.go   |  2 +-
 6 files changed, 21 insertions(+), 21 deletions(-)

diff --git a/README.md b/README.md
index 67b107f..f4ab8f0 100644
--- a/README.md
+++ b/README.md
@@ -111,17 +111,17 @@ Prints the CLI version, as `--version` does.
 - `--jq <expr>`: [jq](https://jqlang.github.io/jq/manual/) filter applied to the JSON result, like `gh --jq`; strings print unquoted and `null` as an empty line, and results stream as they are produced. A filter that prints only `null` gets a warning listing the response's top-level keys. jq is built in, so nothing else needs installing. In bash and zsh, quote the expression with single quotes.
 - `--fields <expr>`: search only; see [search](#search).
 - `--api-key <key>`: API key. Prefer `SERPAPI_KEY`, since flags show up in `ps` and shell history.
-- `--timeout <seconds>`: HTTP request timeout in seconds, such as `120`, or a duration, such as `2m` (default `60`; env `SERPAPI_TIMEOUT`). `0` waits indefinitely. Slow engines such as `google_ai_mode`, and searches with `no_cache=true`, can take longer than the default; raise it when a `network_error` says the request timed out. A timed-out search may still finish on SerpApi's side, count against your searches and be available in your search archive.
+- `--timeout <seconds>`: HTTP request timeout in seconds, such as `120`, or a duration, such as `2m` (default `60`; env `SERPAPI_TIMEOUT`). `0` waits indefinitely. Raise it when a `network_error` says the request timed out and you are on a slow or unstable network path (VPN, proxy, high-latency connection); `--debug` shows where the time went. A timed-out search may still finish on SerpApi's side, count against your searches and be available in your search archive.
   ```bash
-  # Give an AI Mode query up to two minutes
-  serpapi search --timeout 120 engine=google_ai_mode q="..."
+  # Allow up to two minutes for a single request
+  serpapi search --timeout 120 engine=google q="..."
 
   # Or set it once for the shell session
   export SERPAPI_TIMEOUT=120
   ```
-- `--debug`: trace each request on stderr (env `SERPAPI_DEBUG=1`): DNS, TCP connect (local and remote address), TLS handshake, time to first byte, response status and headers (including `Serpapi-Search-Id` and `X-Request-Id`), body size, and, for searches, the server's `search_metadata` timeline correlated with the client's, so you can see whether a long wait happened before SerpApi created the search (network path, proxy, queueing), during processing (slow engine), or after processing finished. Each line carries a UTC timestamp and the seconds elapsed since the request started; the API key is redacted; stdout is untouched, so `--jq` and piping still work.
+- `--debug`: trace each request on stderr (env `SERPAPI_DEBUG=1`): DNS, TCP connect (local and remote address), TLS handshake, time to first byte, response status and headers (including `Serpapi-Search-Id` and `X-Request-Id`), body size, and, for searches, the server's `search_metadata` timeline correlated with the client's, so you can see whether a long wait happened on the network path before SerpApi received the request, during processing, or while the response travelled back. Each line carries a UTC timestamp and the seconds elapsed since the request started; the API key is redacted; stdout is untouched, so `--jq` and piping still work.
   ```bash
-  serpapi search --debug engine=google_ai_mode q="..." > result.json
+  serpapi search --debug engine=google q="..." > result.json
   ```
   ```
   [debug] 2026-10-09T11:50:54.272Z + 0.000s GET https://serpapi.com/search.json?api_key=[REDACTED]&engine=google&q=coffee
diff --git a/pkg/api/client.go b/pkg/api/client.go
index 4be6e0c..8d719bf 100644
--- a/pkg/api/client.go
+++ b/pkg/api/client.go
@@ -23,9 +23,9 @@ const (
 	// DefaultBaseURL is the SerpApi production endpoint.
 	DefaultBaseURL = "https://serpapi.com"
 	// DefaultTimeout bounds one HTTP request, including reading the response
-	// body. It matches the 60s default of the official serpapi-golang library.
-	// Slow engines such as google_ai_mode can take longer with no_cache=true,
-	// and SerpApi still finishes and counts a search the client gave up on.
+	// body. It matches the 60s default of the official serpapi-golang library
+	// and leaves headroom for slow or unreliable network paths. SerpApi still
+	// finishes and counts a search the client gave up on.
 	DefaultTimeout = 60 * time.Second
 )
 
@@ -152,8 +152,8 @@ func (c *Client) networkError(endpoint string, err error) error {
 	var netErr net.Error
 	if c.http.Timeout > 0 && (errors.Is(err, context.DeadlineExceeded) || (errors.As(err, &netErr) && netErr.Timeout())) {
 		return &clierrors.NetworkError{
-			Message: fmt.Sprintf("Request to %s timed out after %s. Slow engines, such as google_ai_mode, and no_cache=true can take longer: "+
-				"retry with a higher --timeout, such as --timeout %d, or 0 to wait indefinitely, or run with --debug to see where time was spent. "+
+			Message: fmt.Sprintf("Request to %s timed out after %s. This usually points to a slow or unstable network path (VPN, proxy, or connectivity issues): "+
+				"run with --debug to see where time was spent, or retry with a higher --timeout, such as --timeout %d, or 0 to wait indefinitely. "+
 				"The search may still finish on SerpApi's side, count against your searches and be available in your search archive",
 				endpoint, seconds(c.http.Timeout), suggestedTimeout(c.http.Timeout)),
 			Cause: cause,
diff --git a/pkg/api/client_test.go b/pkg/api/client_test.go
index c2b0c55..958f4bc 100644
--- a/pkg/api/client_test.go
+++ b/pkg/api/client_test.go
@@ -333,7 +333,7 @@ func TestNewUsesDefaultTimeout(t *testing.T) {
 		t.Fatalf("expected default timeout %s, got %s", DefaultTimeout, got)
 	}
 	if DefaultTimeout < 60*time.Second {
-		t.Fatalf("default timeout %s is too short for slow engines like google_ai_mode", DefaultTimeout)
+		t.Fatalf("default timeout %s is shorter than the 60s used by the official serpapi-golang library", DefaultTimeout)
 	}
 }
 
@@ -412,8 +412,8 @@ func TestOSTimeoutWithoutAClientLimit(t *testing.T) {
 // The advice names a --timeout above the one that just ran out.
 func TestTimeoutAdviceRaisesTheLimit(t *testing.T) {
 	for limit, want := range map[time.Duration]string{
-		50 * time.Millisecond: "timed out after 50ms. Slow engines, such as google_ai_mode, and no_cache=true can take longer: retry with a higher --timeout, such as --timeout 120,",
-		60 * time.Second:      "timed out after 60s. Slow engines, such as google_ai_mode, and no_cache=true can take longer: retry with a higher --timeout, such as --timeout 120,",
+		50 * time.Millisecond: "timed out after 50ms. This usually points to a slow or unstable network path (VPN, proxy, or connectivity issues): run with --debug to see where time was spent, or retry with a higher --timeout, such as --timeout 120,",
+		60 * time.Second:      "timed out after 60s. This usually points to a slow or unstable network path (VPN, proxy, or connectivity issues): run with --debug to see where time was spent, or retry with a higher --timeout, such as --timeout 120,",
 		120 * time.Second:     "--timeout 240,",
 		301 * time.Second:     "--timeout 602,",
 	} {
diff --git a/pkg/api/debug.go b/pkg/api/debug.go
index 2758128..4376962 100644
--- a/pkg/api/debug.go
+++ b/pkg/api/debug.go
@@ -176,7 +176,7 @@ const searchMetadataTimeLayout = "2006-01-02 15:04:05 MST"
 
 // logSearchMetadata correlates the server-side search_metadata timestamps
 // with the client-side timeline so a stall can be attributed to one of:
-//   - before the server created the search (network, edge, queueing)
+//   - before the request reached the server (DNS, VPN, proxy, network path)
 //   - server processing (created_at -> processed_at)
 //   - after processing finished but before headers were sent
 //
@@ -227,9 +227,9 @@ func (t *tracer) logSearchMetadata(body []byte) {
 	}
 	switch {
 	case createdAt.Sub(sentAt) > slack:
-		t.logf("Note: most of the wait (%s) happened before the server created the search; suspect network path, proxy, or server-side queueing rather than the search engine", signedSeconds(createdAt.Sub(sentAt)))
+		t.logf("Note: most of the wait (%s) happened before the request reached SerpApi; check the network path (DNS, VPN, proxy, connectivity)", signedSeconds(createdAt.Sub(sentAt)))
 	case firstByteAt.Sub(processedAt) > slack:
-		t.logf("Note: the server finished processing %s before headers arrived; suspect response delivery path", signedSeconds(firstByteAt.Sub(processedAt)))
+		t.logf("Note: the response took %s to arrive after SerpApi finished processing; check the network path back to this machine", signedSeconds(firstByteAt.Sub(processedAt)))
 	}
 }
 
diff --git a/pkg/api/debug_test.go b/pkg/api/debug_test.go
index dd9ce21..e9d71aa 100644
--- a/pkg/api/debug_test.go
+++ b/pkg/api/debug_test.go
@@ -159,7 +159,7 @@ func TestDebugFlagsStallBeforeSearchCreation(t *testing.T) {
 	if !strings.Contains(out, "(+9.0s processing)") {
 		t.Errorf("expected 9s processing:\n%s", out)
 	}
-	if !strings.Contains(out, "Note: most of the wait (+21.0s) happened before the server created the search") {
+	if !strings.Contains(out, "Note: most of the wait (+21.0s) happened before the request reached SerpApi") {
 		t.Errorf("expected pre-creation stall note:\n%s", out)
 	}
 }
@@ -173,19 +173,19 @@ func TestDebugFlagsStallAfterProcessing(t *testing.T) {
 	if !strings.Contains(out, "headers received +15.0s after processed_at") {
 		t.Errorf("expected 15s post-processing gap:\n%s", out)
 	}
-	if !strings.Contains(out, "Note: the server finished processing +15.0s before headers arrived") {
+	if !strings.Contains(out, "Note: the response took +15.0s to arrive after SerpApi finished processing") {
 		t.Errorf("expected post-processing stall note:\n%s", out)
 	}
 }
 
 func TestDebugNoStallNoteWhenServerProcessingDominates(t *testing.T) {
 	var buf bytes.Buffer
-	// Slow, but honestly slow: the engine took 40s and that's all we waited.
+	// Long, but legitimately so: processing took 40s and that's all we waited.
 	tr, body := stallTracer(&buf, 0, 40*time.Second, 500*time.Millisecond)
 	tr.logSearchMetadata(body)
 
 	if strings.Contains(buf.String(), "Note:") {
-		t.Errorf("slow engine should not be flagged as a client/network stall:\n%s", buf.String())
+		t.Errorf("long server processing should not be flagged as a client/network stall:\n%s", buf.String())
 	}
 }
 
diff --git a/pkg/cmd/edge_test.go b/pkg/cmd/edge_test.go
index 8c29590..a3da6fb 100644
--- a/pkg/cmd/edge_test.go
+++ b/pkg/cmd/edge_test.go
@@ -191,7 +191,7 @@ func edgeCases() []edgeCase {
 		{name: "response/no answer in time", args: []string{"account", "--timeout", "50ms"}, api: hang, exit: 1, code: "network_error",
 			msg: "Request to /account.json timed out after 50ms"},
 		{name: "response/SERPAPI_TIMEOUT applies", args: []string{"account"}, env: map[string]string{"SERPAPI_TIMEOUT": "0.05"}, api: hang, exit: 1,
-			code: "network_error", msg: "Request to /account.json timed out after 50ms. Slow engines, such as google_ai_mode"},
+			code: "network_error", msg: "Request to /account.json timed out after 50ms. This usually points to a slow or unstable network path"},
 
 		{name: "paging/foreign next host and key", args: searchWith("--all-pages"), api: func(w http.ResponseWriter, r *http.Request) {
 			if pageNumber(r) == 1 {

From 0caec01fda39a0e00b490340fcf1fab21f42e96c Mon Sep 17 00:00:00 2001
From: Josef Strzibny <strzibny@strzibny.name>
Date: Tue, 13 Oct 2026 10:04:58 +0200
Subject: [PATCH 4/7] Emit --debug trace as JSON lines off a terminal

---
 README.md             |  16 +++--
 pkg/api/client.go     |   3 +-
 pkg/api/debug.go      | 114 +++++++++++++++++++++++++------
 pkg/api/debug_test.go | 154 +++++++++++++++++++++++++++++++++++++++---
 pkg/cmd/root.go       |  10 ++-
 pkg/cmd/root_test.go  | 133 ++++++++++++++++++++++++++++++++++++
 tests/e2e_test.go     |  37 ++++++++++
 7 files changed, 425 insertions(+), 42 deletions(-)

diff --git a/README.md b/README.md
index f4ab8f0..5801dd7 100644
--- a/README.md
+++ b/README.md
@@ -119,10 +119,7 @@ Prints the CLI version, as `--version` does.
   # Or set it once for the shell session
   export SERPAPI_TIMEOUT=120
   ```
-- `--debug`: trace each request on stderr (env `SERPAPI_DEBUG=1`): DNS, TCP connect (local and remote address), TLS handshake, time to first byte, response status and headers (including `Serpapi-Search-Id` and `X-Request-Id`), body size, and, for searches, the server's `search_metadata` timeline correlated with the client's, so you can see whether a long wait happened on the network path before SerpApi received the request, during processing, or while the response travelled back. Each line carries a UTC timestamp and the seconds elapsed since the request started; the API key is redacted; stdout is untouched, so `--jq` and piping still work.
-  ```bash
-  serpapi search --debug engine=google q="..." > result.json
-  ```
+- `--debug`: trace each request on stderr (env `SERPAPI_DEBUG=1`): DNS, TCP connect (local and remote address), TLS handshake, time to first byte, response status and headers (including `Serpapi-Search-Id` and `X-Request-Id`), body size, and, for searches, the server's `search_metadata` timeline correlated with the client's, so you can see whether a long wait happened on the network path before SerpApi received the request, during processing, or while the response travelled back. Each line carries a UTC timestamp and the seconds elapsed since the request started; the API key is redacted; stdout is untouched, so `--jq` and piping still work. On a terminal the trace is plain text:
   ```
   [debug] 2026-10-09T11:50:54.272Z + 0.000s GET https://serpapi.com/search.json?api_key=[REDACTED]&engine=google&q=coffee
   [debug] 2026-10-09T11:50:54.272Z + 0.000s Timeout: 60s
@@ -137,7 +134,13 @@ Prints the CLI version, as `--version` does.
   [debug] 2026-10-09T11:50:55.234Z + 0.962s Server search: id=6ac8d51eaf5fdcac5434ae91 status=Success total_time_taken=0.5s
   [debug] 2026-10-09T11:50:55.234Z + 0.962s Server timeline: created_at=11:50:54Z (+0.0s after request sent), processed_at=11:50:54Z (+0.0s processing), headers received +1.2s after processed_at
   ```
-  Server timestamps have one-second resolution, so sub-second deltas in the `Server timeline` line are noise. When the client waited noticeably longer than `total_time_taken`, a `Note:` line points at the phase that dominated.
+  Piped or redirected, stderr stays one JSON object per line, so scripts that parse it keep working; headers and the timeline travel as structured `data`:
+  ```
+  {"debug":{"at":"2026-10-09T11:50:54.414Z","elapsed":0.142,"event":"Request sent, waiting for response headers"}}
+  {"debug":{"at":"2026-10-09T11:50:55.227Z","elapsed":0.955,"event":"Response: HTTP/2.0 200 OK","data":{"status":200,"proto":"HTTP/2.0","headers":{"Serpapi-Search-Id":"6ac8d51e..."}}}}
+  {"debug":{"at":"2026-10-09T11:50:55.234Z","elapsed":0.962,"event":"Server timeline: ...","data":{"sent_to_created_s":0.0,"processing_s":0.0,"processed_to_headers_s":1.2}}}
+  ```
+  Server timestamps have one-second resolution, so sub-second deltas in the timeline are noise. When the client waited noticeably longer than `total_time_taken`, a `Note:` event points at the phase that dominated. To send a trace along with a support request: `SERPAPI_DEBUG=1 serpapi search ... > result.json 2> trace.jsonl`.
 
 ## Configuration
 
@@ -164,10 +167,11 @@ A config file that can't be read or isn't valid TOML is reported by path and lin
 
 - **stdout carries only results**: JSON indented by two spaces, colored on a terminal. Piped, it is indented too, so `head`, `grep` and file viewers show whole lines; `head` cuts the JSON short, so take parts with `--jq`. A terminal gets control characters from results escaped, so a page can't drive it; piped output keeps them. Shrink them on the server with `--fields`, then locally with `--jq`, or ask for `output=md`.
 - **Unfamiliar engine?** Responses are often 20–300 KB, and one key can be large too (Maps `place_results` holds reviews and photos). Piped without `--jq`, a result over 16 KB comes with a warning on stderr that lists its top-level keys by size, unless stderr goes into the same pipe (`2>&1`), where it would break a JSON parser. Print a sample with one item per array, `--jq 'walk(if type == "array" then .[:1] else . end)'`; nested arrays are cut too, so it shows the shape, not the answer. Then take what you need from the stored search for free: `serpapi archive SEARCH_METADATA_ID --jq '...'`.
-- **Errors and warnings go to stderr**, one JSON object per line:
+- **Errors and warnings go to stderr**, one JSON object per line; so does the `--debug` trace, as `{"debug":{...}}` lines, when stderr is not a terminal:
   ```
   {"error":{"code":"api_error","message":"Invalid API key. ...","status":401}}
   {"warning":{"message":"..."}}
+  {"debug":{"at":"2026-10-09T11:50:54.414Z","elapsed":0.142,"event":"Request sent, waiting for response headers"}}
   ```
 - **The exit code says what to do next**:
 
diff --git a/pkg/api/client.go b/pkg/api/client.go
index 8d719bf..61acfcb 100644
--- a/pkg/api/client.go
+++ b/pkg/api/client.go
@@ -39,7 +39,8 @@ type Client struct {
 	http    *http.Client
 
 	// debug, if set, receives a trace of each request; see WithDebug.
-	debug io.Writer
+	debug     io.Writer
+	debugJSON bool
 }
 
 // Option configures a Client.
diff --git a/pkg/api/debug.go b/pkg/api/debug.go
index 4376962..5014f74 100644
--- a/pkg/api/debug.go
+++ b/pkg/api/debug.go
@@ -16,17 +16,31 @@ import (
 )
 
 // WithDebug traces each request to w: DNS, connect, TLS, first byte, status
-// and headers, and the search_metadata timeline. Passing a nil w disables it.
-func WithDebug(w io.Writer) Option {
+// and headers, and the search_metadata timeline. With jsonLines set, every
+// line is one JSON object, {"debug":{"at":...,"elapsed":...,"event":...}},
+// so stderr stays parseable line by line off a terminal; otherwise lines are
+// plain text, "[debug] <at> +<elapsed>s <event>". Passing a nil w disables it.
+func WithDebug(w io.Writer, jsonLines bool) Option {
 	return func(c *Client) {
 		c.debug = w
+		c.debugJSON = jsonLines
 	}
 }
 
+// debugEvent is one JSON debug line. Headers and the search timeline carry
+// structured fields next to the human-readable event.
+type debugEvent struct {
+	At      string         `json:"at"`
+	Elapsed float64        `json:"elapsed"`
+	Event   string         `json:"event"`
+	Data    map[string]any `json:"data,omitempty"`
+}
+
 // tracer writes timestamped request-lifecycle events. A nil *tracer is a
 // valid no-op so call sites don't need to guard on whether debug is enabled.
 type tracer struct {
 	w     io.Writer
+	json  bool
 	start time.Time
 	mu    sync.Mutex
 
@@ -40,22 +54,45 @@ func (c *Client) newTracer() *tracer {
 	if c.debug == nil {
 		return nil
 	}
-	return &tracer{w: c.debug, start: time.Now()}
+	return &tracer{w: c.debug, json: c.debugJSON, start: time.Now()}
 }
 
-// logf writes one line: wall-clock UTC time (to correlate with server-side
-// created_at/processed_at), elapsed since the request started, and the
-// message with any api_key value redacted.
+// logf writes one event with no structured data.
 func (t *tracer) logf(format string, args ...any) {
+	t.log(nil, format, args...)
+}
+
+// log writes one event: wall-clock UTC time (to correlate with server-side
+// created_at/processed_at), seconds since the request started, and the
+// message with any api_key value redacted. data, if not nil, is included in
+// the JSON form only.
+func (t *tracer) log(data map[string]any, format string, args ...any) {
 	if t == nil {
 		return
 	}
 	now := time.Now()
+	at := now.UTC().Format("2006-01-02T15:04:05.000Z")
+	elapsed := now.Sub(t.start).Seconds()
 	msg := clierrors.RedactAPIKey(fmt.Sprintf(format, args...))
+
+	var line []byte
+	if t.json {
+		b, err := json.Marshal(map[string]any{"debug": debugEvent{At: at, Elapsed: round3(elapsed), Event: msg, Data: data}})
+		if err != nil {
+			return
+		}
+		line = append(b, '\n')
+	} else {
+		line = fmt.Appendf(nil, "[debug] %s +%6.3fs %s\n", at, elapsed, msg)
+	}
+
 	t.mu.Lock()
 	defer t.mu.Unlock()
-	fmt.Fprintf(t.w, "[debug] %s +%6.3fs %s\n",
-		now.UTC().Format("2006-01-02T15:04:05.000Z"), now.Sub(t.start).Seconds(), msg)
+	_, _ = t.w.Write(line)
+}
+
+func round3(f float64) float64 {
+	return float64(int64(f*1000+0.5)) / 1000
 }
 
 // clientTrace returns httptrace hooks that report each connection phase.
@@ -110,11 +147,12 @@ func (t *tracer) clientTrace() *httptrace.ClientTrace {
 					remote = a.String()
 				}
 			}
+			data := map[string]any{"local": local, "remote": remote, "reused": info.Reused}
 			if info.Reused {
-				t.logf("Using connection: %s -> %s (reused, idle %s)", local, remote, info.IdleTime.Round(time.Millisecond))
+				t.log(data, "Using connection: %s -> %s (reused, idle %s)", local, remote, info.IdleTime.Round(time.Millisecond))
 				return
 			}
-			t.logf("Using connection: %s -> %s (new)", local, remote)
+			t.log(data, "Using connection: %s -> %s (new)", local, remote)
 		},
 		WroteRequest: func(info httptrace.WroteRequestInfo) {
 			if info.Err != nil {
@@ -152,17 +190,28 @@ func (t *tracer) logRequest(req *http.Request, timeout time.Duration) {
 	}
 }
 
-// logResponse reports the status line and headers in a stable order.
+// logResponse reports the status line and headers in a stable order. The
+// JSON form carries them as one event; the text form lists one per line.
 func (t *tracer) logResponse(resp *http.Response) {
 	if t == nil || resp == nil {
 		return
 	}
-	t.logf("Response: %s %s", resp.Proto, resp.Status)
 	names := make([]string, 0, len(resp.Header))
 	for name := range resp.Header {
 		names = append(names, name)
 	}
 	sort.Strings(names)
+
+	if t.json {
+		headers := make(map[string]string, len(names))
+		for _, name := range names {
+			headers[name] = strings.Join(resp.Header[name], ", ")
+		}
+		t.log(map[string]any{"status": resp.StatusCode, "proto": resp.Proto, "headers": headers},
+			"Response: %s %s", resp.Proto, resp.Status)
+		return
+	}
+	t.logf("Response: %s %s", resp.Proto, resp.Status)
 	for _, name := range names {
 		for _, value := range resp.Header[name] {
 			t.logf("  %s: %s", name, value)
@@ -203,7 +252,8 @@ func (t *tracer) logSearchMetadata(body []byte) {
 	sentAt, firstByteAt := t.sentAt, t.firstByteAt
 	t.mu.Unlock()
 
-	t.logf("Server search: id=%s status=%s total_time_taken=%gs", m.ID, m.Status, m.TotalTimeTaken)
+	t.log(map[string]any{"id": m.ID, "status": m.Status, "total_time_taken": m.TotalTimeTaken},
+		"Server search: id=%s status=%s total_time_taken=%gs", m.ID, m.Status, m.TotalTimeTaken)
 
 	createdAt, err1 := time.Parse(searchMetadataTimeLayout, m.CreatedAt)
 	processedAt, err2 := time.Parse(searchMetadataTimeLayout, m.ProcessedAt)
@@ -212,10 +262,32 @@ func (t *tracer) logSearchMetadata(body []byte) {
 		return
 	}
 
-	t.logf("Server timeline: created_at=%s (%s after request sent), processed_at=%s (%s processing), headers received %s after processed_at",
-		createdAt.Format("15:04:05Z"), signedSeconds(createdAt.Sub(sentAt)),
-		processedAt.Format("15:04:05Z"), signedSeconds(processedAt.Sub(createdAt)),
-		signedSeconds(firstByteAt.Sub(processedAt)))
+	beforeCreate := createdAt.Sub(sentAt)
+	processing := processedAt.Sub(createdAt)
+	afterProcess := firstByteAt.Sub(processedAt)
+
+	// A search created well before this request was sent is a cached result:
+	// its timestamps describe the original search, not this round trip. 5s
+	// absorbs clock skew between client and server.
+	if beforeCreate < -5*time.Second {
+		t.log(map[string]any{
+			"created_at":   createdAt.Format(time.RFC3339),
+			"processed_at": processedAt.Format(time.RFC3339),
+			"cached":       true,
+		}, "Server timeline: cached result from %s (%.0fs before this request); the %s wait was network round trip only",
+			createdAt.Format(time.RFC3339), (-beforeCreate).Seconds(), signedSeconds(firstByteAt.Sub(sentAt)))
+		return
+	}
+	t.log(map[string]any{
+		"created_at":             createdAt.Format(time.RFC3339),
+		"processed_at":           processedAt.Format(time.RFC3339),
+		"sent_to_created_s":      round3(beforeCreate.Seconds()),
+		"processing_s":           round3(processing.Seconds()),
+		"processed_to_headers_s": round3(afterProcess.Seconds()),
+	}, "Server timeline: created_at=%s (%s after request sent), processed_at=%s (%s processing), headers received %s after processed_at",
+		createdAt.Format("15:04:05Z"), signedSeconds(beforeCreate),
+		processedAt.Format("15:04:05Z"), signedSeconds(processing),
+		signedSeconds(afterProcess))
 
 	// Flag the phase that dominated when the wait was noticeably longer than
 	// the server's own processing time. 2s absorbs the 1s timestamp
@@ -226,10 +298,10 @@ func (t *tracer) logSearchMetadata(body []byte) {
 		return
 	}
 	switch {
-	case createdAt.Sub(sentAt) > slack:
-		t.logf("Note: most of the wait (%s) happened before the request reached SerpApi; check the network path (DNS, VPN, proxy, connectivity)", signedSeconds(createdAt.Sub(sentAt)))
-	case firstByteAt.Sub(processedAt) > slack:
-		t.logf("Note: the response took %s to arrive after SerpApi finished processing; check the network path back to this machine", signedSeconds(firstByteAt.Sub(processedAt)))
+	case beforeCreate > slack:
+		t.logf("Note: most of the wait (%s) happened before the request reached SerpApi; check the network path (DNS, VPN, proxy, connectivity)", signedSeconds(beforeCreate))
+	case afterProcess > slack:
+		t.logf("Note: the response took %s to arrive after SerpApi finished processing; check the network path back to this machine", signedSeconds(afterProcess))
 	}
 }
 
diff --git a/pkg/api/debug_test.go b/pkg/api/debug_test.go
index e9d71aa..adaf1a8 100644
--- a/pkg/api/debug_test.go
+++ b/pkg/api/debug_test.go
@@ -3,6 +3,7 @@ package api
 import (
 	"bytes"
 	"context"
+	"encoding/json"
 	"fmt"
 	"net/http"
 	"regexp"
@@ -11,20 +12,20 @@ import (
 	"time"
 )
 
-func newDebugServer(t *testing.T, w *bytes.Buffer) *Client {
+func newDebugServer(t *testing.T, w *bytes.Buffer, jsonLines bool) *Client {
 	t.Helper()
 	srv := newTestServer(t, func(rw http.ResponseWriter, r *http.Request) {
 		rw.Header().Set("Content-Type", "application/json")
 		rw.Header().Set("Serpapi-Search-Id", "abc123")
 		_, _ = rw.Write([]byte(`{"ok":true}`))
 	})
-	return New("secret_key", WithBaseURL(srv.URL), WithTimeout(5*time.Second), WithDebug(w))
+	return New("secret_key", WithBaseURL(srv.URL), WithTimeout(5*time.Second), WithDebug(w, jsonLines))
 }
 
 func TestDebugDisabledByDefault(t *testing.T) {
 	var buf bytes.Buffer
-	client := newDebugServer(t, &buf)
-	WithDebug(nil)(client)
+	client := newDebugServer(t, &buf, false)
+	WithDebug(nil, false)(client)
 
 	if _, err := client.Search(context.Background(), map[string]string{"q": "x"}); err != nil {
 		t.Fatalf("unexpected error: %v", err)
@@ -36,7 +37,7 @@ func TestDebugDisabledByDefault(t *testing.T) {
 
 func TestDebugTraceCoversRequestLifecycle(t *testing.T) {
 	var buf bytes.Buffer
-	client := newDebugServer(t, &buf)
+	client := newDebugServer(t, &buf, false)
 
 	if _, err := client.Search(context.Background(), map[string]string{"q": "x"}); err != nil {
 		t.Fatalf("unexpected error: %v", err)
@@ -73,10 +74,88 @@ func TestDebugTraceCoversRequestLifecycle(t *testing.T) {
 	}
 }
 
+// debugLine is the JSON form of one trace line.
+type debugLine struct {
+	Debug struct {
+		At      string         `json:"at"`
+		Elapsed float64        `json:"elapsed"`
+		Event   string         `json:"event"`
+		Data    map[string]any `json:"data"`
+	} `json:"debug"`
+}
+
+// parseDebugLines requires every line of out to be a {"debug":{...}} object.
+func parseDebugLines(t *testing.T, out string) []debugLine {
+	t.Helper()
+	var lines []debugLine
+	for _, raw := range strings.Split(strings.TrimSpace(out), "\n") {
+		var l debugLine
+		if err := json.Unmarshal([]byte(raw), &l); err != nil || l.Debug.Event == "" {
+			t.Fatalf("debug line is not a JSON debug object: %q (%v)", raw, err)
+		}
+		if _, err := time.Parse("2006-01-02T15:04:05.000Z", l.Debug.At); err != nil {
+			t.Errorf("bad timestamp %q: %v", l.Debug.At, err)
+		}
+		lines = append(lines, l)
+	}
+	return lines
+}
+
+func TestDebugJSONLinesStayParseable(t *testing.T) {
+	var buf bytes.Buffer
+	client := newDebugServer(t, &buf, true)
+
+	if _, err := client.Search(context.Background(), map[string]string{"q": "x"}); err != nil {
+		t.Fatalf("unexpected error: %v", err)
+	}
+	lines := parseDebugLines(t, buf.String())
+
+	events := make([]string, 0, len(lines))
+	for _, l := range lines {
+		events = append(events, l.Debug.Event)
+	}
+	joined := strings.Join(events, "\n")
+	for _, want := range []string{"GET http", "Request sent", "First response byte", "Response: HTTP/1.1 200 OK", "Body received: 11 bytes"} {
+		if !strings.Contains(joined, want) {
+			t.Errorf("events missing %q:\n%s", want, joined)
+		}
+	}
+	if strings.Contains(buf.String(), "secret_key") {
+		t.Errorf("JSON debug output must redact the API key:\n%s", buf.String())
+	}
+
+	// Headers travel as one structured event rather than one line each.
+	var sawHeaders, sawConn bool
+	for _, l := range lines {
+		if strings.HasPrefix(l.Debug.Event, "Response:") {
+			sawHeaders = true
+			headers, _ := l.Debug.Data["headers"].(map[string]any)
+			if headers["Serpapi-Search-Id"] != "abc123" {
+				t.Errorf("expected Serpapi-Search-Id in response data, got %v", l.Debug.Data)
+			}
+			if status, _ := l.Debug.Data["status"].(float64); status != 200 {
+				t.Errorf("expected status 200 in response data, got %v", l.Debug.Data["status"])
+			}
+		}
+		if strings.HasPrefix(l.Debug.Event, "Using connection:") {
+			sawConn = true
+			if l.Debug.Data["local"] == nil || l.Debug.Data["remote"] == nil {
+				t.Errorf("expected local/remote in connection data, got %v", l.Debug.Data)
+			}
+		}
+		if strings.HasPrefix(l.Debug.Event, "  ") {
+			t.Errorf("JSON mode should not emit indented header lines: %q", l.Debug.Event)
+		}
+	}
+	if !sawHeaders || !sawConn {
+		t.Errorf("expected Response and Using connection events, got:\n%s", joined)
+	}
+}
+
 func TestDebugTraceReportsTimeout(t *testing.T) {
 	var buf bytes.Buffer
 	client := newSlowServer(t, 5*time.Second, 50*time.Millisecond)
-	WithDebug(&buf)(client)
+	WithDebug(&buf, false)(client)
 
 	if _, err := client.Search(context.Background(), map[string]string{"q": "x"}); err == nil {
 		t.Fatal("expected timeout error")
@@ -95,7 +174,7 @@ func TestDebugTraceReportsTimeout(t *testing.T) {
 
 // newMetadataServer serves a search response whose created_at/processed_at
 // are stamped at request arrival, so the correlation line has real values.
-func newMetadataServer(t *testing.T, w *bytes.Buffer, processing time.Duration) *Client {
+func newMetadataServer(t *testing.T, w *bytes.Buffer, jsonLines bool, processing time.Duration) *Client {
 	t.Helper()
 	srv := newTestServer(t, func(rw http.ResponseWriter, r *http.Request) {
 		created := time.Now().UTC()
@@ -104,12 +183,12 @@ func newMetadataServer(t *testing.T, w *bytes.Buffer, processing time.Duration)
 		fmt.Fprintf(rw, `{"search_metadata":{"id":"abc123","status":"Success","created_at":%q,"processed_at":%q,"total_time_taken":%g}}`,
 			created.Format(searchMetadataTimeLayout), processed.Format(searchMetadataTimeLayout), processing.Seconds())
 	})
-	return New("secret_key", WithBaseURL(srv.URL), WithTimeout(10*time.Second), WithDebug(w))
+	return New("secret_key", WithBaseURL(srv.URL), WithTimeout(10*time.Second), WithDebug(w, jsonLines))
 }
 
 func TestDebugCorrelatesSearchMetadata(t *testing.T) {
 	var buf bytes.Buffer
-	client := newMetadataServer(t, &buf, 1*time.Second)
+	client := newMetadataServer(t, &buf, false, 1*time.Second)
 
 	if _, err := client.Search(context.Background(), map[string]string{"q": "x"}); err != nil {
 		t.Fatalf("unexpected error: %v", err)
@@ -131,6 +210,38 @@ func TestDebugCorrelatesSearchMetadata(t *testing.T) {
 	}
 }
 
+func TestDebugCorrelatesSearchMetadataAsJSON(t *testing.T) {
+	var buf bytes.Buffer
+	client := newMetadataServer(t, &buf, true, 1*time.Second)
+
+	if _, err := client.Search(context.Background(), map[string]string{"q": "x"}); err != nil {
+		t.Fatalf("unexpected error: %v", err)
+	}
+	var sawSearch, sawTimeline bool
+	for _, l := range parseDebugLines(t, buf.String()) {
+		switch {
+		case strings.HasPrefix(l.Debug.Event, "Server search:"):
+			sawSearch = true
+			if l.Debug.Data["id"] != "abc123" || l.Debug.Data["total_time_taken"] != 1.0 {
+				t.Errorf("unexpected search data: %v", l.Debug.Data)
+			}
+		case strings.HasPrefix(l.Debug.Event, "Server timeline:"):
+			sawTimeline = true
+			for _, key := range []string{"created_at", "processed_at", "sent_to_created_s", "processing_s", "processed_to_headers_s"} {
+				if _, ok := l.Debug.Data[key]; !ok {
+					t.Errorf("timeline data missing %q: %v", key, l.Debug.Data)
+				}
+			}
+			if l.Debug.Data["processing_s"] != 1.0 {
+				t.Errorf("expected processing_s=1, got %v", l.Debug.Data["processing_s"])
+			}
+		}
+	}
+	if !sawSearch || !sawTimeline {
+		t.Errorf("expected Server search and Server timeline events:\n%s", buf.String())
+	}
+}
+
 // stallTracer builds a tracer with a fixed client-side timeline and a body
 // whose server timestamps are offset from it, without any real waiting.
 func stallTracer(w *bytes.Buffer, preCreate, processing, postProcess time.Duration) (*tracer, []byte) {
@@ -189,13 +300,34 @@ func TestDebugNoStallNoteWhenServerProcessingDominates(t *testing.T) {
 	}
 }
 
+func TestDebugCachedResultIsNotCorrelated(t *testing.T) {
+	var buf bytes.Buffer
+	// The server created the search 26 minutes before we asked: a cache hit.
+	// Its timestamps describe the original search, so no stall note applies
+	// even though "headers after processed_at" is enormous. The round trip
+	// is firstByte - sent = (-26m + 1s + 26m + 0.8s) = 1.8s.
+	tr, body := stallTracer(&buf, -26*time.Minute, 1*time.Second, 26*time.Minute+800*time.Millisecond)
+	tr.logSearchMetadata(body)
+
+	out := buf.String()
+	if !strings.Contains(out, "Server timeline: cached result from 2026-10-09T11:34:00Z (1560s before this request)") {
+		t.Errorf("expected cached-result timeline:\n%s", out)
+	}
+	if !strings.Contains(out, "the +1.8s wait was network round trip only") {
+		t.Errorf("expected round-trip wait:\n%s", out)
+	}
+	if strings.Contains(out, "Note:") || strings.Contains(out, "after processed_at") {
+		t.Errorf("cached result must not produce a stall diagnosis:\n%s", out)
+	}
+}
+
 func TestDebugSearchMetadataUnparseableIsReported(t *testing.T) {
 	var buf bytes.Buffer
 	srv := newTestServer(t, func(rw http.ResponseWriter, r *http.Request) {
 		rw.Header().Set("Content-Type", "application/json")
 		_, _ = rw.Write([]byte(`{"search_metadata":{"id":"abc123","status":"Success","created_at":"soon","processed_at":"later","total_time_taken":0.5}}`))
 	})
-	client := New("k", WithBaseURL(srv.URL), WithTimeout(5*time.Second), WithDebug(&buf))
+	client := New("k", WithBaseURL(srv.URL), WithTimeout(5*time.Second), WithDebug(&buf, false))
 
 	if _, err := client.Search(context.Background(), map[string]string{"q": "x"}); err != nil {
 		t.Fatalf("unexpected error: %v", err)
@@ -211,7 +343,7 @@ func TestDebugSearchMetadataUnparseableIsReported(t *testing.T) {
 
 func TestDebugNoMetadataLineForNonSearchEndpoints(t *testing.T) {
 	var buf bytes.Buffer
-	client := newDebugServer(t, &buf)
+	client := newDebugServer(t, &buf, false)
 
 	if _, err := client.Account(context.Background()); err != nil {
 		t.Fatalf("unexpected error: %v", err)
diff --git a/pkg/cmd/root.go b/pkg/cmd/root.go
index b4e01c3..6b1ea50 100644
--- a/pkg/cmd/root.go
+++ b/pkg/cmd/root.go
@@ -83,7 +83,9 @@ invalid parameters; 401 invalid API key; 403 account not allowed; 429 rate
 limited or out of searches; 5xx SerpApi failed. No status means no usable
 answer: a network_error, such as a timeout, or an unreadable response.
 Requests time out after 60s: --timeout or SERPAPI_TIMEOUT sets seconds, 0
-waits indefinitely.
+waits indefinitely. --debug or SERPAPI_DEBUG=1 traces each request on stderr
+(DNS, connect, TLS, first byte, headers, server timeline): plain text on a
+terminal, otherwise one {"debug":{...}} JSON object per line.
 Exit 130, code interrupted: Ctrl-C or SIGTERM stopped it before it finished,
 after printing what had arrived.
 
@@ -239,7 +241,7 @@ func init() {
 		"HTTP request timeout in seconds, such as 120, or a duration, such as 2m; 0 waits indefinitely (default %d; env SERPAPI_TIMEOUT)",
 		int(api.DefaultTimeout/time.Second)))
 	pf.BoolVar(&debugFlag, "debug", false,
-		"trace each request on stderr: DNS, connect, TLS, first byte, headers and the server timeline (env SERPAPI_DEBUG=1)")
+		"trace each request on stderr: DNS, connect, TLS, first byte, headers and the server timeline; JSON lines off a terminal (env SERPAPI_DEBUG=1)")
 
 	rootCmd.PersistentPreRunE = validateGlobalFlags
 
@@ -360,7 +362,9 @@ func resolveAPIKey() (string, error) {
 func newClient(apiKey string) *api.Client {
 	opts := []api.Option{api.WithTimeout(requestTimeout)}
 	if debugRequests {
-		opts = append(opts, api.WithDebug(rootCmd.ErrOrStderr()))
+		// Off a terminal, stderr carries only JSON lines, so the trace does too.
+		stderr := rootCmd.ErrOrStderr()
+		opts = append(opts, api.WithDebug(stderr, !output.IsTerminal(stderr)))
 	}
 	return api.New(apiKey, append(opts, clientOptions...)...)
 }
diff --git a/pkg/cmd/root_test.go b/pkg/cmd/root_test.go
index 2492042..4100eb4 100644
--- a/pkg/cmd/root_test.go
+++ b/pkg/cmd/root_test.go
@@ -1,12 +1,17 @@
 package cmd
 
 import (
+	"encoding/json"
 	"errors"
+	"io"
+	"net/http"
+	"strings"
 	"testing"
 	"time"
 
 	"github.com/serpapi/serpapi-cli/pkg/api"
 	clierrors "github.com/serpapi/serpapi-cli/pkg/errors"
+	"github.com/serpapi/serpapi-cli/pkg/output"
 )
 
 func TestResolveDebug(t *testing.T) {
@@ -40,6 +45,134 @@ func TestResolveDebug(t *testing.T) {
 	}
 }
 
+const debugSearchBody = `{"search_metadata":{"id":"abc123","status":"Success","created_at":"2026-10-09 12:00:00 UTC","processed_at":"2026-10-09 12:00:01 UTC","total_time_taken":1},"organic_results":[]}`
+
+// TestDebugOffTerminalKeepsStderrJSONLines is the reviewer's case: scripts
+// and agents parse stderr line by line, so a piped --debug run must emit
+// only JSON objects there, and the result on stdout must be untouched.
+func TestDebugOffTerminalKeepsStderrJSONLines(t *testing.T) {
+	fakeAPI(t, respond(debugSearchBody))
+
+	res := execute(t, "", "--debug", "search", "engine=google", "q=coffee")
+
+	if res.code != 0 {
+		t.Fatalf("exit code = %d, want 0; stderr: %s", res.code, res.stderr)
+	}
+	var out map[string]any
+	if err := json.Unmarshal([]byte(res.stdout), &out); err != nil {
+		t.Fatalf("stdout is not JSON: %v\n%s", err, res.stdout)
+	}
+
+	lines := strings.Split(strings.TrimSpace(res.stderr), "\n")
+	if len(lines) < 5 {
+		t.Fatalf("expected a trace on stderr, got %d lines:\n%s", len(lines), res.stderr)
+	}
+	var events []string
+	for _, line := range lines {
+		var v struct {
+			Debug *struct {
+				At      string  `json:"at"`
+				Elapsed float64 `json:"elapsed"`
+				Event   string  `json:"event"`
+			} `json:"debug"`
+			Error   map[string]any `json:"error"`
+			Warning map[string]any `json:"warning"`
+		}
+		if err := json.Unmarshal([]byte(line), &v); err != nil || (v.Debug == nil && v.Error == nil && v.Warning == nil) {
+			t.Fatalf("stderr line is not a JSON debug, warning or error object: %q", line)
+		}
+		if v.Error != nil {
+			t.Fatalf("unexpected error on stderr: %v", v.Error)
+		}
+		if v.Debug != nil {
+			events = append(events, v.Debug.Event)
+		}
+	}
+	joined := strings.Join(events, "\n")
+	for _, want := range []string{"GET http", "Timeout: 60s", "Request sent", "Response: HTTP/1.1 200 OK", "Server search: id=abc123", "Server timeline:"} {
+		if !strings.Contains(joined, want) {
+			t.Errorf("trace missing %q:\n%s", want, joined)
+		}
+	}
+	if strings.Contains(res.stderr, "[debug]") {
+		t.Errorf("piped stderr must not carry plain-text debug lines:\n%s", res.stderr)
+	}
+}
+
+func TestDebugOnTerminalPrintsPlainText(t *testing.T) {
+	fakeAPI(t, respond(debugSearchBody))
+	isTerminal := output.IsTerminal
+	output.IsTerminal = func(io.Writer) bool { return true }
+	t.Cleanup(func() { output.IsTerminal = isTerminal })
+
+	res := execute(t, "", "--debug", "search", "engine=google", "q=coffee")
+
+	if res.code != 0 {
+		t.Fatalf("exit code = %d, want 0; stderr: %s", res.code, res.stderr)
+	}
+	for _, line := range strings.Split(strings.TrimSpace(res.stderr), "\n") {
+		if !strings.HasPrefix(line, "[debug] ") {
+			t.Errorf("terminal stderr line should be plain text, got %q", line)
+		}
+	}
+	if !strings.Contains(res.stderr, "Server timeline:") {
+		t.Errorf("expected server timeline in trace:\n%s", res.stderr)
+	}
+}
+
+func TestDebugEnvEnablesTrace(t *testing.T) {
+	fakeAPI(t, respond(debugSearchBody))
+	t.Setenv("SERPAPI_DEBUG", "1")
+
+	res := execute(t, "", "search", "engine=google", "q=coffee")
+
+	if res.code != 0 {
+		t.Fatalf("exit code = %d, want 0; stderr: %s", res.code, res.stderr)
+	}
+	if !strings.Contains(res.stderr, `"debug":`) {
+		t.Errorf("SERPAPI_DEBUG=1 should enable the trace:\n%s", res.stderr)
+	}
+}
+
+func TestNoDebugMeansNoTrace(t *testing.T) {
+	fakeAPI(t, respond(debugSearchBody))
+
+	res := execute(t, "", "search", "engine=google", "q=coffee")
+
+	wantWarnings(t, wantOK(t, res))
+	if strings.Contains(res.stderr, "debug") {
+		t.Errorf("stderr should be silent without --debug:\n%s", res.stderr)
+	}
+}
+
+func TestDebugTimeoutErrorStaysLastJSONLine(t *testing.T) {
+	fakeAPI(t, func(w http.ResponseWriter, r *http.Request) {
+		select {
+		case <-time.After(5 * time.Second):
+		case <-r.Context().Done():
+		}
+	})
+
+	res := execute(t, "", "--debug", "--timeout", "0.05", "search", "engine=google", "q=coffee")
+
+	if res.code != 1 {
+		t.Fatalf("exit code = %d, want 1; stderr: %s", res.code, res.stderr)
+	}
+	lines := strings.Split(strings.TrimSpace(res.stderr), "\n")
+	var last struct {
+		Error map[string]any `json:"error"`
+	}
+	if err := json.Unmarshal([]byte(lines[len(lines)-1]), &last); err != nil || last.Error == nil {
+		t.Fatalf("last stderr line should be the JSON error, got %q", lines[len(lines)-1])
+	}
+	if msg, _ := last.Error["message"].(string); !strings.Contains(msg, "--debug") || !strings.Contains(msg, "timed out") {
+		t.Errorf("timeout message should mention --debug: %q", msg)
+	}
+	if !strings.Contains(res.stderr, "Request failed:") {
+		t.Errorf("trace should report the failed request:\n%s", res.stderr)
+	}
+}
+
 func TestResolveTimeout(t *testing.T) {
 	tests := []struct {
 		name    string
diff --git a/tests/e2e_test.go b/tests/e2e_test.go
index 27b8ea8..64d170a 100644
--- a/tests/e2e_test.go
+++ b/tests/e2e_test.go
@@ -193,6 +193,43 @@ func TestSearchWithJQ(t *testing.T) {
 	}
 }
 
+// TestSearchDebugKeepsStderrJSON pipes stderr, as scripts and agents do, so
+// the --debug trace must arrive as {"debug":{...}} lines and leave stdout
+// untouched.
+func TestSearchDebugKeepsStderrJSON(t *testing.T) {
+	key := requireLive(t)
+	res := serpapi(t, "", "--api-key", key, "--debug", "--jq", ".search_metadata.id", "search", "engine=google", "q=coffee")
+	wantSuccess(t, res)
+	if id := strings.TrimSpace(res.stdout); id == "" || strings.Contains(id, "debug") {
+		t.Errorf("stdout should carry only the search ID, got %q", res.stdout)
+	}
+
+	var events []string
+	for _, line := range strings.Split(strings.TrimSpace(res.stderr), "\n") {
+		var v struct {
+			Debug *struct {
+				Event string `json:"event"`
+			} `json:"debug"`
+			Warning map[string]any `json:"warning"`
+		}
+		if err := json.Unmarshal([]byte(line), &v); err != nil || (v.Debug == nil && v.Warning == nil) {
+			t.Fatalf("stderr line is not a JSON debug or warning object: %q", line)
+		}
+		if v.Debug != nil {
+			events = append(events, v.Debug.Event)
+		}
+	}
+	joined := strings.Join(events, "\n")
+	for _, want := range []string{"GET https://serpapi.com/search.json?api_key=[REDACTED]", "TLS handshake done", "Request sent", "Response: HTTP/", "Server search: id="} {
+		if !strings.Contains(joined, want) {
+			t.Errorf("trace missing %q:\n%s", want, joined)
+		}
+	}
+	if strings.Contains(res.stderr, key) {
+		t.Error("trace leaked the API key")
+	}
+}
+
 func TestAccount(t *testing.T) {
 	key := requireLive(t)
 	res := serpapi(t, "", "--api-key", key, "account")

From b606c2953b19a45fdb73698fdce65867a87481c2 Mon Sep 17 00:00:00 2001
From: ilyazub <ilya@serpapi.com>
Date: Tue, 13 Oct 2026 14:57:13 +0200
Subject: [PATCH 5/7] [Debug] Redact the API key from every trace line

A response could carry the key back into the trace: a redirect's Location
echoing the query went into JSON lines unredacted, an encoded api_key%3D
got past redaction on a terminal too, and so did a header named after it.
The tracer now removes the client's key, plain or URL-encoded, from each
event and every name and value in its data. Of the 6 cases in the new test,
3 response shapes piped and on a terminal, 5 printed the key; now 0.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 pkg/api/debug.go     | 32 ++++++++++++++++++++++----
 pkg/cmd/root_test.go | 54 ++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 82 insertions(+), 4 deletions(-)

diff --git a/pkg/api/debug.go b/pkg/api/debug.go
index 5014f74..52219d9 100644
--- a/pkg/api/debug.go
+++ b/pkg/api/debug.go
@@ -7,6 +7,7 @@ import (
 	"io"
 	"net/http"
 	"net/http/httptrace"
+	"net/url"
 	"sort"
 	"strings"
 	"sync"
@@ -41,6 +42,7 @@ type debugEvent struct {
 type tracer struct {
 	w     io.Writer
 	json  bool
+	key   string
 	start time.Time
 	mu    sync.Mutex
 
@@ -54,7 +56,7 @@ func (c *Client) newTracer() *tracer {
 	if c.debug == nil {
 		return nil
 	}
-	return &tracer{w: c.debug, json: c.debugJSON, start: time.Now()}
+	return &tracer{w: c.debug, json: c.debugJSON, key: c.apiKey, start: time.Now()}
 }
 
 // logf writes one event with no structured data.
@@ -64,8 +66,8 @@ func (t *tracer) logf(format string, args ...any) {
 
 // log writes one event: wall-clock UTC time (to correlate with server-side
 // created_at/processed_at), seconds since the request started, and the
-// message with any api_key value redacted. data, if not nil, is included in
-// the JSON form only.
+// message, with the API key redacted from it and from data. data, if not nil,
+// is included in the JSON form only.
 func (t *tracer) log(data map[string]any, format string, args ...any) {
 	if t == nil {
 		return
@@ -73,7 +75,19 @@ func (t *tracer) log(data map[string]any, format string, args ...any) {
 	now := time.Now()
 	at := now.UTC().Format("2006-01-02T15:04:05.000Z")
 	elapsed := now.Sub(t.start).Seconds()
-	msg := clierrors.RedactAPIKey(fmt.Sprintf(format, args...))
+	msg := t.redact(fmt.Sprintf(format, args...))
+	for k, v := range data {
+		switch v := v.(type) {
+		case string:
+			data[k] = t.redact(v)
+		case map[string]string:
+			redacted := make(map[string]string, len(v))
+			for name, value := range v {
+				redacted[t.redact(name)] = t.redact(value)
+			}
+			data[k] = redacted
+		}
+	}
 
 	var line []byte
 	if t.json {
@@ -91,6 +105,16 @@ func (t *tracer) log(data map[string]any, format string, args ...any) {
 	_, _ = t.w.Write(line)
 }
 
+// redact replaces api_key values in s, and the key itself, plain or
+// URL-encoded: a header such as a redirect's Location can carry it anywhere.
+func (t *tracer) redact(s string) string {
+	s = clierrors.RedactAPIKey(s)
+	if t.key == "" {
+		return s
+	}
+	return strings.NewReplacer(t.key, "[REDACTED]", url.QueryEscape(t.key), "[REDACTED]").Replace(s)
+}
+
 func round3(f float64) float64 {
 	return float64(int64(f*1000+0.5)) / 1000
 }
diff --git a/pkg/cmd/root_test.go b/pkg/cmd/root_test.go
index 4100eb4..6c452d6 100644
--- a/pkg/cmd/root_test.go
+++ b/pkg/cmd/root_test.go
@@ -3,8 +3,10 @@ package cmd
 import (
 	"encoding/json"
 	"errors"
+	"fmt"
 	"io"
 	"net/http"
+	"net/url"
 	"strings"
 	"testing"
 	"time"
@@ -173,6 +175,58 @@ func TestDebugTimeoutErrorStaysLastJSONLine(t *testing.T) {
 	}
 }
 
+// TestDebugTraceNeverPrintsTheKey covers responses that carry the key back:
+// redirects the client refuses to follow, since the request URL carries it,
+// one echoing the query and a proxy's login page with the original URL
+// encoded in its own, and a header named after it.
+func TestDebugTraceNeverPrintsTheKey(t *testing.T) {
+	key := strings.Repeat("0123456789abcdef", 4)
+	responses := []struct {
+		name    string
+		headers func(r *http.Request) map[string]string
+	}{
+		{"echoed query", func(r *http.Request) map[string]string {
+			return map[string]string{"Location": "https://serpapi.com/search.json?" + r.URL.RawQuery}
+		}},
+		{"encoded in a login URL", func(r *http.Request) map[string]string {
+			return map[string]string{"Location": "https://proxy.example/login?origurl=" + url.QueryEscape("https://serpapi.com"+r.URL.RequestURI())}
+		}},
+		{"a header named after it", func(*http.Request) map[string]string { return map[string]string{"X-Echo-" + key: "1"} }},
+	}
+	for _, response := range responses {
+		for _, terminal := range []bool{false, true} {
+			t.Run(fmt.Sprintf("%s/terminal=%v", response.name, terminal), func(t *testing.T) {
+				fakeAPI(t, func(w http.ResponseWriter, r *http.Request) {
+					for name, value := range response.headers(r) {
+						w.Header().Set(name, value)
+					}
+					w.WriteHeader(http.StatusFound)
+				})
+				isTerminal := output.IsTerminal
+				output.IsTerminal = func(io.Writer) bool { return terminal }
+				t.Cleanup(func() { output.IsTerminal = isTerminal })
+
+				res := execute(t, "", "--api-key", key, "--debug", "search", "engine=google", "q=coffee")
+
+				if res.code != 1 {
+					t.Fatalf("exit code = %d, want 1; stderr: %s", res.code, res.stderr)
+				}
+				if n := strings.Count(res.stderr, key); n > 0 {
+					t.Errorf("stderr prints the API key %d times:\n%s", n, res.stderr)
+				}
+				if !strings.Contains(res.stderr, "Response: HTTP/1.1 302 Found") {
+					t.Errorf("trace should still show the response:\n%s", res.stderr)
+				}
+				for _, line := range strings.Split(strings.TrimSpace(res.stderr), "\n") {
+					if !terminal && !json.Valid([]byte(line)) {
+						t.Errorf("piped stderr line is not JSON: %q", line)
+					}
+				}
+			})
+		}
+	}
+}
+
 func TestResolveTimeout(t *testing.T) {
 	tests := []struct {
 		name    string

From e80918ff5eca2215f2b60153b237d55a1ed6f662 Mon Sep 17 00:00:00 2001
From: ilyazub <ilya@serpapi.com>
Date: Tue, 13 Oct 2026 14:58:38 +0200
Subject: [PATCH 6/7] [Debug] Say the timeline's verdicts assume the clocks
 agree

The server timeline compares this machine's clock with SerpApi's. With the
client 6s fast, a fresh 9s search read as a cached result whose wait "was
network round trip only"; 30s slow, a stall after processing was blamed on
the way there. The notes now name that assumption, a created_at before the
request may be a fast clock, and contradicting timestamps get no verdict.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 README.md             |  2 +-
 pkg/api/debug.go      | 27 ++++++++++++++++-----------
 pkg/api/debug_test.go | 29 +++++++++++++++++++++++++----
 3 files changed, 42 insertions(+), 16 deletions(-)

diff --git a/README.md b/README.md
index 5801dd7..e016ac8 100644
--- a/README.md
+++ b/README.md
@@ -140,7 +140,7 @@ Prints the CLI version, as `--version` does.
   {"debug":{"at":"2026-10-09T11:50:55.227Z","elapsed":0.955,"event":"Response: HTTP/2.0 200 OK","data":{"status":200,"proto":"HTTP/2.0","headers":{"Serpapi-Search-Id":"6ac8d51e..."}}}}
   {"debug":{"at":"2026-10-09T11:50:55.234Z","elapsed":0.962,"event":"Server timeline: ...","data":{"sent_to_created_s":0.0,"processing_s":0.0,"processed_to_headers_s":1.2}}}
   ```
-  Server timestamps have one-second resolution, so sub-second deltas in the timeline are noise. When the client waited noticeably longer than `total_time_taken`, a `Note:` event points at the phase that dominated. To send a trace along with a support request: `SERPAPI_DEBUG=1 serpapi search ... > result.json 2> trace.jsonl`.
+  Server timestamps have one-second resolution, so sub-second deltas in the timeline are noise. When the client waited noticeably longer than `total_time_taken`, a `Note:` event points at the phase that dominated, if this machine's clock agrees with SerpApi's: it says so, and names no phase when the timestamps contradict each other. To send a trace along with a support request: `SERPAPI_DEBUG=1 serpapi search ... > result.json 2> trace.jsonl`.
 
 ## Configuration
 
diff --git a/pkg/api/debug.go b/pkg/api/debug.go
index 52219d9..5d4adb4 100644
--- a/pkg/api/debug.go
+++ b/pkg/api/debug.go
@@ -248,7 +248,8 @@ func (t *tracer) logResponse(resp *http.Response) {
 const searchMetadataTimeLayout = "2006-01-02 15:04:05 MST"
 
 // logSearchMetadata correlates the server-side search_metadata timestamps
-// with the client-side timeline so a stall can be attributed to one of:
+// with the client-side timeline so a stall can be attributed, if this
+// machine's clock agrees with SerpApi's, to one of:
 //   - before the request reached the server (DNS, VPN, proxy, network path)
 //   - server processing (created_at -> processed_at)
 //   - after processing finished but before headers were sent
@@ -290,15 +291,15 @@ func (t *tracer) logSearchMetadata(body []byte) {
 	processing := processedAt.Sub(createdAt)
 	afterProcess := firstByteAt.Sub(processedAt)
 
-	// A search created well before this request was sent is a cached result:
-	// its timestamps describe the original search, not this round trip. 5s
-	// absorbs clock skew between client and server.
+	// A search created well before this request was sent is a cached result,
+	// whose timestamps describe the original search, or this machine's clock
+	// is that far ahead of SerpApi's; the timestamps can't tell which.
 	if beforeCreate < -5*time.Second {
 		t.log(map[string]any{
-			"created_at":   createdAt.Format(time.RFC3339),
-			"processed_at": processedAt.Format(time.RFC3339),
-			"cached":       true,
-		}, "Server timeline: cached result from %s (%.0fs before this request); the %s wait was network round trip only",
+			"created_at":        createdAt.Format(time.RFC3339),
+			"processed_at":      processedAt.Format(time.RFC3339),
+			"sent_to_created_s": round3(beforeCreate.Seconds()),
+		}, "Server timeline: created_at=%s, %.0fs before this request was sent: a cached result, or this machine's clock is ahead of SerpApi's; headers arrived %s after the request was sent",
 			createdAt.Format(time.RFC3339), (-beforeCreate).Seconds(), signedSeconds(firstByteAt.Sub(sentAt)))
 		return
 	}
@@ -315,17 +316,21 @@ func (t *tracer) logSearchMetadata(body []byte) {
 
 	// Flag the phase that dominated when the wait was noticeably longer than
 	// the server's own processing time. 2s absorbs the 1s timestamp
-	// resolution plus typical network latency.
+	// resolution plus typical network latency. The wait and the processing
+	// time each come from one clock; which phase the rest fell in compares
+	// the two, so a skewed clock moves it.
 	const slack = 2 * time.Second
 	waited := firstByteAt.Sub(sentAt)
 	if waited <= time.Duration(m.TotalTimeTaken*float64(time.Second))+slack {
 		return
 	}
 	switch {
+	case beforeCreate < -slack || afterProcess < -slack:
+		t.logf("Note: waited %s for a search SerpApi processed in %gs, but this machine's clock and SerpApi's disagree, so the timeline can't say where the rest went", signedSeconds(waited), m.TotalTimeTaken)
 	case beforeCreate > slack:
-		t.logf("Note: most of the wait (%s) happened before the request reached SerpApi; check the network path (DNS, VPN, proxy, connectivity)", signedSeconds(beforeCreate))
+		t.logf("Note: if this machine's clock matches SerpApi's, most of the wait (%s) happened before the request reached SerpApi; check the network path (DNS, VPN, proxy, connectivity)", signedSeconds(beforeCreate))
 	case afterProcess > slack:
-		t.logf("Note: the response took %s to arrive after SerpApi finished processing; check the network path back to this machine", signedSeconds(afterProcess))
+		t.logf("Note: if this machine's clock matches SerpApi's, the response took %s to arrive after SerpApi finished processing; check the network path back to this machine", signedSeconds(afterProcess))
 	}
 }
 
diff --git a/pkg/api/debug_test.go b/pkg/api/debug_test.go
index adaf1a8..817bc89 100644
--- a/pkg/api/debug_test.go
+++ b/pkg/api/debug_test.go
@@ -270,7 +270,7 @@ func TestDebugFlagsStallBeforeSearchCreation(t *testing.T) {
 	if !strings.Contains(out, "(+9.0s processing)") {
 		t.Errorf("expected 9s processing:\n%s", out)
 	}
-	if !strings.Contains(out, "Note: most of the wait (+21.0s) happened before the request reached SerpApi") {
+	if !strings.Contains(out, "Note: if this machine's clock matches SerpApi's, most of the wait (+21.0s) happened before the request reached SerpApi") {
 		t.Errorf("expected pre-creation stall note:\n%s", out)
 	}
 }
@@ -284,7 +284,7 @@ func TestDebugFlagsStallAfterProcessing(t *testing.T) {
 	if !strings.Contains(out, "headers received +15.0s after processed_at") {
 		t.Errorf("expected 15s post-processing gap:\n%s", out)
 	}
-	if !strings.Contains(out, "Note: the response took +15.0s to arrive after SerpApi finished processing") {
+	if !strings.Contains(out, "Note: if this machine's clock matches SerpApi's, the response took +15.0s to arrive after SerpApi finished processing") {
 		t.Errorf("expected post-processing stall note:\n%s", out)
 	}
 }
@@ -310,10 +310,10 @@ func TestDebugCachedResultIsNotCorrelated(t *testing.T) {
 	tr.logSearchMetadata(body)
 
 	out := buf.String()
-	if !strings.Contains(out, "Server timeline: cached result from 2026-10-09T11:34:00Z (1560s before this request)") {
+	if !strings.Contains(out, "Server timeline: created_at=2026-10-09T11:34:00Z, 1560s before this request was sent: a cached result, or this machine's clock is ahead of SerpApi's") {
 		t.Errorf("expected cached-result timeline:\n%s", out)
 	}
-	if !strings.Contains(out, "the +1.8s wait was network round trip only") {
+	if !strings.Contains(out, "headers arrived +1.8s after the request was sent") {
 		t.Errorf("expected round-trip wait:\n%s", out)
 	}
 	if strings.Contains(out, "Note:") || strings.Contains(out, "after processed_at") {
@@ -321,6 +321,27 @@ func TestDebugCachedResultIsNotCorrelated(t *testing.T) {
 	}
 }
 
+// The timeline compares this machine's clock with SerpApi's, so a skewed
+// clock must not come out as a verdict.
+func TestDebugTimelineWithSkewedClocks(t *testing.T) {
+	var buf bytes.Buffer
+	// A fresh search that took 9s, seen from a clock 6s ahead of SerpApi's.
+	tr, body := stallTracer(&buf, -6*time.Second, 9*time.Second, 6500*time.Millisecond)
+	tr.logSearchMetadata(body)
+	if out := buf.String(); strings.Contains(out, "round trip only") || !strings.Contains(out, "or this machine's clock is ahead of SerpApi's") {
+		t.Errorf("a clock 6s ahead must not pass for a cache hit:\n%s", out)
+	}
+
+	buf.Reset()
+	// A 15s stall after processing, seen from a clock 30s behind SerpApi's.
+	tr, body = stallTracer(&buf, 30*time.Second, 2*time.Second, -15*time.Second)
+	tr.logSearchMetadata(body)
+	if out := buf.String(); strings.Contains(out, "before the request reached SerpApi") ||
+		!strings.Contains(out, "Note: waited +17.0s for a search SerpApi processed in 2s, but this machine's clock and SerpApi's disagree") {
+		t.Errorf("timestamps that contradict each other must not blame one side:\n%s", out)
+	}
+}
+
 func TestDebugSearchMetadataUnparseableIsReported(t *testing.T) {
 	var buf bytes.Buffer
 	srv := newTestServer(t, func(rw http.ResponseWriter, r *http.Request) {

From 8e98b0ce6d8b40ac260fd136e35513c462a70d5c Mon Sep 17 00:00:00 2001
From: ilyazub <ilya@serpapi.com>
Date: Tue, 13 Oct 2026 14:59:52 +0200
Subject: [PATCH 7/7] [Debug] Keep main's timeout advice and point to --debug
 when it's off

The timeout error had swapped main's advice, that google_ai_mode and
no_cache=true can take longer than the timeout, for "usually a slow or
unstable network path", and suggested --debug even with --debug on. It
keeps main's advice, adds "--debug shows which step stalled" only while
the trace is off, and the README's --timeout example is AI Mode again.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
---
 README.md              |  6 +++---
 pkg/api/client.go      | 16 ++++++++++------
 pkg/api/client_test.go | 24 +++++++++++++++++++++---
 pkg/cmd/edge_test.go   |  2 +-
 pkg/cmd/root_test.go   |  4 ++--
 5 files changed, 37 insertions(+), 15 deletions(-)

diff --git a/README.md b/README.md
index e016ac8..71c549c 100644
--- a/README.md
+++ b/README.md
@@ -111,10 +111,10 @@ Prints the CLI version, as `--version` does.
 - `--jq <expr>`: [jq](https://jqlang.github.io/jq/manual/) filter applied to the JSON result, like `gh --jq`; strings print unquoted and `null` as an empty line, and results stream as they are produced. A filter that prints only `null` gets a warning listing the response's top-level keys. jq is built in, so nothing else needs installing. In bash and zsh, quote the expression with single quotes.
 - `--fields <expr>`: search only; see [search](#search).
 - `--api-key <key>`: API key. Prefer `SERPAPI_KEY`, since flags show up in `ps` and shell history.
-- `--timeout <seconds>`: HTTP request timeout in seconds, such as `120`, or a duration, such as `2m` (default `60`; env `SERPAPI_TIMEOUT`). `0` waits indefinitely. Raise it when a `network_error` says the request timed out and you are on a slow or unstable network path (VPN, proxy, high-latency connection); `--debug` shows where the time went. A timed-out search may still finish on SerpApi's side, count against your searches and be available in your search archive.
+- `--timeout <seconds>`: HTTP request timeout in seconds, such as `120`, or a duration, such as `2m` (default `60`; env `SERPAPI_TIMEOUT`). `0` waits indefinitely. Slow engines such as `google_ai_mode`, and searches with `no_cache=true`, can take longer than the default; raise it when a `network_error` says the request timed out, and add `--debug` to see which step stalled. A timed-out search may still finish on SerpApi's side, count against your searches and be available in your search archive.
   ```bash
-  # Allow up to two minutes for a single request
-  serpapi search --timeout 120 engine=google q="..."
+  # Give an AI Mode query up to two minutes
+  serpapi search --timeout 120 engine=google_ai_mode q="..."
 
   # Or set it once for the shell session
   export SERPAPI_TIMEOUT=120
diff --git a/pkg/api/client.go b/pkg/api/client.go
index 61acfcb..c5509ac 100644
--- a/pkg/api/client.go
+++ b/pkg/api/client.go
@@ -23,9 +23,9 @@ const (
 	// DefaultBaseURL is the SerpApi production endpoint.
 	DefaultBaseURL = "https://serpapi.com"
 	// DefaultTimeout bounds one HTTP request, including reading the response
-	// body. It matches the 60s default of the official serpapi-golang library
-	// and leaves headroom for slow or unreliable network paths. SerpApi still
-	// finishes and counts a search the client gave up on.
+	// body. It matches the 60s default of the official serpapi-golang library.
+	// Slow engines such as google_ai_mode can take longer with no_cache=true,
+	// and SerpApi still finishes and counts a search the client gave up on.
 	DefaultTimeout = 60 * time.Second
 )
 
@@ -152,11 +152,15 @@ func (c *Client) networkError(endpoint string, err error) error {
 	}
 	var netErr net.Error
 	if c.http.Timeout > 0 && (errors.Is(err, context.DeadlineExceeded) || (errors.As(err, &netErr) && netErr.Timeout())) {
+		debugHint := ""
+		if c.debug == nil {
+			debugHint = "; --debug shows which step stalled"
+		}
 		return &clierrors.NetworkError{
-			Message: fmt.Sprintf("Request to %s timed out after %s. This usually points to a slow or unstable network path (VPN, proxy, or connectivity issues): "+
-				"run with --debug to see where time was spent, or retry with a higher --timeout, such as --timeout %d, or 0 to wait indefinitely. "+
+			Message: fmt.Sprintf("Request to %s timed out after %s. Slow engines, such as google_ai_mode, and no_cache=true can take longer: "+
+				"retry with a higher --timeout, such as --timeout %d, or 0 to wait indefinitely%s. "+
 				"The search may still finish on SerpApi's side, count against your searches and be available in your search archive",
-				endpoint, seconds(c.http.Timeout), suggestedTimeout(c.http.Timeout)),
+				endpoint, seconds(c.http.Timeout), suggestedTimeout(c.http.Timeout), debugHint),
 			Cause: cause,
 		}
 	}
diff --git a/pkg/api/client_test.go b/pkg/api/client_test.go
index 958f4bc..9888b53 100644
--- a/pkg/api/client_test.go
+++ b/pkg/api/client_test.go
@@ -3,6 +3,7 @@ package api
 import (
 	"context"
 	"errors"
+	"io"
 	"net/http"
 	"net/http/httptest"
 	"net/url"
@@ -333,7 +334,7 @@ func TestNewUsesDefaultTimeout(t *testing.T) {
 		t.Fatalf("expected default timeout %s, got %s", DefaultTimeout, got)
 	}
 	if DefaultTimeout < 60*time.Second {
-		t.Fatalf("default timeout %s is shorter than the 60s used by the official serpapi-golang library", DefaultTimeout)
+		t.Fatalf("default timeout %s is too short for slow engines like google_ai_mode", DefaultTimeout)
 	}
 }
 
@@ -412,8 +413,8 @@ func TestOSTimeoutWithoutAClientLimit(t *testing.T) {
 // The advice names a --timeout above the one that just ran out.
 func TestTimeoutAdviceRaisesTheLimit(t *testing.T) {
 	for limit, want := range map[time.Duration]string{
-		50 * time.Millisecond: "timed out after 50ms. This usually points to a slow or unstable network path (VPN, proxy, or connectivity issues): run with --debug to see where time was spent, or retry with a higher --timeout, such as --timeout 120,",
-		60 * time.Second:      "timed out after 60s. This usually points to a slow or unstable network path (VPN, proxy, or connectivity issues): run with --debug to see where time was spent, or retry with a higher --timeout, such as --timeout 120,",
+		50 * time.Millisecond: "timed out after 50ms. Slow engines, such as google_ai_mode, and no_cache=true can take longer: retry with a higher --timeout, such as --timeout 120,",
+		60 * time.Second:      "timed out after 60s. Slow engines, such as google_ai_mode, and no_cache=true can take longer: retry with a higher --timeout, such as --timeout 120,",
 		120 * time.Second:     "--timeout 240,",
 		301 * time.Second:     "--timeout 602,",
 	} {
@@ -424,3 +425,20 @@ func TestTimeoutAdviceRaisesTheLimit(t *testing.T) {
 		}
 	}
 }
+
+// The timeout advice points to --debug only while the trace is off.
+func TestTimeoutAdvicePointsToDebugWhenItIsOff(t *testing.T) {
+	for _, debug := range []bool{false, true} {
+		c := New("secret", WithTimeout(time.Second))
+		if debug {
+			WithDebug(io.Discard, false)(c)
+		}
+		var netErr *clierrors.NetworkError
+		if err := c.networkError("/search.json", osTimeout{}); !errors.As(err, &netErr) {
+			t.Fatalf("debug %v: got %v, want a NetworkError", debug, err)
+		}
+		if suggests := strings.Contains(netErr.Message, "--debug shows which step stalled"); suggests == debug {
+			t.Errorf("debug %v: message %q", debug, netErr.Message)
+		}
+	}
+}
diff --git a/pkg/cmd/edge_test.go b/pkg/cmd/edge_test.go
index a3da6fb..8c29590 100644
--- a/pkg/cmd/edge_test.go
+++ b/pkg/cmd/edge_test.go
@@ -191,7 +191,7 @@ func edgeCases() []edgeCase {
 		{name: "response/no answer in time", args: []string{"account", "--timeout", "50ms"}, api: hang, exit: 1, code: "network_error",
 			msg: "Request to /account.json timed out after 50ms"},
 		{name: "response/SERPAPI_TIMEOUT applies", args: []string{"account"}, env: map[string]string{"SERPAPI_TIMEOUT": "0.05"}, api: hang, exit: 1,
-			code: "network_error", msg: "Request to /account.json timed out after 50ms. This usually points to a slow or unstable network path"},
+			code: "network_error", msg: "Request to /account.json timed out after 50ms. Slow engines, such as google_ai_mode"},
 
 		{name: "paging/foreign next host and key", args: searchWith("--all-pages"), api: func(w http.ResponseWriter, r *http.Request) {
 			if pageNumber(r) == 1 {
diff --git a/pkg/cmd/root_test.go b/pkg/cmd/root_test.go
index 6c452d6..6139a8e 100644
--- a/pkg/cmd/root_test.go
+++ b/pkg/cmd/root_test.go
@@ -167,8 +167,8 @@ func TestDebugTimeoutErrorStaysLastJSONLine(t *testing.T) {
 	if err := json.Unmarshal([]byte(lines[len(lines)-1]), &last); err != nil || last.Error == nil {
 		t.Fatalf("last stderr line should be the JSON error, got %q", lines[len(lines)-1])
 	}
-	if msg, _ := last.Error["message"].(string); !strings.Contains(msg, "--debug") || !strings.Contains(msg, "timed out") {
-		t.Errorf("timeout message should mention --debug: %q", msg)
+	if msg, _ := last.Error["message"].(string); strings.Contains(msg, "--debug") || !strings.Contains(msg, "timed out") {
+		t.Errorf("with --debug on, the timeout message shouldn't suggest it: %q", msg)
 	}
 	if !strings.Contains(res.stderr, "Request failed:") {
 		t.Errorf("trace should report the failed request:\n%s", res.stderr)