diff --git a/README.md b/README.md index 9bf506c..71c549c 100644 --- a/README.md +++ b/README.md @@ -111,7 +111,7 @@ Prints the CLI version, as `--version` does. - `--jq `: [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 `: search only; see [search](#search). - `--api-key `: API key. Prefer `SERPAPI_KEY`, since flags show up in `ps` and shell history. -- `--timeout `: 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 `: 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 # Give an AI Mode query up to two minutes serpapi search --timeout 120 engine=google_ai_mode q="..." @@ -119,6 +119,28 @@ 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. 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 + [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 + ``` + 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, 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 @@ -145,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 0245e1d..c5509ac 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,10 @@ type Client struct { apiKey string baseURL string http *http.Client + + // debug, if set, receives a trace of each request; see WithDebug. + debug io.Writer + debugJSON bool } // Option configures a Client. @@ -82,6 +87,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} @@ -93,22 +104,31 @@ func (c *Client) get(ctx context.Context, endpoint string, params map[string]str } u.RawQuery = q.Encode() + 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)) @@ -132,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. 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%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, } } @@ -177,7 +201,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 } @@ -203,13 +231,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/client_test.go b/pkg/api/client_test.go index c2b0c55..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" @@ -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/api/debug.go b/pkg/api/debug.go new file mode 100644 index 0000000..5d4adb4 --- /dev/null +++ b/pkg/api/debug.go @@ -0,0 +1,341 @@ +package api + +import ( + "crypto/tls" + "encoding/json" + "fmt" + "io" + "net/http" + "net/http/httptrace" + "net/url" + "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, 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] +s ". 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 + key string + 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 { + if c.debug == nil { + return nil + } + return &tracer{w: c.debug, json: c.debugJSON, key: c.apiKey, start: time.Now()} +} + +// 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 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 + } + now := time.Now() + at := now.UTC().Format("2006-01-02T15:04:05.000Z") + elapsed := now.Sub(t.start).Seconds() + 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 { + 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() + _, _ = 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 +} + +// 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) { + 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() + } + } + data := map[string]any{"local": local, "remote": remote, "reused": info.Reused} + if info.Reused { + t.log(data, "Using connection: %s -> %s (reused, idle %s)", local, remote, info.IdleTime.Round(time.Millisecond)) + return + } + t.log(data, "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") + }, + } +} + +// 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. 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 + } + 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) + } + } +} + +// 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, 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 +// +// 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.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) + 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 + } + + 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, + // 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), + "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 + } + 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 + // 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: 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: 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)) + } +} + +// 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 new file mode 100644 index 0000000..817bc89 --- /dev/null +++ b/pkg/api/debug_test.go @@ -0,0 +1,375 @@ +package api + +import ( + "bytes" + "context" + "encoding/json" + "fmt" + "net/http" + "regexp" + "strings" + "testing" + "time" +) + +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, jsonLines)) +} + +func TestDebugDisabledByDefault(t *testing.T) { + var buf bytes.Buffer + 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) + } + 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, false) + + 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) + } + // 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) + } + } +} + +// 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, false)(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) + } +} + +// 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, jsonLines bool, 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, jsonLines)) +} + +func TestDebugCorrelatesSearchMetadata(t *testing.T) { + var buf bytes.Buffer + 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) + } + 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) + } +} + +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) { + 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: 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) + } +} + +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: 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) + } +} + +func TestDebugNoStallNoteWhenServerProcessingDominates(t *testing.T) { + var buf bytes.Buffer + // 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("long server processing should not be flagged as a client/network stall:\n%s", buf.String()) + } +} + +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: 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, "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") { + t.Errorf("cached result must not produce a stall diagnosis:\n%s", out) + } +} + +// 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) { + 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, false)) + + 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, false) + + 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 c3e980b..6b1ea50 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 @@ -78,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. @@ -233,6 +240,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, headers and the server timeline; JSON lines off a terminal (env SERPAPI_DEBUG=1)") rootCmd.PersistentPreRunE = validateGlobalFlags @@ -275,6 +284,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 +332,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 +360,22 @@ 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 { + // 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...)...) } // 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..6139a8e 100644 --- a/pkg/cmd/root_test.go +++ b/pkg/cmd/root_test.go @@ -1,14 +1,232 @@ package cmd import ( + "encoding/json" "errors" + "fmt" + "io" + "net/http" + "net/url" + "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) { + 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) + } + }) + } +} + +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("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) + } +} + +// 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 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")