diff --git a/CLAUDE.md b/CLAUDE.md index 900f2c9..8cd82a5 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -20,15 +20,20 @@ Unit tests pass ≠ feature works. The TUI has UI state that tests cannot cover. ## Mandatory Pre-Push Requirement -**Before any `git push`, run tests and linters locally. They MUST pass.** +**Before any `git push`, run ALL of the following locally. They MUST pass.** ```bash go test ./... # all tests must pass -golangci-lint run # linter must be clean +golangci-lint run # linter must be clean (matches CI config in .golangci.yml) +mise run build # binary must build ``` Equivalently: `mise run test:all` (runs lint + test + build). +CI runs `golangci-lint` v2 with `gocritic`, `gosec`, `errcheck`, and other strict +linters configured in `.golangci.yml`. If your local `golangci-lint` version is older, +it may miss issues that CI catches. Always verify lint passes before pushing. + Pushing code that breaks CI is unacceptable. No exceptions. ## Project diff --git a/cmd/root.go b/cmd/root.go index 4e0c386..f7e4fe9 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -12,11 +12,14 @@ import ( "github.com/gleanwork/glean-cli/internal/auth" gleanClient "github.com/gleanwork/glean-cli/internal/client" "github.com/gleanwork/glean-cli/internal/config" + "github.com/gleanwork/glean-cli/internal/debug" "github.com/gleanwork/glean-cli/internal/tui" "github.com/gleanwork/glean-cli/internal/update" "github.com/spf13/cobra" ) +var authErrLog = debug.New("auth:login") + // cliVersion is set at startup via SetVersion from the ldflags-injected build version. var cliVersion = "dev" @@ -49,7 +52,9 @@ func NewCmdRoot() *cobra.Command { Run 'glean --help' for other available commands. `), PersistentPreRun: func(cmd *cobra.Command, args []string) { - _ = verbosity // reserved for future debug logging + if verbosity > 0 { + debug.Enable() + } }, PersistentPostRun: func(cmd *cobra.Command, args []string) { // Skip update notice when the user is already running `glean update`. @@ -183,7 +188,10 @@ func authError(err error) error { fmt.Fprintf(os.Stderr, "Or set environment variables:\n") fmt.Fprintf(os.Stderr, " export GLEAN_HOST=your-company-be.glean.com\n") fmt.Fprintf(os.Stderr, " export GLEAN_API_TOKEN=your-token\n\n") - _ = err // underlying error logged above; don't expose internal message + authErrLog.Log("underlying auth error: %v", err) + if !authErrLog.Enabled() { + fmt.Fprintf(os.Stderr, " Tip: re-run with -v or GLEAN_DEBUG=auth:* for details\n\n") + } return errSilent } diff --git a/internal/auth/auth.go b/internal/auth/auth.go index 8301739..3afac78 100644 --- a/internal/auth/auth.go +++ b/internal/auth/auth.go @@ -16,12 +16,22 @@ import ( "github.com/coreos/go-oidc/v3/oidc" "github.com/gleanwork/glean-cli/internal/config" + "github.com/gleanwork/glean-cli/internal/debug" "github.com/gleanwork/glean-cli/internal/httputil" "github.com/int128/oauth2cli" "github.com/pkg/browser" "golang.org/x/oauth2" ) +var ( + loginLog = debug.New("auth:login") + hostLog = debug.New("auth:resolve-host") + discoveryLog = debug.New("auth:discovery") + dcrLog = debug.New("auth:dcr") + tokenLog = debug.New("auth:token") + emailLog = debug.New("auth:email") +) + //go:embed success.html var successHTML string @@ -29,16 +39,21 @@ var successHTML string // If the host is not configured, prompts for a work email and auto-discovers it. // If the instance doesn't support OAuth, falls back to an inline API token prompt. func Login(ctx context.Context) error { + loginLog.Log("starting login flow") + host, err := resolveHost(ctx) if err != nil { return err } + loginLog.Log("host resolved: %s", host) provider, endpoint, registrationEndpoint, err := discover(ctx, host) if err != nil { + loginLog.Log("OAuth discovery failed, falling back to API token: %v", err) fmt.Fprintf(os.Stderr, "\nOAuth discovery failed: %v\n", err) return promptForAPIToken(host) } + loginLog.Log("OAuth discovery succeeded: auth=%s token=%s registration=%s", endpoint.AuthURL, endpoint.TokenURL, registrationEndpoint) // Find a free port for the local callback server. // This must happen before DCR so we register the exact redirect URI @@ -57,6 +72,7 @@ func Login(ctx context.Context) error { verifier := oauth2.GenerateVerifier() scopes := resolveScopes(provider) + loginLog.Log("requesting scopes: %v", scopes) oauthCfg := oauth2.Config{ ClientID: clientID, @@ -223,19 +239,32 @@ func EnsureAuth(ctx context.Context) error { // a silent refresh and persists the new tokens before returning. func LoadOAuthToken(host string) string { tok, err := LoadTokens(host) - if err != nil || tok == nil { + if err != nil { + tokenLog.Log("load failed for %s: %v", host, err) + return "" + } + if tok == nil { + tokenLog.Log("no stored tokens for %s", host) return "" } if !tok.IsExpired() { + tokenLog.Log("token valid (expires %s)", tok.Expiry.Format("15:04:05")) return tok.AccessToken } + // Token expired — attempt silent refresh. - if tok.RefreshToken != "" && tok.TokenEndpoint != "" { - if refreshed, err := refreshOAuthToken(host, tok); err == nil { - return refreshed.AccessToken - } + if tok.RefreshToken == "" || tok.TokenEndpoint == "" { + tokenLog.Log("token expired, cannot refresh (refresh_token=%t endpoint=%t)", tok.RefreshToken != "", tok.TokenEndpoint != "") + return "" } - return "" + tokenLog.Log("token expired, refreshing via %s", tok.TokenEndpoint) + refreshed, err := refreshOAuthToken(host, tok) + if err != nil { + tokenLog.Log("refresh failed: %v", err) + return "" + } + tokenLog.Log("refreshed (new expiry=%s)", refreshed.Expiry.Format("15:04:05")) + return refreshed.AccessToken } // refreshOAuthToken exchanges a stored refresh_token for a new access token. @@ -243,8 +272,10 @@ func LoadOAuthToken(host string) string { func refreshOAuthToken(host string, tok *StoredTokens) (*StoredTokens, error) { cl, err := LoadClient(host) if err != nil || cl == nil { + tokenLog.Log("no stored OAuth client for %s (err=%v)", host, err) return nil, fmt.Errorf("no stored OAuth client for %s — re-run 'glean auth login'", host) } + tokenLog.Log("using stored client_id=%s for refresh", cl.ClientID) oauthCfg := oauth2.Config{ ClientID: cl.ClientID, @@ -279,7 +310,9 @@ func refreshOAuthToken(host string, tok *StoredTokens) (*StoredTokens, error) { TokenType: newTok.TokenType, TokenEndpoint: tok.TokenEndpoint, } - _ = SaveTokens(host, stored) + if err := SaveTokens(host, stored); err != nil { + tokenLog.Log("persisting refreshed tokens failed: %v", err) + } return stored, nil } @@ -289,8 +322,11 @@ func refreshOAuthToken(host string, tok *StoredTokens) (*StoredTokens, error) { func resolveHost(ctx context.Context) (string, error) { cfg, _ := config.LoadConfig() if cfg != nil && cfg.GleanHost != "" { - return config.NormalizeHost(cfg.GleanHost), nil + host := config.NormalizeHost(cfg.GleanHost) + hostLog.Log("using configured host: %s", host) + return host, nil } + hostLog.Log("no host configured, prompting for email") fmt.Print("Enter your work email: ") reader := bufio.NewReader(os.Stdin) @@ -301,6 +337,7 @@ func resolveHost(ctx context.Context) (string, error) { email = strings.TrimSpace(email) fmt.Print("Looking up your Glean instance…") + hostLog.Log("looking up backend for email domain") backendURL, err := LookupBackendURL(ctx, email) if err != nil { fmt.Println() @@ -311,8 +348,11 @@ func resolveHost(ctx context.Context) (string, error) { host := strings.TrimPrefix(backendURL, "https://") host = strings.TrimPrefix(host, "http://") host = strings.SplitN(host, "/", 2)[0] + hostLog.Log("discovered host: %s", host) - _ = config.SaveHostToFile(host) + if err := config.SaveHostToFile(host); err != nil { + hostLog.Log("best-effort host save failed: %v", err) + } return host, nil } @@ -328,16 +368,21 @@ func resolveHost(ctx context.Context) (string, error) { // provider is nil when only RFC 8414 discovery succeeded. func discover(ctx context.Context, host string) (*oidc.Provider, oauth2.Endpoint, string, error) { baseURL := "https://" + host + discoveryLog.Log("fetching protected resource metadata: %s", baseURL) meta, err := fetchProtectedResource(ctx, baseURL) if err != nil { + discoveryLog.Log("protected resource metadata failed: %v", err) return nil, oauth2.Endpoint{}, "", err } issuer := meta.AuthorizationServers[0] + discoveryLog.Log("authorization server: %s", issuer) // Try full OIDC discovery first (supports ID token, UserInfo). + discoveryLog.Log("trying OIDC discovery at %s", issuer) provider, err := oidc.NewProvider(ctx, issuer) if err == nil { + discoveryLog.Log("OIDC discovery succeeded") // Still need registration_endpoint, which oidc.Provider doesn't expose. authMeta, _ := fetchAuthServerMetadata(ctx, issuer) regEndpoint := "" @@ -346,6 +391,7 @@ func discover(ctx context.Context, host string) (*oidc.Provider, oauth2.Endpoint } return provider, provider.Endpoint(), regEndpoint, nil } + discoveryLog.Log("OIDC discovery failed: %v, falling back to RFC 8414", err) // Fall back to RFC 8414 auth server metadata. authMeta, err := fetchAuthServerMetadata(ctx, issuer) @@ -353,8 +399,10 @@ func discover(ctx context.Context, host string) (*oidc.Provider, oauth2.Endpoint return nil, oauth2.Endpoint{}, "", fmt.Errorf("OAuth discovery failed for %s: %w", issuer, err) } if authMeta.AuthorizationEndpoint == "" || authMeta.TokenEndpoint == "" { + discoveryLog.Log("RFC 8414 metadata incomplete: auth=%q token=%q", authMeta.AuthorizationEndpoint, authMeta.TokenEndpoint) return nil, oauth2.Endpoint{}, "", fmt.Errorf("OAuth metadata missing required endpoints for %s", issuer) } + discoveryLog.Log("RFC 8414 discovery succeeded: auth=%s token=%s", authMeta.AuthorizationEndpoint, authMeta.TokenEndpoint) return nil, oauth2.Endpoint{ AuthURL: authMeta.AuthorizationEndpoint, @@ -369,18 +417,25 @@ func discover(ctx context.Context, host string) (*oidc.Provider, oauth2.Endpoint // Falls back to a static client configured via glean config --oauth-client-id. func dcrOrStaticClient(ctx context.Context, host, registrationEndpoint, redirectURI string) (string, string, error) { if registrationEndpoint != "" { + dcrLog.Log("registering client at %s with redirect %s", registrationEndpoint, redirectURI) cl, err := registerClient(ctx, registrationEndpoint, redirectURI) if err == nil { - // Persist so future token refresh can use the same client credentials. - _ = SaveClient(host, cl) + dcrLog.Log("registered client_id=%s", cl.ClientID) + if err := SaveClient(host, cl); err != nil { + dcrLog.Log("persisting client registration failed: %v", err) + } return cl.ClientID, cl.ClientSecret, nil } // DCR failed — log and fall through to static client + dcrLog.Log("DCR failed: %v, trying static client", err) fmt.Printf("Note: dynamic client registration failed (%v), trying static client\n", err) + } else { + dcrLog.Log("no registration endpoint, trying static client") } cfg, _ := config.LoadConfig() if cfg != nil && cfg.OAuthClientID != "" { + dcrLog.Log("using static client_id=%s", cfg.OAuthClientID) return cfg.OAuthClientID, cfg.OAuthClientSecret, nil } @@ -443,6 +498,7 @@ func fetchAuthServerMetadata(ctx context.Context, issuer string) (*authServerMet } // RFC 8414 path-aware: origin + /.well-known/oauth-authorization-server + path u := parsed.Scheme + "://" + parsed.Host + "/.well-known/oauth-authorization-server" + parsed.Path + discoveryLog.Log("fetching RFC 8414 metadata: %s", u) req, err := http.NewRequestWithContext(ctx, http.MethodGet, u, nil) if err != nil { return nil, err @@ -481,6 +537,7 @@ func extractEmailFromToken(ctx context.Context, provider *oidc.Provider, clientI Email string `json:"email"` } if err := idToken.Claims(&claims); err == nil && claims.Email != "" { + emailLog.Log("email from OIDC ID token: %s", claims.Email) return claims.Email } } @@ -491,6 +548,7 @@ func extractEmailFromToken(ctx context.Context, provider *oidc.Provider, clientI Email string `json:"email"` } if err := ui.Claims(&claims); err == nil && claims.Email != "" { + emailLog.Log("email from UserInfo endpoint: %s", claims.Email) return claims.Email } } @@ -498,7 +556,13 @@ func extractEmailFromToken(ctx context.Context, provider *oidc.Provider, clientI // 2. Decode the access token as a JWT (no signature verification). // Glean issues JWT access tokens that contain the user's email claim. - return EmailFromJWT(token.AccessToken) + email := EmailFromJWT(token.AccessToken) + if email != "" { + emailLog.Log("email from JWT access token: %s", email) + } else { + emailLog.Log("could not extract email from token") + } + return email } // EmailFromJWT decodes a JWT payload (without verification) and returns the diff --git a/internal/auth/discovery.go b/internal/auth/discovery.go index 94b57f7..b512e17 100644 --- a/internal/auth/discovery.go +++ b/internal/auth/discovery.go @@ -30,6 +30,7 @@ type protectedResourceMetadata struct { // baseURL is the Glean backend root (e.g. "https://myco-be.glean.com"). func fetchProtectedResource(ctx context.Context, baseURL string) (*protectedResourceMetadata, error) { u := strings.TrimRight(baseURL, "/") + "/.well-known/oauth-protected-resource" + discoveryLog.Log("fetching protected resource: %s", u) req, err := http.NewRequestWithContext(ctx, http.MethodGet, u, nil) if err != nil { return nil, fmt.Errorf("building protected-resource request: %w", err) @@ -45,6 +46,7 @@ func fetchProtectedResource(ctx context.Context, baseURL string) (*protectedReso switch resp.StatusCode { case http.StatusOK: case http.StatusNotFound: + discoveryLog.Log("protected resource returned 404 — OAuth not supported") return nil, &ErrOAuthNotSupported{URL: u} default: return nil, fmt.Errorf("protected resource metadata returned HTTP %d", resp.StatusCode) @@ -57,6 +59,7 @@ func fetchProtectedResource(ctx context.Context, baseURL string) (*protectedReso if len(meta.AuthorizationServers) == 0 { return nil, fmt.Errorf("server returned OK but OAuth metadata is incomplete (no authorization_servers)") } + discoveryLog.Log("found %d authorization server(s): %v", len(meta.AuthorizationServers), meta.AuthorizationServers) return &meta, nil } @@ -88,6 +91,7 @@ func registerClient(ctx context.Context, registrationEndpoint, redirectURI strin defer resp.Body.Close() if resp.StatusCode != http.StatusCreated && resp.StatusCode != http.StatusOK { + dcrLog.Log("DCR returned HTTP %d", resp.StatusCode) return nil, fmt.Errorf("DCR returned HTTP %d", resp.StatusCode) } @@ -101,5 +105,6 @@ func registerClient(ctx context.Context, registrationEndpoint, redirectURI strin if result.ClientID == "" { return nil, fmt.Errorf("DCR response missing client_id") } + dcrLog.Log("DCR succeeded: client_id=%s", result.ClientID) return &StoredClient{ClientID: result.ClientID, ClientSecret: result.ClientSecret}, nil } diff --git a/internal/auth/domainlookup.go b/internal/auth/domainlookup.go index 70527a7..f03ce95 100644 --- a/internal/auth/domainlookup.go +++ b/internal/auth/domainlookup.go @@ -25,6 +25,7 @@ func lookupBackendURL(ctx context.Context, email, endpoint string) (string, erro if domain == "" { return "", fmt.Errorf("invalid email address: %q", email) } + hostLog.Log("domain lookup: domain=%s endpoint=%s", domain, endpoint) body := map[string]any{ "email": email, @@ -65,7 +66,9 @@ func lookupBackendURL(ctx context.Context, email, endpoint string) (string, erro return "", fmt.Errorf("no Glean instance found for domain %q", domain) } - return strings.TrimRight(result.SearchConfig.QueryURL, "/"), nil + backendURL := strings.TrimRight(result.SearchConfig.QueryURL, "/") + hostLog.Log("domain lookup resolved: %s", backendURL) + return backendURL, nil } func extractDomain(email string) string { diff --git a/internal/client/client.go b/internal/client/client.go index 8683e1e..c7395bc 100644 --- a/internal/client/client.go +++ b/internal/client/client.go @@ -11,9 +11,12 @@ import ( glean "github.com/gleanwork/api-client-go" "github.com/gleanwork/glean-cli/internal/auth" "github.com/gleanwork/glean-cli/internal/config" + "github.com/gleanwork/glean-cli/internal/debug" "github.com/gleanwork/glean-cli/internal/httputil" ) +var resolveLog = debug.New("client:resolve") + // authTypeOAuth is the X-Glean-Auth-Type header value required for External IdP OAuth tokens. const authTypeOAuth = "OAUTH" @@ -22,12 +25,15 @@ const authTypeOAuth = "OAUTH" // sourced from local storage return authTypeOAuth. func ResolveToken(cfg *config.Config) (token, authType string) { if cfg.GleanToken != "" { + resolveLog.Log("using API token from env/config") return cfg.GleanToken, "" } tok := auth.LoadOAuthToken(cfg.GleanHost) if tok != "" { + resolveLog.Log("using OAuth token for %s", cfg.GleanHost) return tok, authTypeOAuth } + resolveLog.Log("no credentials found") return "", "" } @@ -52,6 +58,7 @@ func New(cfg *config.Config) (*glean.Glean, error) { } instance := extractInstance(cfg.GleanHost) + resolveLog.Log("instance=%s authType=%s", instance, authType) opts := []glean.SDKOption{ glean.WithInstance(instance), diff --git a/internal/client/stream.go b/internal/client/stream.go index 73f05ca..9b5c9d9 100644 --- a/internal/client/stream.go +++ b/internal/client/stream.go @@ -11,9 +11,12 @@ import ( "github.com/gleanwork/api-client-go/models/components" "github.com/gleanwork/glean-cli/internal/config" + "github.com/gleanwork/glean-cli/internal/debug" "github.com/gleanwork/glean-cli/internal/httputil" ) +var streamLog = debug.New("stream:connect") + // streamTimeout is a generous timeout for long-running AUTO/ADVANCED agent // responses. Context cancellation (ctrl+c in the TUI) handles user-initiated // cancellation; this timeout is only a backstop for genuine network hangs. @@ -59,6 +62,7 @@ func StreamChat(ctx context.Context, cfg *config.Config, req components.ChatRequ } url := fmt.Sprintf("https://%s/rest/api/v1/chat", host) + streamLog.Log("POST %s (%d bytes)", url, len(payload)) httpReq, err := http.NewRequestWithContext(ctx, http.MethodPost, url, bytes.NewReader(payload)) if err != nil { return nil, fmt.Errorf("building request: %w", err) @@ -75,9 +79,11 @@ func StreamChat(ctx context.Context, cfg *config.Config, req components.ChatRequ return nil, fmt.Errorf("chat request failed: %w", err) } if resp.StatusCode != http.StatusOK { + streamLog.Log("chat request failed: HTTP %d (body discarded)", resp.StatusCode) resp.Body.Close() return nil, fmt.Errorf("chat request returned HTTP %d", resp.StatusCode) } + streamLog.Log("stream connected: HTTP %d", resp.StatusCode) return resp.Body, nil } diff --git a/internal/config/config.go b/internal/config/config.go index 963a5a8..9c98b0b 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -9,9 +9,15 @@ import ( "path/filepath" "strings" + "github.com/gleanwork/glean-cli/internal/debug" "github.com/zalando/go-keyring" ) +var ( + cfgLog = debug.New("config:load") + keyringLog = debug.New("config:keyring") +) + // keyringProvider defines operations for secure credential storage. type keyringProvider interface { Get(service, key string) (string, error) @@ -68,6 +74,7 @@ func ValidateAndTransformHost(host string) (string, error) { // 3. ~/.glean/config.json func LoadConfig() (*Config, error) { cfg := loadFromEnv() + cfgLog.Log("env: host=%t token=%t", cfg.GleanHost != "", cfg.GleanToken != "") if cfg.GleanHost == "" || cfg.GleanToken == "" { keyringCfg := loadFromKeyring() @@ -77,11 +84,13 @@ func LoadConfig() (*Config, error) { if cfg.GleanToken == "" { cfg.GleanToken = keyringCfg.GleanToken } + cfgLog.Log("after keyring: host=%t token=%t", cfg.GleanHost != "", cfg.GleanToken != "") } if cfg.GleanHost == "" || cfg.GleanToken == "" { fileCfg, err := loadFromFile() if err != nil { + cfgLog.Log("config file error: %v", err) return nil, err } if cfg.GleanHost == "" { @@ -96,8 +105,10 @@ func LoadConfig() (*Config, error) { if cfg.OAuthClientSecret == "" { cfg.OAuthClientSecret = fileCfg.OAuthClientSecret } + cfgLog.Log("after file: host=%t token=%t", cfg.GleanHost != "", cfg.GleanToken != "") } + cfgLog.Log("resolved host=%s token=%t", cfg.GleanHost, cfg.GleanToken != "") return cfg, nil } @@ -235,10 +246,14 @@ func loadFromKeyring() *Config { if host, err := keyringImpl.Get(ServiceName, hostKey); err == nil { cfg.GleanHost = host + } else { + keyringLog.Log("get %s: %v", hostKey, err) } if token, err := keyringImpl.Get(ServiceName, tokenKey); err == nil { cfg.GleanToken = token + } else { + keyringLog.Log("get %s: %v", tokenKey, err) } return cfg @@ -252,10 +267,12 @@ func loadFromFile() (*Config, error) { data, err := os.ReadFile(ConfigPath) if err != nil { if os.IsNotExist(err) { + cfgLog.Log("config file not found: %s", ConfigPath) return &Config{}, nil } return nil, fmt.Errorf("error reading config file: %w", err) } + cfgLog.Log("loaded config file: %s (%d bytes)", ConfigPath, len(data)) var cfg Config if err := json.Unmarshal(data, &cfg); err != nil { diff --git a/internal/debug/debug.go b/internal/debug/debug.go new file mode 100644 index 0000000..cb1d2a8 --- /dev/null +++ b/internal/debug/debug.go @@ -0,0 +1,167 @@ +// Package debug provides namespaced debug logging inspired by npm's debug package. +// +// Loggers are created with a namespace (e.g. "auth:token", "http:request") and +// write to stderr only when enabled. Enable via: +// +// - GLEAN_DEBUG env var with glob patterns: GLEAN_DEBUG=auth:* or GLEAN_DEBUG=* +// - Programmatically via Enable() (used by the --verbose flag) +// +// When disabled, Log is a near-zero-cost no-op (single atomic bool check). +package debug + +import ( + "fmt" + "hash/fnv" + "os" + "strings" + "sync" + "sync/atomic" + "time" + + "github.com/fatih/color" +) + +var ( + globalEnabled atomic.Bool + patterns []pattern + lastTime atomic.Int64 + mu sync.Mutex + maxNameLen atomic.Int32 + + palette = []*color.Color{ + color.New(color.FgCyan), + color.New(color.FgMagenta), + color.New(color.FgYellow), + color.New(color.FgGreen), + color.New(color.FgBlue), + color.New(color.FgRed), + } +) + +type pattern struct { + negate bool + prefix string // "auth:" for "auth:*", or full name for exact match + glob bool // true if pattern ends with * +} + +func init() { + raw := os.Getenv("GLEAN_DEBUG") + if raw == "" { + return + } + for p := range strings.SplitSeq(raw, ",") { + p = strings.TrimSpace(p) + if p == "" { + continue + } + pat := pattern{} + if strings.HasPrefix(p, "-") { + pat.negate = true + p = p[1:] + } + switch { + case p == "*": + pat.glob = true + pat.prefix = "" + case strings.HasSuffix(p, "*"): + pat.glob = true + pat.prefix = p[:len(p)-1] + default: + pat.prefix = p + } + patterns = append(patterns, pat) + } +} + +// Logger is a namespaced debug logger. The zero value is a disabled no-op logger. +type Logger struct { + namespace string + enabled bool + clr *color.Color +} + +// New creates a debug logger for the given namespace. +// The logger is enabled if GLEAN_DEBUG patterns match the namespace. +func New(namespace string) Logger { + if n := int32(len(namespace)); n > maxNameLen.Load() { + maxNameLen.Store(n) + } + return Logger{ + namespace: namespace, + enabled: matchesPatterns(namespace), + clr: pickColor(namespace), + } +} + +// Enable turns on all debug loggers globally. Called by --verbose flag handling. +// Loggers created before Enable() is called are retroactively activated. +func Enable() { + globalEnabled.Store(true) +} + +// Enabled reports whether this logger will produce output. +func (l Logger) Enabled() bool { + return l.enabled || globalEnabled.Load() +} + +// Log writes a debug message to stderr if this logger is enabled. +// Format and args follow fmt.Sprintf conventions. +func (l Logger) Log(format string, args ...any) { + if !l.enabled && !globalEnabled.Load() { + return + } + + now := time.Now() + prev := lastTime.Swap(now.UnixMilli()) + delta := time.Duration(0) + if prev > 0 { + delta = now.Sub(time.UnixMilli(prev)) + } + + msg := fmt.Sprintf(format, args...) + deltaStr := formatDelta(delta) + + mu.Lock() + defer mu.Unlock() + + padded := fmt.Sprintf("%-*s", maxNameLen.Load(), l.namespace) + ns := l.clr.Sprint(padded) + dt := l.clr.Sprint(deltaStr) + fmt.Fprintf(os.Stderr, " %s %s %s\n", ns, msg, dt) +} + +func matchesPatterns(namespace string) bool { + matched := false + for _, p := range patterns { + if p.matches(namespace) { + matched = !p.negate + } + } + return matched +} + +func (p pattern) matches(namespace string) bool { + if p.glob { + return strings.HasPrefix(namespace, p.prefix) + } + return namespace == p.prefix +} + +func pickColor(namespace string) *color.Color { + h := fnv.New32a() + h.Write([]byte(namespace)) + return palette[h.Sum32()%uint32(len(palette))] +} + +func formatDelta(d time.Duration) string { + switch { + case d < time.Millisecond: + return "+0ms" + case d < time.Second: + return fmt.Sprintf("+%dms", d.Milliseconds()) + case d < time.Minute: + return fmt.Sprintf("+%.1fs", d.Seconds()) + default: + return fmt.Sprintf("+%dm%ds", int(d.Minutes()), int(d.Seconds())%60) + } +} diff --git a/internal/debug/debug_test.go b/internal/debug/debug_test.go new file mode 100644 index 0000000..bb13600 --- /dev/null +++ b/internal/debug/debug_test.go @@ -0,0 +1,287 @@ +package debug + +import ( + "bytes" + "fmt" + "os" + "strings" + "sync" + "sync/atomic" + "testing" + "time" +) + +// resetState clears global state between tests. +func resetState(t *testing.T) { + t.Helper() + patterns = nil + globalEnabled.Store(false) + lastTime.Store(0) + maxNameLen.Store(0) +} + +func TestMatchesPatterns_Wildcard(t *testing.T) { + resetState(t) + patterns = []pattern{{glob: true, prefix: ""}} // "*" + + if !matchesPatterns("auth:token") { + t.Error("wildcard should match auth:token") + } + if !matchesPatterns("http:request") { + t.Error("wildcard should match http:request") + } +} + +func TestMatchesPatterns_PrefixGlob(t *testing.T) { + resetState(t) + patterns = []pattern{{glob: true, prefix: "auth:"}} // "auth:*" + + if !matchesPatterns("auth:token") { + t.Error("auth:* should match auth:token") + } + if !matchesPatterns("auth:discovery") { + t.Error("auth:* should match auth:discovery") + } + if matchesPatterns("http:request") { + t.Error("auth:* should not match http:request") + } +} + +func TestMatchesPatterns_Exact(t *testing.T) { + resetState(t) + patterns = []pattern{{prefix: "auth:token"}} // "auth:token" + + if !matchesPatterns("auth:token") { + t.Error("exact pattern should match auth:token") + } + if matchesPatterns("auth:discovery") { + t.Error("exact pattern should not match auth:discovery") + } +} + +func TestMatchesPatterns_Negation(t *testing.T) { + resetState(t) + // "*,-http:*" — everything except http namespaces + patterns = []pattern{ + {glob: true, prefix: ""}, + {glob: true, prefix: "http:", negate: true}, + } + + if !matchesPatterns("auth:token") { + t.Error("should match auth:token") + } + if matchesPatterns("http:request") { + t.Error("should not match http:request (negated)") + } +} + +func TestMatchesPatterns_CommaSeparated(t *testing.T) { + resetState(t) + // "auth:token,auth:discovery" + patterns = []pattern{ + {prefix: "auth:token"}, + {prefix: "auth:discovery"}, + } + + if !matchesPatterns("auth:token") { + t.Error("should match auth:token") + } + if !matchesPatterns("auth:discovery") { + t.Error("should match auth:discovery") + } + if matchesPatterns("auth:dcr") { + t.Error("should not match auth:dcr") + } +} + +func TestMatchesPatterns_Empty(t *testing.T) { + resetState(t) + patterns = nil + + if matchesPatterns("auth:token") { + t.Error("empty patterns should match nothing") + } +} + +func TestEnable_RetroactiveActivation(t *testing.T) { + resetState(t) + // No patterns set — logger starts disabled + l := New("auth:token") + if l.Enabled() { + t.Error("logger should be disabled before Enable()") + } + + Enable() + if !l.Enabled() { + t.Error("logger should be enabled after Enable()") + } +} + +func TestLog_DisabledProducesNoOutput(t *testing.T) { + resetState(t) + + // Capture stderr + old := os.Stderr + r, w, _ := os.Pipe() + os.Stderr = w + + l := New("auth:token") + l.Log("should not appear") + + w.Close() + var buf bytes.Buffer + buf.ReadFrom(r) + os.Stderr = old + + if buf.Len() > 0 { + t.Errorf("disabled logger should produce no output, got: %s", buf.String()) + } +} + +func TestLog_EnabledProducesOutput(t *testing.T) { + resetState(t) + patterns = []pattern{{glob: true, prefix: ""}} // "*" + + old := os.Stderr + r, w, _ := os.Pipe() + os.Stderr = w + + l := New("auth:token") + l.Log("hello %s", "world") + + w.Close() + var buf bytes.Buffer + buf.ReadFrom(r) + os.Stderr = old + + output := buf.String() + if !strings.Contains(output, "auth:token") { + t.Errorf("output should contain namespace, got: %s", output) + } + if !strings.Contains(output, "hello world") { + t.Errorf("output should contain message, got: %s", output) + } + if !strings.Contains(output, "+") { + t.Errorf("output should contain time delta, got: %s", output) + } +} + +func TestLog_GlobalEnableProducesOutput(t *testing.T) { + resetState(t) + // No patterns, but Enable() is called + + old := os.Stderr + r, w, _ := os.Pipe() + os.Stderr = w + + l := New("http:request") + Enable() + l.Log("GET https://example.com") + + w.Close() + var buf bytes.Buffer + buf.ReadFrom(r) + os.Stderr = old + + output := buf.String() + if !strings.Contains(output, "http:request") { + t.Errorf("output should contain namespace, got: %s", output) + } + if !strings.Contains(output, "GET https://example.com") { + t.Errorf("output should contain message, got: %s", output) + } +} + +func TestFormatDelta(t *testing.T) { + tests := []struct { + input string + expected string + }{ + {"0ms", "+0ms"}, + {"500µs", "+0ms"}, + {"150ms", "+150ms"}, + {"1.5s", "+1.5s"}, + {"90s", "+1m30s"}, + } + for _, tt := range tests { + t.Run(tt.input, func(t *testing.T) { + d, err := parseDuration(tt.input) + if err != nil { + t.Fatalf("bad test input: %v", err) + } + got := formatDelta(d) + if got != tt.expected { + t.Errorf("formatDelta(%v) = %q, want %q", d, got, tt.expected) + } + }) + } +} + +// parseDuration is a test helper that wraps time.ParseDuration with support +// for the "ms" suffix that time.ParseDuration already handles. +func parseDuration(s string) (time.Duration, error) { + return time.ParseDuration(s) +} + +func TestPickColor_Deterministic(t *testing.T) { + c1 := pickColor("auth:token") + c2 := pickColor("auth:token") + if fmt.Sprintf("%p", c1) != fmt.Sprintf("%p", c2) { + t.Error("pickColor should return the same color for the same namespace") + } +} + +func TestLog_ConcurrentSafety(t *testing.T) { + resetState(t) + patterns = []pattern{{glob: true, prefix: ""}} + + old := os.Stderr + _, w, _ := os.Pipe() + os.Stderr = w + + l := New("test:concurrent") + var wg sync.WaitGroup + for i := range 100 { + wg.Add(1) + go func(n int) { + defer wg.Done() + l.Log("message %d", n) + }(i) + } + wg.Wait() + + w.Close() + os.Stderr = old + // Test passes if no data races (run with -race) +} + +func TestNew_TracksMaxNameLen(t *testing.T) { + resetState(t) + New("a") + if got := maxNameLen.Load(); got != 1 { + t.Errorf("maxNameLen = %d, want 1", got) + } + New("auth:discovery") + if got := maxNameLen.Load(); got != 14 { + t.Errorf("maxNameLen = %d, want 14", got) + } + // Shorter name should not reduce maxNameLen + New("b") + if got := maxNameLen.Load(); got != 14 { + t.Errorf("maxNameLen = %d, want 14 (should not shrink)", got) + } +} + +func BenchmarkLog_Disabled(b *testing.B) { + // Reset state to ensure no patterns + patterns = nil + globalEnabled.Store(false) + var a atomic.Bool + _ = a.Load() // warm up + + l := New("bench:disabled") + b.ResetTimer() + for b.Loop() { + l.Log("message") + } +} diff --git a/internal/httputil/httputil.go b/internal/httputil/httputil.go index 56f73d0..9dd9034 100644 --- a/internal/httputil/httputil.go +++ b/internal/httputil/httputil.go @@ -3,6 +3,8 @@ package httputil import ( "net/http" "time" + + "github.com/gleanwork/glean-cli/internal/debug" ) // cliVersion is set at startup via SetVersion. Defaults to "dev" for local builds. @@ -34,13 +36,29 @@ type cliTransport struct { extraHeaders map[string]string } +var ( + reqLog = debug.New("http:request") + resLog = debug.New("http:response") +) + func (t *cliTransport) RoundTrip(req *http.Request) (*http.Response, error) { req = req.Clone(req.Context()) req.Header.Set("User-Agent", "glean-cli/"+cliVersion) for k, v := range t.extraHeaders { req.Header.Set(k, v) } - return t.base.RoundTrip(req) + + reqLog.Log("%s %s", req.Method, req.URL.String()) + + start := time.Now() + resp, err := t.base.RoundTrip(req) + if err != nil { + resLog.Log("%s %s error: %v (%s)", req.Method, req.URL.String(), err, time.Since(start).Round(time.Millisecond)) + return nil, err + } + + resLog.Log("%d %s (%s)", resp.StatusCode, http.StatusText(resp.StatusCode), time.Since(start).Round(time.Millisecond)) + return resp, nil } // NewTransport returns an http.RoundTripper that injects the CLI User-Agent diff --git a/internal/tui/model.go b/internal/tui/model.go index f9d23b2..258b8ba 100644 --- a/internal/tui/model.go +++ b/internal/tui/model.go @@ -21,6 +21,12 @@ import ( "github.com/gleanwork/api-client-go/models/components" "github.com/gleanwork/glean-cli/internal/client" "github.com/gleanwork/glean-cli/internal/config" + "github.com/gleanwork/glean-cli/internal/debug" +) + +var ( + tuiLog = debug.New("tui:init") + parseLog = debug.New("stream:parse") ) const ( @@ -131,7 +137,10 @@ func New(cfg *config.Config, session *Session, identity, version string, ctx con renderer, err := newGlamourRenderer(100) if err != nil { + tuiLog.Log("glamour renderer failed: %v (markdown rendering disabled)", err) renderer = nil + } else { + tuiLog.Log("glamour renderer initialized") } m := &Model{ @@ -151,6 +160,7 @@ func New(cfg *config.Config, session *Session, identity, version string, ctx con mouseEnabled: true, } + tuiLog.Log("session: %d prior turns", len(session.Turns)) for _, turn := range session.Turns { m.addTurnToConversation(turn) } @@ -583,13 +593,20 @@ func (m *Model) callAPI() tea.Cmd { seen := map[string]bool{} scanner := bufio.NewScanner(body) + lineNum := 0 for scanner.Scan() { line := strings.TrimSpace(scanner.Text()) + lineNum++ if line == "" || line == "[DONE]" { continue } var resp components.ChatResponse if err := json.Unmarshal([]byte(line), &resp); err != nil { + preview := line + if len(preview) > 100 { + preview = preview[:100] + "…" + } + parseLog.Log("skipped malformed line %d: %v (%.100s)", lineNum, err, preview) continue } if resp.ChatID != nil && returnedChatID == nil { @@ -641,9 +658,11 @@ func (m *Model) callAPI() tea.Cmd { } } if err := scanner.Err(); err != nil { + parseLog.Log("scanner error after %d lines: %v", lineNum, err) ch <- streamCompleteMsg{err: err} return } + parseLog.Log("stream complete: %d lines processed", lineNum) elapsed := time.Since(start).Round(time.Second) elapsedStr := fmt.Sprintf("%ds", int(elapsed.Seconds())) diff --git a/internal/tui/session.go b/internal/tui/session.go index 0421456..e713763 100644 --- a/internal/tui/session.go +++ b/internal/tui/session.go @@ -6,8 +6,12 @@ import ( "fmt" "os" "path/filepath" + + "github.com/gleanwork/glean-cli/internal/debug" ) +var sessionLog = debug.New("session:persist") + // Turn holds one exchange in the conversation history. type Turn struct { Role string `json:"role"` // "user" or "assistant" @@ -41,17 +45,21 @@ func sessionsDir() (string, error) { func LoadLatest() *Session { dir, err := sessionsDir() if err != nil { + sessionLog.Log("load: sessions dir error: %v", err) return &Session{} } path := filepath.Join(dir, "latest.json") data, err := os.ReadFile(path) if err != nil { + sessionLog.Log("load: %v", err) return &Session{} } var s Session if err := json.Unmarshal(data, &s); err != nil { + sessionLog.Log("load: parse error: %v", err) return &Session{} } + sessionLog.Log("loaded %d turns from %s", len(s.Turns), path) return &s } @@ -80,5 +88,7 @@ func (s *Session) AddTurn(role, content string, sources []Source) { // to the session and saves immediately. func (s *Session) AppendTurn(turn Turn) { s.Turns = append(s.Turns, turn) - _ = s.Save() // best-effort + if err := s.Save(); err != nil { + sessionLog.Log("save failed: %v", err) + } }