From 08e7de3f5882499edea9c33ec2dff55308d27743 Mon Sep 17 00:00:00 2001 From: benbenbang Date: Sun, 11 Oct 2026 10:58:32 +0800 Subject: [PATCH] feat(cli): classify MCP startup failures and add --verbose alias Add safe diagnostics for MCP startup so missing or malformed upstream API keys, unsupported providers, and client configuration errors are classified and surfaced with actionable guidance, without logging credential values or raw error causes. Validate the configured API key by trimming whitespace and rejecting non-printable characters so an invalid key is reported distinctly from a missing one, and ensure an explicit empty CLI key never falls back to an SDK environment key. Introduce a `--verbose` persistent flag as an alias for `--debug`. Either flag now enables debug-level logging and the diagnostic startup category; an explicit `--debug=false --verbose` still logs. Update the debug documentation to cover the alias and the new MCP startup failure guidance, and add tests exercising the initialization logging and the verbose alias behaviour. --- cmd/main_test.go | 26 ++++++++ docs/debug.md | 10 ++- internal/cli/debug.go | 10 ++- internal/cli/decide.go | 19 +++--- internal/cli/initialization.go | 56 ++++++++++++++++ internal/cli/mcp.go | 7 +- internal/cli/root.go | 3 +- internal/cli/verbose_test.go | 114 +++++++++++++++++++++++++++++++++ 8 files changed, 229 insertions(+), 16 deletions(-) create mode 100644 internal/cli/initialization.go create mode 100644 internal/cli/verbose_test.go diff --git a/cmd/main_test.go b/cmd/main_test.go index 8265067..b3b3060 100644 --- a/cmd/main_test.go +++ b/cmd/main_test.go @@ -25,3 +25,29 @@ func TestRunExitStatusAndStreams(t *testing.T) { } } } + +func TestRunMCPInitializationLogging(t *testing.T) { + t.Chdir(t.TempDir()) + t.Setenv("XDG_CONFIG_HOME", t.TempDir()) + t.Setenv("JEV_MCP_TOKEN", "private-agent-token") + for _, name := range []string{"JEV_API_KEY", "JEVWISE_API_KEY", "JEVWISE_MCP_TOKEN", "JEVWISE_MCP_AUTH_TOKEN", "TS_JEV_API_KEY", "TYPESAFE_API_KEY", "TS_JEV_BASE_URL", "TYPESAFE_BASE_URL", "TS_JEV_MODEL", "TYPESAFE_DEFAULT_MODEL", "TS_JEV_PROVIDER", "TS_JEV_TIMEOUT"} { + t.Setenv(name, "") + } + for _, flag := range []string{"", "--debug", "--verbose"} { + args := []string{"mcp"} + if flag != "" { + args = append(args, flag) + } + var out, stderr bytes.Buffer + if code := run(context.Background(), args, strings.NewReader(""), &out, &stderr); code != 1 || out.Len() != 0 { + t.Fatal("startup failure exit/stdout changed") + } + logs := stderr.String() + if !strings.Contains(logs, "API key is required") || !strings.Contains(logs, "docs/configuration.md") || !strings.Contains(logs, `"level":"error"`) || strings.Contains(logs, "private") { + t.Fatal("startup error lacked safe guidance") + } + if strings.Contains(logs, "service.initialize.api_key_missing") != (flag != "") { + t.Fatal("debug startup category not controlled by alias flags") + } + } +} diff --git a/docs/debug.md b/docs/debug.md index a05f80a..7961ded 100644 --- a/docs/debug.md +++ b/docs/debug.md @@ -7,10 +7,18 @@ ```sh jevwise --debug update --check jevwise --debug mcp +jevwise mcp --verbose # Same logging as --debug ``` -- Debug logging is opt-in via `--debug`, uses `github.com/phuslu/log`, and writes JSON to stderr. Normal stdout stays unchanged; logs can be redirected with `2>debug.log`. +- Debug logging is opt-in via `--debug` or its `--verbose` alias, uses `github.com/phuslu/log`, and writes JSON to stderr. Normal stdout stays unchanged; logs can be redirected with `2>debug.log`. - Covers command/stage outcomes and timing, config loading, API attempts/retries/status codes, release verification/replacement, skills, MCP requests/lifecycle and authenticated management. - Never logs credentials, prompts/options/results, user-supplied URLs/paths, raw headers/bodies, or raw error causes. Release checks may log their fixed public GitHub endpoint and strictly numeric rate-limit metadata. Treat timing/status diagnostics as operationally sensitive when sharing logs. - Detached background mode traces the launcher only; child output remains isolated. There is no persistent debug log file. Use foreground MCP for request diagnostics, then restart without `--debug` when finished. - Logging is best-effort. Write failures do not change operation results. No global logger or SDK configuration is changed. + +## MCP startup failures + +- Either flag enables diagnostics; `--debug=false --verbose` still logs. They are flags only, not config settings. No flag means no debug trace. +- Foreground startup logs classify missing/invalid upstream API keys, unsupported providers, client configuration errors and failed/empty factories, without showing values or raw causes. Known credential failures also print actionable errors without enabling debugging. +- Set a Jev API key through `TS_JEV_API_KEY`, `TYPESAFE_API_KEY` or TOML `api_key`. The separate MCP agent bearer token is not the upstream key; see [configuration](configuration.md) and [MCP credentials](mcp.md#credentials-state-and-safety). +- If neither flag is listed by `jevwise mcp --help`, check `jevwise version` and which binary is on PATH. Older published binaries may predate logging even when the current source supports it. For Homebrew-managed installs, use `brew upgrade jevwise` once a release containing these changes is available, not the standalone updater. diff --git a/internal/cli/debug.go b/internal/cli/debug.go index 93dfad5..c2343b2 100644 --- a/internal/cli/debug.go +++ b/internal/cli/debug.go @@ -14,7 +14,7 @@ func instrumentCommands(cmd *cobra.Command) { cmd.RunE = func(cmd *cobra.Command, args []string) (err error) { previous := cmd.Context() var writer io.Writer - if enabled, _ := cmd.Flags().GetBool("debug"); enabled { + if debugEnabled(cmd) { writer = cmd.ErrOrStderr() } cmd.SetContext(debuglog.WithWriter(previous, writer)) @@ -28,3 +28,11 @@ func instrumentCommands(cmd *cobra.Command) { instrumentCommands(child) } } + +// Either flag enables diagnostics; an explicit false never disables the other. +func debugEnabled(cmd *cobra.Command) bool { + flags := cmd.Root().PersistentFlags() + debug, _ := flags.GetBool("debug") + verbose, _ := flags.GetBool("verbose") + return debug || verbose +} diff --git a/internal/cli/decide.go b/internal/cli/decide.go index 6856f06..3e4eea0 100644 --- a/internal/cli/decide.go +++ b/internal/cli/decide.go @@ -5,6 +5,7 @@ import ( "encoding/json" "errors" "io" + "strings" "github.com/bitbrew-dev/jevwise/internal/config" "github.com/bitbrew-dev/jevwise/internal/debuglog" @@ -33,13 +34,18 @@ func defaultServiceFactory(cfg config.Config) (service.DecisionService, func(), return svc, nil, err } // An explicit empty CLI key must not fall back to an SDK environment key. - if cfg.APIKey == "" { - return nil, nil, errors.New("API key is required") + if strings.TrimSpace(cfg.APIKey) == "" { + return nil, nil, &initializationError{kind: "api_key_missing"} + } + for _, b := range []byte(strings.TrimSpace(cfg.APIKey)) { + if b < 0x21 || b > 0x7e { + return nil, nil, &initializationError{kind: "api_key_invalid"} + } } client, err := typesafe.NewClient(typesafe.ClientOptions{APIKey: cfg.APIKey, BaseURL: cfg.BaseURL, DefaultModel: cfg.Model, Timeout: cfg.Timeout}) if err != nil { - return nil, nil, err + return nil, nil, &initializationError{kind: "client_configuration", cause: err} } svc, err := service.New("jev", func(ctx context.Context, request typesafe.SystemOneRequest) (*typesafe.SystemOneResponse, error) { return client.SystemOne(ctx, request) @@ -104,11 +110,8 @@ func newDecide(factory ServiceFactory) *cobra.Command { if cleanup != nil { defer cleanup() } - if errors.Is(err, service.ErrNotImplemented) { - return &decisionError{"provider is not implemented", err} - } - if err != nil || svc == nil { - return &decisionError{"cannot initialize decision service", err} + if err != nil || !initializedMCPService(svc) { + return initializationFailure(ctx, "cannot initialize decision service", err) } if err := ctx.Err(); err != nil { return err diff --git a/internal/cli/initialization.go b/internal/cli/initialization.go new file mode 100644 index 0000000..8a8dc87 --- /dev/null +++ b/internal/cli/initialization.go @@ -0,0 +1,56 @@ +package cli + +import ( + "context" + "errors" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" + "github.com/bitbrew-dev/jevwise/internal/service" +) + +// Only trusted initialization failures get specific messages. Never expose factory errors. +type initializationError struct { + kind string + cause error +} + +func (e *initializationError) Error() string { + switch e.kind { + case "api_key_missing": + return "API key is required" + case "api_key_invalid": + return "API key must contain printable ASCII without whitespace; check the selected credential" + default: + return "cannot initialize Jev client: check base URL, model and timeout" + } +} +func (e *initializationError) Unwrap() error { return e.cause } + +func initializationFailure(ctx context.Context, fallback string, err error) error { + event, message := "service.initialize.factory_failed", fallback + var known *initializationError + switch { + case errors.Is(err, service.ErrNotImplemented): + event, message = "service.initialize.provider_unimplemented", "provider is not implemented" + case errors.As(err, &known) && known != nil: + message = known.Error() + // Do not put an unchecked kind, even from an injected factory, in logs. + switch known.kind { + case "api_key_missing": + event = "service.initialize.api_key_missing" + message += ": check the selected TOML api_key and its environment references, or set an upstream API-key environment variable (see docs/configuration.md)" + case "api_key_invalid": + event = "service.initialize.api_key_invalid" + default: + event = "service.initialize.client_configuration" + } + case err == nil: + event = "service.initialize.nil_service" + case errors.Is(err, context.Canceled): + event = "service.initialize.canceled" + case errors.Is(err, context.DeadlineExceeded): + event = "service.initialize.timeout" + } + debuglog.Event(ctx, event) + return &decisionError{message, err} +} diff --git a/internal/cli/mcp.go b/internal/cli/mcp.go index 9f45551..2fe619a 100644 --- a/internal/cli/mcp.go +++ b/internal/cli/mcp.go @@ -72,11 +72,8 @@ func newMCPWithBackground(factory ServiceFactory, run mcpRunner, start mcpStarte if cleanup != nil { defer cleanup() } - if errors.Is(err, service.ErrNotImplemented) { - return &decisionError{"provider is not implemented", err} - } - if err != nil || svc == nil { - return &decisionError{"cannot initialize MCP decision service", err} + if err != nil || !initializedMCPService(svc) { + return initializationFailure(ctx, "cannot initialize MCP decision service", err) } if err := ctx.Err(); err != nil { return err diff --git a/internal/cli/root.go b/internal/cli/root.go index b998c83..286167b 100644 --- a/internal/cli/root.go +++ b/internal/cli/root.go @@ -50,6 +50,7 @@ func NewRootWithFactory(factory ServiceFactory) *cobra.Command { cmd.Flags().BoolVar(&showVersion, "version", false, "Print version and build metadata") flags := cmd.PersistentFlags() flags.Bool("debug", false, "Write safe structured debug logs to stderr") + flags.Bool("verbose", false, "Alias for --debug: write safe structured debug logs to stderr") flags.String("config", "", "Path to TOML configuration") flags.String("provider", "jev", "Decision provider: jev, codex or claude") flags.String("api-key", "", "Jev API key (prefer environment or config)") @@ -88,7 +89,7 @@ func LoadConfig(cmd *cobra.Command) (_ config.Config, resultErr error) { // never credentials, prompt bodies, option content, or raw request/response bodies. func Logger(cmd *cobra.Command) log.Logger { level := log.InfoLevel - if enabled, _ := cmd.Root().PersistentFlags().GetBool("debug"); enabled { + if debugEnabled(cmd) { level = log.DebugLevel } return log.Logger{Level: level, Writer: log.IOWriter{Writer: cmd.ErrOrStderr()}} diff --git a/internal/cli/verbose_test.go b/internal/cli/verbose_test.go new file mode 100644 index 0000000..77bfbd3 --- /dev/null +++ b/internal/cli/verbose_test.go @@ -0,0 +1,114 @@ +package cli + +import ( + "context" + "errors" + "strings" + "testing" + + "github.com/bitbrew-dev/jevwise/internal/config" + "github.com/bitbrew-dev/jevwise/internal/service" +) + +func TestVerboseAliasAndExplicitFalse(t *testing.T) { + configEnvironment(t) + for _, tt := range []struct { + flags []string + enabled bool + }{ + {nil, false}, {[]string{"--debug"}, true}, {[]string{"--verbose"}, true}, + {[]string{"--debug=false", "--verbose"}, true}, {[]string{"--verbose", "--debug=false"}, true}, + {[]string{"--verbose=false", "--debug"}, true}, {[]string{"--debug", "--verbose=false"}, true}, + {[]string{"--debug=false", "--verbose=false"}, false}, + } { + for _, before := range []bool{false, true} { + cmd := NewRoot() + args := append([]string{"version"}, tt.flags...) + if before { + args = append(append([]string{}, tt.flags...), "version") + } + out, stderr, err := execute(cmd, args...) + if err != nil || !strings.Contains(out, "commit:") || (stderr != "") != tt.enabled || debugEnabled(cmd) != tt.enabled { + t.Fatal("alias flag semantics changed", args, err) + } + baseline := NewRoot() + _, _, _ = execute(baseline, "version", "--debug") + if (Logger(cmd).Level == Logger(baseline).Level) != tt.enabled { + t.Fatal("error logger disagrees with trace logger") + } + } + } + for _, args := range [][]string{{"--verbose", "--help"}, {"mcp", "--help", "--verbose"}, {"completion", "bash", "--verbose"}} { + if _, stderr, err := execute(NewRoot(), args...); err != nil || stderr != "" { + t.Fatal("lazy command logged or failed", err) + } + } + cmd := NewRoot() + _, _, _ = execute(cmd, "version", "--verbose") + if _, stderr, err := execute(cmd, "version", "--verbose=false"); err != nil || stderr != "" { + t.Fatal("alias leaked across invocations", err) + } + if _, stderr, err := execute(NewRoot(), "version"); err != nil || stderr != "" { + t.Fatal("alias leaked to another root", err) + } +} + +func TestMCPInitializationDiagnosticsAndPrivacy(t *testing.T) { + configEnvironment(t) + t.Setenv("JEV_MCP_TOKEN", "private-agent-token") + privateCause := errors.New("private-factory-error") + cases := []struct { + key, provider, event, message string + factory ServiceFactory + cause error + }{ + {"", "jev", "api_key_missing", "API key is required", nil, nil}, + {"private key", "jev", "api_key_invalid", "printable ASCII", nil, nil}, + {"private-秘密", "jev", "api_key_invalid", "printable ASCII", nil, nil}, + {"private-key", "codex", "provider_unimplemented", "provider is not implemented", nil, service.ErrNotImplemented}, + {"private-key", "jev", "factory_failed", "cannot initialize MCP", func(config.Config) (service.DecisionService, func(), error) { return nil, nil, privateCause }, privateCause}, + {"private-key", "jev", "nil_service", "cannot initialize MCP", func(config.Config) (service.DecisionService, func(), error) { + var svc *mcpFixture + return svc, nil, nil + }, nil}, + } + for _, tt := range cases { + for _, flag := range []string{"", "--debug", "--verbose"} { + cmd := NewRootWithFactory(tt.factory) + args := []string{"mcp", "--api-key", tt.key, "--provider", tt.provider} + if flag != "" { + args = append(args, flag) + } + out, stderr, err := execute(cmd, args...) + if err == nil || out != "" || !strings.Contains(err.Error(), tt.message) || (tt.cause != nil && !errors.Is(err, tt.cause)) { + t.Fatal("initialization failure unclear or cause lost", tt.event, err) + } + if strings.Contains(stderr+err.Error(), "private") { + t.Fatal("initialization diagnostics leaked credentials/cause") + } + if flag == "" && stderr != "" { + t.Fatal("default debugging enabled") + } + if flag != "" && (!strings.Contains(stderr, "service.initialize."+tt.event) || !strings.Contains(stderr, `"success":false`)) { + t.Fatal("initialization category or failure trace missing", tt.event) + } + } + } + // A URL accepted by config but rejected by the SDK must still be sanitized. + _, stderr, err := execute(NewRoot(), "mcp", "--verbose", "--api-key=private-key", "--base-url=https://private-host.example/?") + if err == nil || !strings.Contains(stderr, "service.initialize.client_configuration") || strings.Contains(stderr+err.Error(), "private") { + t.Fatal("client configuration failure leaked values or lacked diagnostics") + } + _, stderr, err = execute(NewRoot(), "decide", "--verbose", "--prompt=private-prompt", "--option=A", "--option=B") + if err == nil || !strings.Contains(err.Error(), "API key is required") || !strings.Contains(stderr, "service.initialize.api_key_missing") || strings.Contains(stderr, "private") { + t.Fatal("decision initialization did not share safe diagnostics") + } + // Context failures and arbitrary factories never expose raw errors. + for _, cause := range []error{context.Canceled, context.DeadlineExceeded} { + cmd := NewRootWithFactory(func(config.Config) (service.DecisionService, func(), error) { return nil, nil, cause }) + _, _, err := execute(cmd, "mcp", "--verbose") + if !errors.Is(err, cause) { + t.Fatal("cancellation identity lost") + } + } +}