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") + } + } +}