diff --git a/README.md b/README.md index 5826397..f5da39a 100644 --- a/README.md +++ b/README.md @@ -127,6 +127,26 @@ serpapi login # Or set it once for the shell session export SERPAPI_TIMEOUT=120 ``` +- `--debug` — Print request tracing to 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`), and body size. Each line carries a UTC wall-clock timestamp and the elapsed time since the request started. For searches, the server's `search_metadata` timestamps are correlated against the client timeline 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. The API key is redacted. Stdout is unaffected, so `--jq` and piping still work. + ```bash + serpapi search --debug engine=google_ai_mode 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 + [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.314Z + 0.042s Connected: tcp 162.159.142.21:443 + [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 9a6d7ab..cc5e3eb 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" "time" @@ -30,6 +31,7 @@ type Client struct { baseURL string timeout time.Duration http *http.Client + debug io.Writer // nil unless SetDebugWriter was called } // New creates a new SerpApi client with DefaultTimeout. apiKey may be empty @@ -62,6 +64,12 @@ func (c *Client) userAgent() string { } func (c *Client) doGet(ctx context.Context, endpoint string, params map[string]string) ([]byte, error) { + return c.doGetTraced(ctx, endpoint, params, newTracer(c.debug)) +} + +// doGetTraced is doGet with a caller-supplied tracer, so callers can keep +// logging against the same timeline after the response is read. +func (c *Client) doGetTraced(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} @@ -73,25 +81,46 @@ func (c *Client) doGet(ctx context.Context, endpoint string, params map[string]s } u.RawQuery = q.Encode() + if tr != nil { + ctx = httptrace.WithClientTrace(ctx, tr.clientTrace()) + } + req, err := http.NewRequestWithContext(ctx, "GET", u.String(), nil) if err != nil { return nil, &clierrors.NetworkError{Message: err.Error(), Cause: err} } req.Header.Set("User-Agent", c.userAgent()) + if tr != nil { + tr.logf("GET %s", u.String()) + tr.logf("User-Agent: %s", c.userAgent()) + if c.timeout > 0 { + tr.logf("Timeout: %gs", c.timeout.Seconds()) + } else { + tr.logf("Timeout: disabled") + } + if proxyURL, perr := http.ProxyFromEnvironment(req); perr == nil && proxyURL != nil { + tr.logf("Proxy: %s", proxyURL.Redacted()) + } + } + resp, err := c.http.Do(req) if err != nil { + tr.logf("Request failed: %v", err) if c.isTimeout(req, err) { return nil, &clierrors.NetworkError{Message: c.timeoutMessage(), Cause: err} } return nil, &clierrors.NetworkError{Message: err.Error(), Cause: err} } defer resp.Body.Close() + tr.logResponse(resp) body, err := io.ReadAll(io.LimitReader(resp.Body, maxResponseBytes)) if err != nil { + tr.logf("Read body failed: %v", err) return nil, &clierrors.NetworkError{Message: "Failed to read response: " + err.Error(), Cause: err} } + tr.logf("Body received: %d bytes", len(body)) // Detect truncation: try reading one more byte; if it succeeds the body exceeded the limit. if len(body) == maxResponseBytes { var extra [1]byte @@ -145,7 +174,7 @@ func (c *Client) timeoutMessage() string { return fmt.Sprintf( "Request timed out after %gs waiting for SerpApi to respond. "+ "Slow engines (e.g. google_ai_mode) or no_cache=true can take longer; "+ - "retry with --timeout (0 to wait indefinitely). "+ + "retry with --timeout (0 to wait indefinitely), or run with --debug to see where time was spent. "+ "The search may still have completed server-side and be available in your SerpApi search archive.", c.timeout.Seconds(), ) @@ -172,13 +201,15 @@ func (c *Client) Search(ctx context.Context, params map[string]string) (json.Raw p["api_key"] = c.apiKey } - body, err := c.doGet(ctx, "/search.json", p) + tr := newTracer(c.debug) + body, err := c.doGetTraced(ctx, "/search.json", p, tr) if err != nil { return nil, err } if err := checkAPIError(body); err != nil { return nil, err } + tr.logSearchMetadata(body) return json.RawMessage(body), nil } diff --git a/pkg/api/debug.go b/pkg/api/debug.go new file mode 100644 index 0000000..1604ad6 --- /dev/null +++ b/pkg/api/debug.go @@ -0,0 +1,221 @@ +package api + +import ( + "crypto/tls" + "encoding/json" + "fmt" + "io" + "net/http" + "net/http/httptrace" + "sort" + "strings" + "sync" + "time" + + clierrors "github.com/serpapi/serpapi-cli/pkg/errors" +) + +// SetDebugWriter enables verbose request tracing (DNS, connect, TLS, first +// byte, status, headers) written to w. Pass nil to disable. +func (c *Client) SetDebugWriter(w io.Writer) { + 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 + + // Captured so the server-side search_metadata timestamps can be + // correlated with the client-side timeline afterwards. + sentAt time.Time + firstByteAt time.Time +} + +func newTracer(w io.Writer) *tracer { + if w == nil { + return nil + } + return &tracer{w: w, 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 doGet. +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() + } + } + if info.Reused { + t.logf("Using connection: %s -> %s (reused, idle %s)", local, remote, info.IdleTime.Round(time.Millisecond)) + return + } + 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") + }, + } +} + +// 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) + } + } +} + +// 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 new file mode 100644 index 0000000..5c6bc41 --- /dev/null +++ b/pkg/api/debug_test.go @@ -0,0 +1,236 @@ +package api + +import ( + "bytes" + "context" + "fmt" + "net/http" + "net/http/httptest" + "regexp" + "strings" + "testing" + "time" +) + +func newDebugServer(t *testing.T, w *bytes.Buffer) *Client { + t.Helper() + srv := httptest.NewServer(http.HandlerFunc(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}`)) + })) + t.Cleanup(srv.Close) + + client := NewWithTimeout("secret_key", 5*time.Second) + client.baseURL = srv.URL + client.SetDebugWriter(w) + return client +} + +func TestDebugDisabledByDefault(t *testing.T) { + var buf bytes.Buffer + client := newDebugServer(t, &buf) + client.SetDebugWriter(nil) + + 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) + } + // 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) + } + } +} + +func TestDebugTraceReportsTimeout(t *testing.T) { + var buf bytes.Buffer + client := newSlowServer(t, 5*time.Second, 50*time.Millisecond) + client.SetDebugWriter(&buf) + + 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, processing time.Duration) *Client { + t.Helper() + srv := httptest.NewServer(http.HandlerFunc(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()) + })) + t.Cleanup(srv.Close) + + client := NewWithTimeout("secret_key", 10*time.Second) + client.baseURL = srv.URL + client.SetDebugWriter(w) + return client +} + +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 := httptest.NewServer(http.HandlerFunc(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}}`)) + })) + t.Cleanup(srv.Close) + client := NewWithTimeout("k", 5*time.Second) + client.baseURL = srv.URL + client.SetDebugWriter(&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 41eb197..766769b 100644 --- a/pkg/cmd/root.go +++ b/pkg/cmd/root.go @@ -6,6 +6,7 @@ import ( "fmt" "os" "strconv" + "strings" "time" "github.com/spf13/cobra" @@ -24,6 +25,7 @@ var ( fieldsFlag string jqFlag string timeoutFlag string + debugFlag bool ) var rootCmd = &cobra.Command{ @@ -55,6 +57,8 @@ func init() { rootCmd.PersistentFlags().StringVar(&jqFlag, "jq", "", "Apply jq filter to output") rootCmd.PersistentFlags().StringVar(&timeoutFlag, "timeout", "", fmt.Sprintf("HTTP request timeout in seconds, 0 to disable (default %d; env: SERPAPI_TIMEOUT)", int(api.DefaultTimeout/time.Second))) + rootCmd.PersistentFlags().BoolVar(&debugFlag, "debug", false, + "Print request timing and connection details (DNS, TLS, first byte, headers) to stderr (env: SERPAPI_DEBUG=1)") // Wrap cobra flag-parsing errors as UsageError so they get exit code 2. rootCmd.SetFlagErrorFunc(func(_ *cobra.Command, err error) error { @@ -111,13 +115,39 @@ func parseTimeout(raw, source string) (time.Duration, error) { return time.Duration(secs * float64(time.Second)), nil } -// newClient builds an API client honoring the configured request timeout. +// debugEnabled reports whether --debug or SERPAPI_DEBUG is set. +func debugEnabled() bool { + if debugFlag { + return true + } + switch strings.ToLower(os.Getenv("SERPAPI_DEBUG")) { + case "", "0", "false", "no", "off": + return false + } + return true +} + +// newClient builds an API client honoring the configured request timeout +// and debug tracing. func newClient(apiKey string) (*api.Client, error) { timeout, err := resolveTimeout() if err != nil { return nil, err } - return api.NewWithTimeout(apiKey, timeout), nil + client := api.NewWithTimeout(apiKey, timeout) + if debugEnabled() { + client.SetDebugWriter(os.Stderr) + } + return client, nil +} + +// newSpinner creates a spinner with the given label. The spinner is disabled +// in debug mode so its redraws don't interleave with trace output. +func newSpinner(label string) *spinner.Spinner { + if debugEnabled() { + return &spinner.Spinner{} + } + return spinner.New(label) } // handleOutput applies --jq filtering and prints result. @@ -146,8 +176,3 @@ func handleOutput(raw json.RawMessage) error { } return nil } - -// newSpinner creates a spinner with the given label. -func newSpinner(label string) *spinner.Spinner { - return spinner.New(label) -} diff --git a/pkg/cmd/root_test.go b/pkg/cmd/root_test.go index 471af0a..2b33a87 100644 --- a/pkg/cmd/root_test.go +++ b/pkg/cmd/root_test.go @@ -9,6 +9,36 @@ import ( clierrors "github.com/serpapi/serpapi-cli/pkg/errors" ) +func TestDebugEnabled(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: "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 := debugEnabled(); got != tt.want { + t.Errorf("expected %v, got %v", tt.want, got) + } + }) + } +} + func TestResolveTimeout(t *testing.T) { tests := []struct { name string