From 9b5650db3a3a3db78db6fba8123d7247ea4a93a8 Mon Sep 17 00:00:00 2001 From: benbenbang Date: Fri, 9 Oct 2026 18:34:51 +0800 Subject: [PATCH 1/2] feat(logging): add opt-in structured debug logging Add a `--debug` flag that emits safe JSON diagnostics to stderr without changing normal command output or operation results. Instrument configuration, API retries and responses, updates, skill installation, MCP lifecycle and requests, and authenticated management with stage outcomes, status codes, and timing while excluding credentials, prompts, URLs, paths, headers, bodies, and raw errors. Update the README and add coverage for the logging and CLI behavior. --- README.md | 13 ++++++ internal/cli/config.go | 3 ++ internal/cli/config_edit.go | 6 ++- internal/cli/debug.go | 30 ++++++++++++++ internal/cli/debug_test.go | 52 +++++++++++++++++++++++ internal/cli/decide.go | 4 ++ internal/cli/mcp.go | 2 + internal/cli/mcp_background.go | 2 + internal/cli/mcp_management.go | 2 + internal/cli/root.go | 18 +++++++- internal/cli/skill.go | 2 + internal/cli/skill_install.go | 4 ++ internal/daemon/controller.go | 6 ++- internal/daemon/launch.go | 8 +++- internal/debuglog/debug.go | 71 ++++++++++++++++++++++++++++++++ internal/debuglog/debug_test.go | 58 ++++++++++++++++++++++++++ internal/mcpserver/debug_test.go | 51 +++++++++++++++++++++++ internal/mcpserver/http.go | 7 ++++ internal/mcpserver/run.go | 7 +++- internal/mcpserver/tool.go | 11 ++++- internal/update/download.go | 12 +++++- internal/update/guard.go | 5 ++- internal/update/replace.go | 8 +++- internal/update/update.go | 6 ++- pkg/typesafe/debug_test.go | 39 ++++++++++++++++++ pkg/typesafe/retry_runner.go | 8 +++- pkg/typesafe/transport.go | 7 +++- 27 files changed, 428 insertions(+), 14 deletions(-) create mode 100644 internal/cli/debug.go create mode 100644 internal/cli/debug_test.go create mode 100644 internal/debuglog/debug.go create mode 100644 internal/debuglog/debug_test.go create mode 100644 internal/mcpserver/debug_test.go create mode 100644 pkg/typesafe/debug_test.go diff --git a/README.md b/README.md index 367b7d8..4c4929a 100644 --- a/README.md +++ b/README.md @@ -104,6 +104,19 @@ The release-assets workflow attaches raw CLI binaries and `SHA256SUMS` to an exi - Filesystem checks assume ordinary cooperative local storage, not hostile concurrent writers, mount changes or power-loss durability. Context cancellation is checked at safe boundaries; filesystem calls are not interruptible. - Use your package manager for managed installs. `os.Executable` may resolve a symlink launch to its physical target, so the updater cannot reliably identify every symlink-invoked or package-managed installation. +## Debug logging + +```sh +jevwise --debug update --check +jevwise --debug mcp +``` + +- 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`. +- 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, URLs/paths, headers/bodies, or raw error causes. 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. + ## CLI configuration Precedence: **changed flags > nonblank environment > TOML > defaults**. diff --git a/internal/cli/config.go b/internal/cli/config.go index 15b6a71..28cfe14 100644 --- a/internal/cli/config.go +++ b/internal/cli/config.go @@ -8,6 +8,7 @@ import ( "strings" "github.com/bitbrew-dev/jevwise/internal/config" + "github.com/bitbrew-dev/jevwise/internal/debuglog" "github.com/spf13/cobra" ) @@ -52,6 +53,7 @@ func newConfig() *cobra.Command { if err != nil { return errors.New("cannot determine configuration path") } + debuglog.Event(cmd.Context(), "config.init.publish") if err := config.Init(cmd.Context(), path); err != nil { if errors.Is(err, os.ErrExist) { return errors.New("configuration already exists; no file replaced") @@ -78,6 +80,7 @@ func newConfig() *cobra.Command { if err != nil { return err } + debuglog.Event(cmd.Context(), "config.view.read") text, err := config.View(path) if err != nil { return err diff --git a/internal/cli/config_edit.go b/internal/cli/config_edit.go index 0abecf7..5f96f43 100644 --- a/internal/cli/config_edit.go +++ b/internal/cli/config_edit.go @@ -10,12 +10,15 @@ import ( "time" "github.com/bitbrew-dev/jevwise/internal/config" + "github.com/bitbrew-dev/jevwise/internal/debuglog" "github.com/spf13/cobra" ) type configEditor func(context.Context, string, string, io.Reader, io.Writer, io.Writer) error -func runConfigEditor(ctx context.Context, editor, path string, in io.Reader, out, stderr io.Writer) error { +func runConfigEditor(ctx context.Context, editor, path string, in io.Reader, out, stderr io.Writer) (resultErr error) { + finish := debuglog.Trace(ctx, "config.editor") + defer func() { finish(resultErr) }() process := exec.CommandContext(ctx, editor, path) // No shell; absolute file is one argument. process.WaitDelay = 250 * time.Millisecond // Bound inherited Go-copy pipe waits. process.Stdin, process.Stdout, process.Stderr = in, out, stderr @@ -41,6 +44,7 @@ func newConfigEdit(run configEditor) *cobra.Command { if err != nil { return err } + debuglog.Event(cmd.Context(), "config.edit.inspect") info, err := os.Lstat(path) if err != nil || !info.Mode().IsRegular() { return errors.New("config edit requires an existing regular file, not a link; initialize it first") diff --git a/internal/cli/debug.go b/internal/cli/debug.go new file mode 100644 index 0000000..93dfad5 --- /dev/null +++ b/internal/cli/debug.go @@ -0,0 +1,30 @@ +package cli + +import ( + "io" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" + "github.com/spf13/cobra" +) + +// Instrument declared commands only. Help/completion generated by Cobra stay quiet. +func instrumentCommands(cmd *cobra.Command) { + if run := cmd.RunE; run != nil { + operation := cmd.CommandPath() + cmd.RunE = func(cmd *cobra.Command, args []string) (err error) { + previous := cmd.Context() + var writer io.Writer + if enabled, _ := cmd.Flags().GetBool("debug"); enabled { + writer = cmd.ErrOrStderr() + } + cmd.SetContext(debuglog.WithWriter(previous, writer)) + defer cmd.SetContext(previous) + finish := debuglog.Trace(cmd.Context(), operation) + defer func() { finish(err) }() + return run(cmd, args) + } + } + for _, child := range cmd.Commands() { + instrumentCommands(child) + } +} diff --git a/internal/cli/debug_test.go b/internal/cli/debug_test.go new file mode 100644 index 0000000..59e5e53 --- /dev/null +++ b/internal/cli/debug_test.go @@ -0,0 +1,52 @@ +package cli + +import ( + "context" + "errors" + "strings" + "testing" + + "github.com/bitbrew-dev/jevwise/internal/config" + "github.com/bitbrew-dev/jevwise/internal/service" +) + +func TestDebugStreamsPrivacyAndContextIsolation(t *testing.T) { + configEnvironment(t) + original := context.Background() + factory := func(config.Config) (service.DecisionService, func(), error) { + return decideFunc(func(context.Context, service.Request) (service.Response, error) { + return service.Response{Choice: "private-option"}, nil + }), nil, nil + } + cmd := NewRootWithFactory(factory) + cmd.SetContext(original) + args := []string{"decide", "--prompt=private-prompt", "--option=private-option", "--option=other", "--api-key=private-key"} + quiet, stderr, err := execute(cmd, args...) + if err != nil || stderr != "" { + t.Fatal("default logs changed command behavior", err) + } + verbose, stderr, err := execute(cmd, "decide", "--debug") + if err != nil || quiet != verbose || !strings.Contains(stderr, `"operation":"config.load"`) || !strings.Contains(stderr, "decision.dispatch") { + t.Fatal("debug output missing or stdout changed", err) + } + child, _, _ := cmd.Find([]string{"decide"}) + if strings.Contains(stderr, "private") || child.Context() != original || cmd.Context() != original { + t.Fatal("diagnostics leaked input or context") + } + _, stderr, err = execute(cmd, "decide", "--debug=false") + if err != nil || stderr != "" { + t.Fatal("debug setting leaked across invocations", err) + } + for _, args := range [][]string{{"--help", "--debug"}, {"decide", "--help", "--debug"}, {"version"}} { + if _, stderr, err := execute(NewRoot(), args...); err != nil || stderr != "" { + t.Fatal("help/version unexpectedly logged", err) + } + } + broken := NewRootWithFactory(func(config.Config) (service.DecisionService, func(), error) { + return nil, nil, errors.New("private-service-error") + }) + _, stderr, err = execute(broken, append(args, "--debug")...) + if err == nil || strings.Contains(stderr, "private") || !strings.Contains(stderr, `"success":false`) { + t.Fatal("failure logs leaked or lost the outcome") + } +} diff --git a/internal/cli/decide.go b/internal/cli/decide.go index 6ae677c..6856f06 100644 --- a/internal/cli/decide.go +++ b/internal/cli/decide.go @@ -7,6 +7,7 @@ import ( "io" "github.com/bitbrew-dev/jevwise/internal/config" + "github.com/bitbrew-dev/jevwise/internal/debuglog" "github.com/bitbrew-dev/jevwise/internal/service" "github.com/bitbrew-dev/jevwise/pkg/typesafe" "github.com/spf13/cobra" @@ -98,6 +99,7 @@ func newDecide(factory ServiceFactory) *cobra.Command { if err := ctx.Err(); err != nil { return err } + debuglog.Event(ctx, "decision.service.initialize") svc, cleanup, err := factory(cfg) if cleanup != nil { defer cleanup() @@ -111,6 +113,7 @@ func newDecide(factory ServiceFactory) *cobra.Command { if err := ctx.Err(); err != nil { return err } + debuglog.Event(ctx, "decision.dispatch") response, err := svc.Decide(ctx, request) if err != nil { return &decisionError{"decision request failed", err} @@ -118,6 +121,7 @@ func newDecide(factory ServiceFactory) *cobra.Command { if err := ctx.Err(); err != nil { return err } + debuglog.Event(ctx, "decision.output") if err := json.NewEncoder(cmd.OutOrStdout()).Encode(response); err != nil { return &decisionError{"cannot write decision response", err} } diff --git a/internal/cli/mcp.go b/internal/cli/mcp.go index ee6b344..9f45551 100644 --- a/internal/cli/mcp.go +++ b/internal/cli/mcp.go @@ -9,6 +9,7 @@ import ( "time" "github.com/bitbrew-dev/jevwise/internal/daemon" + "github.com/bitbrew-dev/jevwise/internal/debuglog" "github.com/bitbrew-dev/jevwise/internal/mcpserver" "github.com/bitbrew-dev/jevwise/internal/service" "github.com/spf13/cobra" @@ -66,6 +67,7 @@ func newMCPWithBackground(factory ServiceFactory, run mcpRunner, start mcpStarte if background { return runMCPBackground(cmd, cfg, canonical, token, runtimeDir, start) } + debuglog.Event(ctx, "mcp.service.initialize") svc, cleanup, err := factory(cfg) if cleanup != nil { defer cleanup() diff --git a/internal/cli/mcp_background.go b/internal/cli/mcp_background.go index e658c4f..c70d955 100644 --- a/internal/cli/mcp_background.go +++ b/internal/cli/mcp_background.go @@ -11,6 +11,7 @@ import ( "github.com/bitbrew-dev/jevwise/internal/buildinfo" "github.com/bitbrew-dev/jevwise/internal/config" "github.com/bitbrew-dev/jevwise/internal/daemon" + "github.com/bitbrew-dev/jevwise/internal/debuglog" "github.com/bitbrew-dev/jevwise/internal/mcpserver" "github.com/bitbrew-dev/jevwise/internal/service" "github.com/spf13/cobra" @@ -40,6 +41,7 @@ func runMCPBackground(cmd *cobra.Command, cfg config.Config, address, agentToken if err := daemon.ValidateBootstrap(boot); err != nil { return err } + debuglog.Event(cmd.Context(), "mcp.background.inspect") state, token, err := readBackgroundInstance(path) if err == nil { controller, err := daemon.NewController(state.Address, state.Instance, token) diff --git a/internal/cli/mcp_management.go b/internal/cli/mcp_management.go index 0cf3d7b..81fad88 100644 --- a/internal/cli/mcp_management.go +++ b/internal/cli/mcp_management.go @@ -8,6 +8,7 @@ import ( "strconv" "github.com/bitbrew-dev/jevwise/internal/daemon" + "github.com/bitbrew-dev/jevwise/internal/debuglog" "github.com/spf13/cobra" ) @@ -30,6 +31,7 @@ func newMCPManagement(action string, runtimeDir *string) *cobra.Command { if err != nil || *runtimeDir == "" { return errors.New("invalid MCP runtime directory") } + debuglog.Event(cmd.Context(), "mcp.management.inspect") store, err := daemon.OpenExistingStore(filepath.Clean(path)) if errors.Is(err, os.ErrNotExist) { return writeMCPManagement(cmd, "MCP background instance is not running", false) diff --git a/internal/cli/root.go b/internal/cli/root.go index c8a49a3..b998c83 100644 --- a/internal/cli/root.go +++ b/internal/cli/root.go @@ -7,6 +7,7 @@ import ( "github.com/bitbrew-dev/jevwise/internal/buildinfo" "github.com/bitbrew-dev/jevwise/internal/config" + "github.com/bitbrew-dev/jevwise/internal/debuglog" "github.com/bitbrew-dev/jevwise/internal/mcpserver" "github.com/bitbrew-dev/jevwise/internal/update" "github.com/phuslu/log" @@ -48,6 +49,7 @@ func NewRootWithFactory(factory ServiceFactory) *cobra.Command { // Leave Command.Version empty: Cobra prints raw version-template writer errors. 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.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)") @@ -62,20 +64,32 @@ func NewRootWithFactory(factory ServiceFactory) *cobra.Command { cmd.AddCommand(newMCP(factory, mcpserver.Run)) cmd.AddCommand(newMCPChild(factory)) cmd.AddCommand(newSkill(newSkillFetch(nil), installSkill)) + instrumentCommands(cmd) return cmd } // LoadConfig resolves a command's inherited flags without changing global state. -func LoadConfig(cmd *cobra.Command) (config.Config, error) { +func LoadConfig(cmd *cobra.Command) (_ config.Config, resultErr error) { + finish := debuglog.Trace(cmd.Context(), "config.load") + defer func() { finish(resultErr) }() path, err := cmd.Flags().GetString("config") if err != nil { return config.Config{}, errors.New("configuration flag is unavailable") } + if path == "" { + debuglog.Event(cmd.Context(), "config.discovery") + } else { + debuglog.Event(cmd.Context(), "config.explicit") + } return config.Load(path, cmd.Flags()) } // Logger writes only to the command's error stream. Log status and safe metadata, // never credentials, prompt bodies, option content, or raw request/response bodies. func Logger(cmd *cobra.Command) log.Logger { - return log.Logger{Level: log.InfoLevel, Writer: log.IOWriter{Writer: cmd.ErrOrStderr()}} + level := log.InfoLevel + if enabled, _ := cmd.Root().PersistentFlags().GetBool("debug"); enabled { + level = log.DebugLevel + } + return log.Logger{Level: level, Writer: log.IOWriter{Writer: cmd.ErrOrStderr()}} } diff --git a/internal/cli/skill.go b/internal/cli/skill.go index ee5fb5f..d760496 100644 --- a/internal/cli/skill.go +++ b/internal/cli/skill.go @@ -12,6 +12,7 @@ import ( "time" "unicode/utf8" + "github.com/bitbrew-dev/jevwise/internal/debuglog" "github.com/spf13/cobra" ) @@ -132,6 +133,7 @@ func newSkill(fetch skillFetch, install skillInstall) *cobra.Command { if err := ctx.Err(); err != nil { return err } + debuglog.Event(ctx, "skill.fetch") data, err := fetch(ctx) if err != nil { return &decisionError{"cannot fetch Jev skill", err} diff --git a/internal/cli/skill_install.go b/internal/cli/skill_install.go index 6241eca..306d45d 100644 --- a/internal/cli/skill_install.go +++ b/internal/cli/skill_install.go @@ -7,6 +7,8 @@ import ( "io" "os" "runtime" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" ) var errSkillExists = errors.New("skill already exists; use --force to replace it") @@ -30,6 +32,8 @@ func installSkill(ctx context.Context, data []byte, target string, force bool) e // replacement; Unix rename replaces the directory entry, never its old inode. // Directory and final-link checks are static checks, not hostile-writer CAS. func installSkillAt(ctx context.Context, project string, data []byte, target string, force bool, hooks skillInstallHooks) (err error) { + finish := debuglog.Trace(ctx, "skill.install") + defer func() { finish(err) }() if ctx == nil { return errors.New("skill context is required") } diff --git a/internal/daemon/controller.go b/internal/daemon/controller.go index abe9616..09439f9 100644 --- a/internal/daemon/controller.go +++ b/internal/daemon/controller.go @@ -10,6 +10,8 @@ import ( "net" "net/http" "time" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" ) const controlResponseLimit = 4 << 10 @@ -59,7 +61,9 @@ func (c *Controller) Stop(ctx context.Context) (ManagementStatus, error) { return c.request(ctx, http.MethodPost, "/_jev/stop") } -func (c *Controller) request(ctx context.Context, method, path string) (ManagementStatus, error) { +func (c *Controller) request(ctx context.Context, method, path string) (_ ManagementStatus, resultErr error) { + finish := debuglog.Trace(ctx, "mcp.management.request") + defer func() { finish(resultErr) }() fail := func(cause error) (ManagementStatus, error) { return ManagementStatus{}, &controlError{cause} } diff --git a/internal/daemon/launch.go b/internal/daemon/launch.go index bd72264..e5012be 100644 --- a/internal/daemon/launch.go +++ b/internal/daemon/launch.go @@ -9,6 +9,8 @@ import ( "path/filepath" "strings" "time" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" ) // ChildArgument is the fixed hidden command. Credentials never appear in argv. @@ -26,7 +28,9 @@ type StartResult struct{ Started bool } // boot.ControlToken; running=false checks preparation, true checks ACK promotion. // Readiness must honor its bounded context. Acknowledged children are never // killed when this context expires. -func Start(ctx context.Context, executable string, boot Bootstrap, validate func(Bootstrap) error, readiness func(context.Context, bool) error) (StartResult, error) { +func Start(ctx context.Context, executable string, boot Bootstrap, validate func(Bootstrap) error, readiness func(context.Context, bool) error) (_ StartResult, resultErr error) { + finish := debuglog.Trace(ctx, "mcp.background.start") + defer func() { finish(resultErr) }() fail := errors.New("background startup failed: inspect authenticated status") if ctx == nil || readiness == nil { return StartResult{}, fail @@ -95,9 +99,11 @@ func Start(ctx context.Context, executable string, boot Bootstrap, validate func if n, err := output.Write(frame.Bytes()); err != nil || n != frame.Len() { return StartResult{}, fail } + debuglog.Event(ctx, "mcp.background.wait.prepared") if waitReady(startup, done, readiness, false) != nil { return StartResult{}, fail } + debuglog.Event(ctx, "mcp.background.acknowledge") n, err := output.Write([]byte{acknowledgement}) acknowledged = n == 1 _ = output.Close() diff --git a/internal/debuglog/debug.go b/internal/debuglog/debug.go new file mode 100644 index 0000000..b32f988 --- /dev/null +++ b/internal/debuglog/debug.go @@ -0,0 +1,71 @@ +// Package debuglog provides opt-in, context-scoped diagnostics, never payload logs. +package debuglog + +import ( + "context" + "errors" + "io" + "sync" + "time" + + "github.com/phuslu/log" +) + +type key struct{} +type lockedWriter struct { + mu sync.Mutex + writer io.Writer +} + +func (w *lockedWriter) Write(p []byte) (int, error) { + w.mu.Lock() + defer w.mu.Unlock() + return w.writer.Write(p) +} + +// WithWriter enables debug output to writer, or disables inherited logging with nil. +// The writer must not be concurrently used outside this logger without its own lock. +// Logging is best-effort: write failures never replace an operation's result. +func WithWriter(ctx context.Context, writer io.Writer) context.Context { + var logger *log.Logger + if writer != nil { + logger = &log.Logger{Level: log.DebugLevel, Writer: log.IOWriter{Writer: &lockedWriter{writer: writer}}} + } + return context.WithValue(ctx, key{}, logger) +} + +func from(ctx context.Context) *log.Logger { + if ctx == nil { + return nil + } + logger, _ := ctx.Value(key{}).(*log.Logger) + return logger +} + +// Event and Count accept fixed event names only, never user-controlled strings. +func Event(ctx context.Context, name string) { + if logger := from(ctx); logger != nil { + logger.Debug().Msg(name) + } +} + +func Count(ctx context.Context, name string, value int) { + if logger := from(ctx); logger != nil { + logger.Debug().Int("value", value).Msg(name) + } +} + +// Trace logs timing and outcome, never error text, causes or returned data. +func Trace(ctx context.Context, operation string) func(error) { + logger := from(ctx) + if logger == nil { + return func(error) {} + } + started := time.Now() + logger.Debug().Str("operation", operation).Msg("started") + return func(err error) { + logger.Debug().Str("operation", operation).Bool("success", err == nil). + Bool("canceled", errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded)). + Int64("elapsed_ms", time.Since(started).Milliseconds()).Msg("finished") + } +} diff --git a/internal/debuglog/debug_test.go b/internal/debuglog/debug_test.go new file mode 100644 index 0000000..5938ebc --- /dev/null +++ b/internal/debuglog/debug_test.go @@ -0,0 +1,58 @@ +package debuglog + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "strings" + "sync" + "testing" +) + +func TestTraceIsOptInPrivateAndConcurrent(t *testing.T) { + var output bytes.Buffer + ctx := WithWriter(context.Background(), &output) + finish := Trace(ctx, "fixture.operation") + finish(errors.New("private-key-and-error")) + var group sync.WaitGroup + for i := 0; i < 16; i++ { + group.Go(func() { Count(ctx, "fixture.status", 503) }) + } + group.Wait() + lines := strings.Split(strings.TrimSpace(output.String()), "\n") + if len(lines) != 18 || strings.Contains(output.String(), "private") { + t.Fatal("concurrent diagnostics were lost or leaked") + } + for _, line := range lines { + var fields map[string]any + if json.Unmarshal([]byte(line), &fields) != nil || fields["level"] != "debug" { + t.Fatal("invalid structured event") + } + if fields["message"] == "finished" && fields["success"] != false { + t.Fatal("failure outcome lost") + } + } + before := output.Len() + quiet := WithWriter(ctx, nil) + Event(quiet, "disabled") + Trace(quiet, "disabled")(nil) + Event(nil, "disabled") + Trace(nil, "disabled")(nil) + if output.Len() != before { + t.Fatal("disabled context inherited output") + } +} + +type failedWriter struct{} + +func (failedWriter) Write([]byte) (int, error) { return 0, errors.New("private-writer-error") } + +func TestCancellationAndWriterFailure(t *testing.T) { + var output bytes.Buffer + Trace(WithWriter(context.Background(), &output), "canceled")(context.DeadlineExceeded) + if !strings.Contains(output.String(), `"canceled":true`) { + t.Fatal("deadline outcome lost") + } + Trace(WithWriter(context.Background(), failedWriter{}), "fixture")(nil) +} diff --git a/internal/mcpserver/debug_test.go b/internal/mcpserver/debug_test.go new file mode 100644 index 0000000..40e2439 --- /dev/null +++ b/internal/mcpserver/debug_test.go @@ -0,0 +1,51 @@ +package mcpserver + +import ( + "bytes" + "context" + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" + "github.com/bitbrew-dev/jevwise/internal/service" + "github.com/modelcontextprotocol/go-sdk/mcp" +) + +func TestDebugHTTPRejectsWithoutLoggingPeerData(t *testing.T) { + var logs bytes.Buffer + ctx := debuglog.WithWriter(context.Background(), &logs) + server, err := New(ctx, decisionFunc(func(context.Context, service.Request) (service.Response, error) { + t.Fatal("rejected request dispatched") + return service.Response{}, nil + }), time.Second) + if err != nil { + t.Fatal(err) + } + handler, err := NewHTTP(server, "127.0.0.1:8080", "private-token") + if err != nil { + t.Fatal(err) + } + r := httptest.NewRequest(http.MethodPost, "http://127.0.0.1:8080/mcp", strings.NewReader("private-payload")).WithContext(ctx) + r.Header.Set("Authorization", "Bearer private-invalid-token") + response := httptest.NewRecorder() + handler.ServeHTTP(response, r) + if response.Code != 401 || !strings.Contains(logs.String(), `"value":401`) || strings.Contains(logs.String(), "private") || strings.Contains(logs.String(), "127.0.0.1") { + t.Fatal("rejection diagnostics missing or exposed peer data") + } +} + +func TestDebugToolCancellation(t *testing.T) { + var logs bytes.Buffer + lifetime := debuglog.WithWriter(context.Background(), &logs) + ctx, cancel := context.WithCancel(lifetime) + cancel() + result, err := decisionHandler(lifetime, nil, time.Second)(ctx, &mcp.CallToolRequest{ + Params: &mcp.CallToolParamsRaw{Arguments: []byte(`{"prompt":"private","options":["a","b"]}`)}, + }) + if err != nil || !result.IsError || !strings.Contains(logs.String(), `"canceled":true`) || strings.Contains(logs.String(), "private") { + t.Fatal("tool cancellation diagnostic lost or leaked input") + } +} diff --git a/internal/mcpserver/http.go b/internal/mcpserver/http.go index 5476b4f..48c71e7 100644 --- a/internal/mcpserver/http.go +++ b/internal/mcpserver/http.go @@ -11,6 +11,7 @@ import ( "net/netip" "strings" + "github.com/bitbrew-dev/jevwise/internal/debuglog" "github.com/modelcontextprotocol/go-sdk/mcp" ) @@ -79,6 +80,7 @@ func NewHTTP(server *mcp.Server, address, token string) (http.Handler, error) { status = http.StatusMethodNotAllowed } if status != 0 { + debuglog.Count(r.Context(), "mcp.http.rejected", status) http.Error(w, "MCP request rejected", status) return } @@ -86,6 +88,7 @@ func NewHTTP(server *mcp.Server, address, token string) (http.Handler, error) { case slots <- struct{}{}: defer func() { <-slots }() default: + debuglog.Event(r.Context(), "mcp.http.busy") http.Error(w, "MCP server is busy", http.StatusServiceUnavailable) return } @@ -94,15 +97,18 @@ func NewHTTP(server *mcp.Server, address, token string) (http.Handler, error) { } body, err := io.ReadAll(io.LimitReader(r.Body, inputLimit+1)) if len(body) > inputLimit { + debuglog.Count(r.Context(), "mcp.http.rejected", http.StatusRequestEntityTooLarge) http.Error(w, "MCP request rejected", http.StatusRequestEntityTooLarge) return } if err != nil || r.Context().Err() != nil { + debuglog.Count(r.Context(), "mcp.http.rejected", http.StatusBadRequest) http.Error(w, "MCP request rejected", http.StatusBadRequest) return } // Even legacy revisions cannot batch paid decisions through one slot. if trimmed := bytes.TrimSpace(body); len(trimmed) > 0 && trimmed[0] == '[' { + debuglog.Count(r.Context(), "mcp.http.rejected", http.StatusBadRequest) http.Error(w, "MCP request rejected", http.StatusBadRequest) return } @@ -111,6 +117,7 @@ func NewHTTP(server *mcp.Server, address, token string) (http.Handler, error) { writer := &httpPrivacyWriter{ResponseWriter: w} transport.ServeHTTP(writer, r) writer.finish() + debuglog.Count(r.Context(), "mcp.http.status", writer.status) }), nil } diff --git a/internal/mcpserver/run.go b/internal/mcpserver/run.go index 325c611..b39ec1f 100644 --- a/internal/mcpserver/run.go +++ b/internal/mcpserver/run.go @@ -9,6 +9,7 @@ import ( "net/http" "time" + "github.com/bitbrew-dev/jevwise/internal/debuglog" "github.com/bitbrew-dev/jevwise/internal/service" ) @@ -49,7 +50,9 @@ func Run(ctx context.Context, svc service.DecisionService, timeout time.Duration // Its actual bound address is authoritative; options.Address is only for Run. // A prepared listener supports private daemon startup leases and isolated tests. // Normal lifetime cancellation is a successful, bounded graceful shutdown. -func Serve(ctx context.Context, listener net.Listener, svc service.DecisionService, timeout time.Duration, options RunOptions) error { +func Serve(ctx context.Context, listener net.Listener, svc service.DecisionService, timeout time.Duration, options RunOptions) (resultErr error) { + finish := debuglog.Trace(ctx, "mcp.serve") + defer func() { finish(resultErr) }() if listener == nil { return errors.New("MCP listener is required") } @@ -97,6 +100,7 @@ func Serve(ctx context.Context, listener net.Listener, svc service.DecisionServi <-served return err } + debuglog.Event(lifetime, "mcp.ready") if options.Ready != nil { if err := options.Ready(lifetime, "http://"+listener.Addr().String()+"/mcp"); err != nil { cancel() @@ -114,6 +118,7 @@ func Serve(ctx context.Context, listener net.Listener, svc service.DecisionServi } // Cancellation reaches active decisions before the bounded connection drain. cancel() + debuglog.Event(lifetime, "mcp.shutdown") shutdown, stop := context.WithTimeout(context.Background(), 5*time.Second) defer stop() err = httpServer.Shutdown(shutdown) diff --git a/internal/mcpserver/tool.go b/internal/mcpserver/tool.go index 8e8a55f..c158ac2 100644 --- a/internal/mcpserver/tool.go +++ b/internal/mcpserver/tool.go @@ -13,6 +13,7 @@ import ( "unicode/utf8" "github.com/bitbrew-dev/jevwise/internal/buildinfo" + "github.com/bitbrew-dev/jevwise/internal/debuglog" "github.com/bitbrew-dev/jevwise/internal/service" "github.com/modelcontextprotocol/go-sdk/mcp" ) @@ -72,7 +73,15 @@ func New(lifetime context.Context, svc service.DecisionService, timeout time.Dur } func decisionHandler(lifetime context.Context, svc service.DecisionService, timeout time.Duration) mcp.ToolHandler { - return func(ctx context.Context, call *mcp.CallToolRequest) (*mcp.CallToolResult, error) { + return func(ctx context.Context, call *mcp.CallToolRequest) (result *mcp.CallToolResult, err error) { + finish := debuglog.Trace(lifetime, "mcp.decide") + defer func() { + loggedErr := err + if loggedErr == nil && result != nil && result.IsError { + loggedErr = result.GetError() + } + finish(loggedErr) + }() if ctx == nil || call == nil || call.Params == nil || len(call.Params.Arguments) > inputLimit || !utf8.Valid(call.Params.Arguments) { return toolFailure("invalid decision input", errors.New("invalid tool request")) } diff --git a/internal/update/download.go b/internal/update/download.go index 2a4df24..2ab1044 100644 --- a/internal/update/download.go +++ b/internal/update/download.go @@ -10,6 +10,8 @@ import ( "net/http" "net/url" "strings" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" ) const binaryLimit = 64 << 20 @@ -30,7 +32,9 @@ func (e *downloadError) Unwrap() error { return e.cause } // Download verifies one exact platform artifact against the release's SHA256SUMS. // The caller context controls the total deadline; no files are written. -func (c *Client) Download(ctx context.Context, release Release, goos, goarch string) (*Binary, error) { +func (c *Client) Download(ctx context.Context, release Release, goos, goarch string) (_ *Binary, resultErr error) { + finish := debuglog.Trace(ctx, "update.download") + defer func() { finish(resultErr) }() fail := func(err error) (*Binary, error) { if ctx != nil && ctx.Err() != nil { err = ctx.Err() @@ -63,6 +67,7 @@ func (c *Client) Download(ctx context.Context, release Release, goos, goarch str } } if !primaryPresent { + debuglog.Event(ctx, "update.asset.legacy") name = "jev_" + strings.TrimPrefix(name, "jevwise_") } sizes := make(map[string]int64, 2) @@ -101,10 +106,13 @@ func (c *Client) Download(ctx context.Context, release Release, goos, goarch str if err := ctx.Err(); err != nil { return fail(err) } + debuglog.Event(ctx, "update.checksum.verified") return &Binary{data: data, digest: digest, tag: release.Tag, goos: goos, goarch: goarch}, nil } -func (c *Client) readAsset(ctx context.Context, original string, size int64) ([]byte, error) { +func (c *Client) readAsset(ctx context.Context, original string, size int64) (_ []byte, resultErr error) { + finish := debuglog.Trace(ctx, "update.asset") + defer func() { finish(resultErr) }() if err := ctx.Err(); err != nil { return nil, err } diff --git a/internal/update/guard.go b/internal/update/guard.go index fdf3ee7..c241c49 100644 --- a/internal/update/guard.go +++ b/internal/update/guard.go @@ -11,6 +11,7 @@ import ( "runtime/debug" "github.com/bitbrew-dev/jevwise/internal/buildinfo" + "github.com/bitbrew-dev/jevwise/internal/debuglog" ) type guardError struct{ cause error } @@ -68,7 +69,9 @@ func readInstalled(ctx context.Context, reader io.ReaderAt, size int64, current, } // validateBinary rechecks the opaque download before any filesystem publication. -func validateBinary(ctx context.Context, binary *Binary, current, goos, goarch string) error { +func validateBinary(ctx context.Context, binary *Binary, current, goos, goarch string) (resultErr error) { + finish := debuglog.Trace(ctx, "update.verify") + defer func() { finish(resultErr) }() if ctx == nil || binary == nil || len(binary.data) == 0 || len(binary.data) > binaryLimit { return guardFailure(ctx, errors.New("invalid verified binary")) } diff --git a/internal/update/replace.go b/internal/update/replace.go index f034784..950bbf1 100644 --- a/internal/update/replace.go +++ b/internal/update/replace.go @@ -8,6 +8,8 @@ import ( "os" "path/filepath" "runtime" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" ) // InstallResult distinguishes publication from subsequent cleanup/cancellation. @@ -31,7 +33,9 @@ type replaceHooks struct { // The lock coordinates cooperating installers, not hostile filesystem writers. // Only permission bits are preserved, not group ownership, ACLs or xattrs. // File sync precedes publication; no directory-sync/power-loss guarantee is made. -func Replace(ctx context.Context, binary *Binary, current string) (InstallResult, error) { +func Replace(ctx context.Context, binary *Binary, current string) (_ InstallResult, resultErr error) { + finish := debuglog.Trace(ctx, "update.replace") + defer func() { finish(resultErr) }() if err := replaceCandidate(ctx, binary, current); err != nil { return InstallResult{}, &replaceError{err} } @@ -84,6 +88,7 @@ func replaceAt(ctx context.Context, binary *Binary, current, directory, name str } defer func() { err = errors.Join(err, root.Close()) }() lock := "." + name + ".jev-update-lock" + debuglog.Event(ctx, "update.lock.acquire") if err = root.Mkdir(lock, 0o700); err != nil { return result, err // Never remove a preexisting or stale lock. } @@ -166,6 +171,7 @@ func replaceAt(ctx context.Context, binary *Binary, current, directory, name str if err = hooks.publish(root, stageName, name); err != nil { return result, err } + debuglog.Event(ctx, "update.published") result.Installed, stageName = true, "" return result, ctx.Err() } diff --git a/internal/update/update.go b/internal/update/update.go index 6913a00..6427eee 100644 --- a/internal/update/update.go +++ b/internal/update/update.go @@ -11,6 +11,8 @@ import ( "strconv" "strings" "time" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" ) const latestURL = "https://api.github.com/repos/bitbrew-dev/jevwise/releases/latest" @@ -57,7 +59,9 @@ func NewClient(client *http.Client) *Client { } // Latest obtains bounded metadata for the newest stable release. -func (c *Client) Latest(ctx context.Context) (Release, error) { +func (c *Client) Latest(ctx context.Context) (_ Release, resultErr error) { + finish := debuglog.Trace(ctx, "update.lookup") + defer func() { finish(resultErr) }() fail := func(err error) (Release, error) { if ctx != nil && ctx.Err() != nil { err = ctx.Err() diff --git a/pkg/typesafe/debug_test.go b/pkg/typesafe/debug_test.go new file mode 100644 index 0000000..ed76c30 --- /dev/null +++ b/pkg/typesafe/debug_test.go @@ -0,0 +1,39 @@ +package typesafe + +import ( + "bytes" + "context" + "io" + "net/http" + "strings" + "testing" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" +) + +func TestDebugTransportRetriesWithoutPayloads(t *testing.T) { + clientEnvironment(t) + var logs bytes.Buffer + ctx := debuglog.WithWriter(context.Background(), &logs) + calls := 0 + c := transportClient(t, roundTripFunc(func(*http.Request) (*http.Response, error) { + calls++ + status := 503 + if calls > 1 { + status = 200 + } + return &http.Response{StatusCode: status, Header: http.Header{"X-Private": {"private-header"}}, Body: io.NopCloser(strings.NewReader(`{"private-response":true}`))}, nil + })) + policy := RetryPolicy{MaxRetries: 1, HTTPStatuses: map[int]bool{503: true}} + _, err := runRetry(ctx, policy, func(ctx context.Context, index int) (*RawResponse, error) { + return c.sendOnce(ctx, "POST", "/private-path", []byte("private-prompt"), 0, nil, index) + }, retryHooks{}) + if err != nil || calls != 2 || !strings.Contains(logs.String(), "api.retry.wait") || !strings.Contains(logs.String(), `"value":503`) { + t.Fatal("retry diagnostics missing", err) + } + for _, secret := range []string{"private", "secret-key", "example.com", "Authorization"} { + if strings.Contains(logs.String(), secret) { + t.Fatal("transport logs exposed request/response data") + } + } +} diff --git a/pkg/typesafe/retry_runner.go b/pkg/typesafe/retry_runner.go index 5f4be14..b3fe7d0 100644 --- a/pkg/typesafe/retry_runner.go +++ b/pkg/typesafe/retry_runner.go @@ -5,6 +5,8 @@ import ( "errors" "math/rand/v2" "time" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" ) // retryHooks are per-call seams. Missing hooks use production defaults; no @@ -35,7 +37,9 @@ func retrySleep(ctx context.Context, delay time.Duration) error { // runRetry repeats an entire HTTP-plus-decode attempt. The retry budget only // prevents starting another attempt: it does not cancel in-flight work. Context // expiration returns its sentinel so the client can attach safe HTTP metadata. -func runRetry(ctx context.Context, policy RetryPolicy, attempt func(context.Context, int) (*RawResponse, error), hooks retryHooks) (*RawResponse, error) { +func runRetry(ctx context.Context, policy RetryPolicy, attempt func(context.Context, int) (*RawResponse, error), hooks retryHooks) (_ *RawResponse, resultErr error) { + finish := debuglog.Trace(ctx, "api.retry") + defer func() { finish(resultErr) }() if ctx == nil { return nil, errors.New("typesafe: retry context is required") } @@ -67,6 +71,7 @@ func runRetry(ctx context.Context, policy RetryPolicy, attempt func(context.Cont if index > 0 && policy.Budget > 0 && hooks.now().Sub(started) >= policy.Budget { return raw, err } + debuglog.Count(ctx, "api.attempt", index) raw, err = attempt(ctx, index) if contextErr := ctx.Err(); contextErr != nil { return raw, contextErr @@ -91,6 +96,7 @@ func runRetry(ctx context.Context, policy RetryPolicy, attempt func(context.Cont if policy.Budget > 0 && delay >= remaining { return raw, err } + debuglog.Event(ctx, "api.retry.wait") sleepErr := hooks.sleep(ctx, delay) if contextErr := ctx.Err(); contextErr != nil { return raw, contextErr diff --git a/pkg/typesafe/transport.go b/pkg/typesafe/transport.go index ac649e8..9f9ed01 100644 --- a/pkg/typesafe/transport.go +++ b/pkg/typesafe/transport.go @@ -13,6 +13,8 @@ import ( "strconv" "strings" "time" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" ) // Responses are bounded to 8 MiB, including error bodies, to prevent unbounded @@ -23,7 +25,9 @@ const sdkIdentity = "typesafe-sdk-go/dev" // sendOnce executes one attempt. A zero timeout uses the client default. The // enclosing retry loop is responsible for incrementing the zero-based attempt. -func (c *Client) sendOnce(ctx context.Context, method, path string, body []byte, timeout time.Duration, headers http.Header, attempt int) (*RawResponse, error) { +func (c *Client) sendOnce(ctx context.Context, method, path string, body []byte, timeout time.Duration, headers http.Header, attempt int) (_ *RawResponse, resultErr error) { + finish := debuglog.Trace(ctx, "api.request") + defer func() { finish(resultErr) }() if err := ctx.Err(); err != nil { return nil, transportError(ctx, method, c.redact(c.baseURL+path), err) } @@ -70,6 +74,7 @@ func (c *Client) sendOnce(ctx context.Context, method, path string, body []byte, if err != nil { return nil, transportError(ctx, method, c.redact(endpoint), err) } + debuglog.Count(ctx, "api.response.status", response.StatusCode) payload, err := io.ReadAll(io.LimitReader(response.Body, maxResponseBytes+1)) if err != nil { return nil, transportError(ctx, method, c.redact(endpoint), err) From 1963e60e3f9b72e2e7536b615b246463932e2e91 Mon Sep 17 00:00:00 2001 From: benbenbang Date: Sat, 10 Oct 2026 00:26:28 +0800 Subject: [PATCH 2/2] feat(update): add release check diagnostics Improve update diagnostics by categorizing lookup and download failures, reporting HTTP and rate-limit metadata, and exposing clearer CLI errors for release checks. Add coverage for diagnostic behavior and document the new debug output and rate-limit handling. --- README.md | 3 +- internal/cli/update.go | 2 +- internal/cli/update_diagnostics_test.go | 32 ++++++++ internal/update/diagnostics.go | 80 ++++++++++++++++++ internal/update/diagnostics_test.go | 105 ++++++++++++++++++++++++ internal/update/download.go | 13 ++- internal/update/update.go | 51 ++++++++---- 7 files changed, 266 insertions(+), 20 deletions(-) create mode 100644 internal/cli/update_diagnostics_test.go create mode 100644 internal/update/diagnostics.go create mode 100644 internal/update/diagnostics_test.go diff --git a/README.md b/README.md index 4c4929a..f382976 100644 --- a/README.md +++ b/README.md @@ -62,6 +62,7 @@ bin/jevwise update --check --timeout 20s bin/jevwise update --timeout 60s # Install on supported standalone Linux/macOS builds ``` +- `--debug update --check` shows the fixed `bitbrew-dev/jevwise` endpoint, HTTP status, rate-limit remaining/reset/retry seconds and failure category. Anonymous checks can be rate-limited: wait for the limit to reset. A 403 without rate-limit evidence is reported as an HTTP failure, not assumed to be rate limiting. - `--check` checks the latest stable GitHub release without downloading a binary or changing files. No background checks, API credentials, or decision configuration are used. - `--timeout` is a positive flag-only deadline for the whole update, default `10s`; decision timeout environment/config values do not affect updates. Increase it for slow downloads. - Reports newer/current releases or no published release. Development/unknown builds report the latest release without inventing a version comparison. @@ -113,7 +114,7 @@ jevwise --debug mcp - 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`. - 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, URLs/paths, headers/bodies, or raw error causes. Treat timing/status diagnostics as operationally sensitive when sharing logs. +- 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. diff --git a/internal/cli/update.go b/internal/cli/update.go index 57cefaf..0f227f6 100644 --- a/internal/cli/update.go +++ b/internal/cli/update.go @@ -74,7 +74,7 @@ func newUpdate(ops updateOps, current string) *cobra.Command { if errors.Is(err, update.ErrNoRelease) { output = "No stable Jevwise release is published yet.\n" } else if err != nil { - return &decisionError{"cannot check Jevwise releases", err} + return &decisionError{update.LookupMessage(err), err} } else { if _, err := update.Compare(release.Tag, release.Tag); err != nil { return &decisionError{"invalid latest release version", err} diff --git a/internal/cli/update_diagnostics_test.go b/internal/cli/update_diagnostics_test.go new file mode 100644 index 0000000..78fb8d7 --- /dev/null +++ b/internal/cli/update_diagnostics_test.go @@ -0,0 +1,32 @@ +package cli + +import ( + "io" + "net/http" + "strings" + "testing" + + "github.com/bitbrew-dev/jevwise/internal/update" +) + +func TestUpdateReportsRateLimitWithAndWithoutDebug(t *testing.T) { + client := update.NewClient(&http.Client{Transport: skillTransport(func(*http.Request) (*http.Response, error) { + return &http.Response{StatusCode: 403, Header: http.Header{"X-Ratelimit-Remaining": {"0"}}, Body: io.NopCloser(strings.NewReader("private-body"))}, nil + })}) + for _, debug := range []bool{false, true} { + root := updateRoot(client.Latest, "dev") + cmd, _, _ := root.Find([]string{"update"}) + instrumentCommands(cmd) // The injected test command was added after NewRoot. + args := []string{"update", "--check"} + if debug { + args = append(args, "--debug") + } + out, stderr, err := execute(root, args...) + if err == nil || out != "" || !strings.Contains(err.Error(), "rate limited") || strings.Contains(stderr+err.Error(), "private") { + t.Fatal("rate-limit failure unhelpful or unsafe") + } + if debug != strings.Contains(stderr, "update.lookup.failed.rate_limited") { + t.Fatal("debug flag was not honored") + } + } +} diff --git a/internal/update/diagnostics.go b/internal/update/diagnostics.go new file mode 100644 index 0000000..f980f91 --- /dev/null +++ b/internal/update/diagnostics.go @@ -0,0 +1,80 @@ +package update + +import ( + "context" + "crypto/tls" + "errors" + "fmt" + "net" + "net/http" + "strconv" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" +) + +var errRedirectRefused = errors.New("release redirect refused") + +// LookupMessage exposes only locally assigned categories and numeric HTTP status, +// never an upstream body, header text, URL error or underlying error message. +func LookupMessage(err error) string { + var failure *safeError + if errors.As(err, &failure) { + if failure.reason == "rate_limited" { + return "GitHub release check is rate limited; wait for the limit to reset and retry (--debug shows rate-limit details)" + } + if failure.status != 0 && failure.status != http.StatusOK { + return fmt.Sprintf("cannot check Jevwise releases (HTTP %d); rerun with --debug", failure.status) + } + } + return "cannot check Jevwise releases; rerun with --debug" +} + +// Classify typed errors only. Error strings may contain proxy credentials or URLs. +func networkReason(err error) string { + var dns *net.DNSError + var certificate *tls.CertificateVerificationError + var network net.Error + switch { + case errors.Is(err, context.Canceled): + return "canceled" + case errors.Is(err, context.DeadlineExceeded): + return "timeout" + case errors.Is(err, errRedirectRefused): + return "redirect_refused" + case errors.As(err, &dns): + return "dns" + case errors.As(err, &certificate): + return "tls_certificate" + case errors.As(err, &network) && network.Timeout(): + return "timeout" + default: + return "network" + } +} + +// HTTP diagnostics use fixed stage names and bounded numeric metadata only. +// A 403 alone is not evidence of rate limiting; a 429 is. +func logHTTP(ctx context.Context, stage string, res *http.Response) bool { + debuglog.Count(ctx, stage+".http_status", res.StatusCode) + number := func(header, event string) int64 { + value := res.Header.Get(header) + if value == "" || len(value) > 19 { + return -1 + } + for _, b := range value { + if b < '0' || b > '9' { + return -1 + } + } + n, err := strconv.ParseInt(value, 10, strconv.IntSize) + if err != nil { + return -1 + } + debuglog.Count(ctx, stage+event, int(n)) + return n + } + remaining := number("X-RateLimit-Remaining", ".rate_limit.remaining") + number("X-RateLimit-Reset", ".rate_limit.reset_unix") + retry := number("Retry-After", ".rate_limit.retry_after_seconds") + return res.StatusCode == 429 || res.StatusCode == 403 && (remaining == 0 || retry >= 0) +} diff --git a/internal/update/diagnostics_test.go b/internal/update/diagnostics_test.go new file mode 100644 index 0000000..571c3d4 --- /dev/null +++ b/internal/update/diagnostics_test.go @@ -0,0 +1,105 @@ +package update + +import ( + "bytes" + "context" + "crypto/tls" + "errors" + "io" + "net" + "net/http" + "strings" + "testing" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" +) + +func TestLookupDiagnosticsExplainFailuresWithoutLeaks(t *testing.T) { + for _, test := range []struct { + name, reason string + status int + headers http.Header + body string + err error + }{ + {"rate", "rate_limited", 403, http.Header{"X-Ratelimit-Remaining": {"0"}, "X-Ratelimit-Reset": {"1791544363"}}, "private-body", nil}, + {"secondary", "rate_limited", 403, http.Header{"Retry-After": {"12"}}, "private-body", nil}, + {"429", "rate_limited", 429, nil, "private-body", nil}, + {"forbidden", "http_status", 403, nil, "private-body", nil}, + {"malicious headers", "http_status", 403, http.Header{"X-Ratelimit-Remaining": {"private-header"}, "X-Ratelimit-Reset": {"9223372036854775808"}, "Retry-After": {"-1"}}, "private-body", nil}, + {"json", "metadata_json", 200, nil, "private-body", nil}, + {"tag", "release_tag", 200, nil, strings.Replace(stable, "v1.2.3", "private-tag", 1), nil}, + {"dns", "dns", 0, nil, "", &net.DNSError{Err: "private-cause", Name: "private-host"}}, + {"tls", "tls_certificate", 0, nil, "", &tls.CertificateVerificationError{Err: errors.New("private-certificate")}}, + {"deadline", "timeout", 0, nil, "", context.DeadlineExceeded}, + {"network", "network", 0, nil, "", errors.New("https://user:private-password@proxy.invalid")}, + } { + t.Run(test.name, func(t *testing.T) { + var output bytes.Buffer + client := NewClient(&http.Client{Transport: roundTripFunc(func(*http.Request) (*http.Response, error) { + if test.err != nil { + return nil, test.err + } + return &http.Response{StatusCode: test.status, Header: test.headers, Body: io.NopCloser(strings.NewReader(test.body))}, nil + })}) + _, err := client.Latest(debuglog.WithWriter(context.Background(), &output)) + if err == nil || !strings.Contains(output.String(), "update.lookup.failed."+test.reason) || !strings.Contains(output.String(), latestURL) { + t.Fatal("failure diagnostics missing") + } + if strings.Contains(output.String()+err.Error()+LookupMessage(err), "private") { + t.Fatal("diagnostics exposed raw data") + } + if strings.Contains(LookupMessage(err), "rate limited") != (test.reason == "rate_limited") { + t.Fatal("HTTP failure incorrectly classified") + } + if test.name == "rate" && (!strings.Contains(output.String(), `"value":0`) || !strings.Contains(output.String(), `"value":1791544363`)) { + t.Fatal("rate-limit numbers missing") + } + if test.err != nil && !errors.Is(err, test.err) { + t.Fatal("underlying cause changed") + } + }) + } +} + +func TestLookupDiagnosticsAreOptInAnd404Ambiguous(t *testing.T) { + var output bytes.Buffer + client := NewClient(&http.Client{Transport: roundTripFunc(func(*http.Request) (*http.Response, error) { + return &http.Response{StatusCode: 404, Body: io.NopCloser(strings.NewReader("private-body"))}, nil + })}) + _, err := client.Latest(debuglog.WithWriter(context.Background(), &output)) + if !errors.Is(err, ErrNoRelease) || !strings.Contains(output.String(), "no_public_release_or_repository") || strings.Contains(output.String(), "private-body") { + t.Fatal("404 diagnosis changed or leaked") + } + before := output.Len() + client.Latest(context.Background()) + if output.Len() != before { + t.Fatal("default lookup inherited debug output") + } +} + +func TestAssetDiagnosticsDoNotExposeRedirectsOrBodies(t *testing.T) { + for _, kind := range []string{"rate", "redirect"} { + var output bytes.Buffer + calls := 0 + client := NewClient(&http.Client{Transport: roundTripFunc(func(*http.Request) (*http.Response, error) { + calls++ + status, headers := 403, http.Header{"X-Ratelimit-Remaining": {"0"}} + if kind == "redirect" { + status, headers = 302, http.Header{"Location": {"https://private.invalid/?token=private-secret"}} + } + return &http.Response{StatusCode: status, Header: headers, Body: io.NopCloser(strings.NewReader("private-body"))}, nil + })}) + _, err := client.readAsset(debuglog.WithWriter(context.Background(), &output), "https://github.com/bitbrew-dev/jevwise/releases/download/v1.2.3/SHA256SUMS", 1) + want := "rate_limited" + if kind == "redirect" { + want = "redirect_refused" + } + if err == nil || calls != 1 || !strings.Contains(output.String(), "update.asset.failed."+want) || strings.Contains(output.String(), "private") { + t.Fatal("asset diagnostics missing or exposed remote data") + } + if (kind == "redirect") != errors.Is(err, errRedirectRefused) { + t.Fatal("redirect guard cause changed") + } + } +} diff --git a/internal/update/download.go b/internal/update/download.go index 2ab1044..02bb79f 100644 --- a/internal/update/download.go +++ b/internal/update/download.go @@ -79,11 +79,13 @@ func (c *Client) Download(ctx context.Context, release Release, goos, goarch str continue } if _, exists := sizes[asset.Name]; exists || asset.Size <= 0 || asset.Size > limit { + debuglog.Event(ctx, "update.download.failed.asset_metadata") return fail(errors.New("invalid or duplicate release asset")) } sizes[asset.Name] = asset.Size } if len(sizes) != 2 { + debuglog.Event(ctx, "update.download.failed.missing_assets") return fail(errors.New("required release assets missing")) } base := "https://github.com/bitbrew-dev/jevwise/releases/download/" + release.Tag + "/" @@ -93,6 +95,7 @@ func (c *Client) Download(ctx context.Context, release Release, goos, goarch str } digest, err := manifestDigest(manifest, name) if err != nil { + debuglog.Event(ctx, "update.download.failed.manifest") return fail(err) } data, err := c.readAsset(ctx, base+name, sizes[name]) @@ -101,6 +104,7 @@ func (c *Client) Download(ctx context.Context, release Release, goos, goarch str } actual := sha256.Sum256(data) if subtle.ConstantTimeCompare(actual[:], digest[:]) != 1 { + debuglog.Event(ctx, "update.download.failed.checksum") return fail(errors.New("release checksum mismatch")) } if err := ctx.Err(); err != nil { @@ -120,7 +124,7 @@ func (c *Client) readAsset(ctx context.Context, original string, size int64) (_ client.Jar = nil client.CheckRedirect = func(req *http.Request, via []*http.Request) error { if len(via) > 5 || !assetURLAllowed(req.URL, original) { - return errors.New("release redirect refused") + return errRedirectRefused } // Do not forward credentials or leak a signed storage query via Referer. req.Header.Del("Authorization") @@ -135,13 +139,20 @@ func (c *Client) readAsset(ctx context.Context, original string, size int64) (_ req.Header.Set("User-Agent", "jevwise-update") res, err := client.Do(req) if err != nil { + debuglog.Event(ctx, "update.asset.failed."+networkReason(err)) return nil, err } defer res.Body.Close() if err := ctx.Err(); err != nil { return nil, err } + rateLimited := logHTTP(ctx, "update.asset", res) if res.StatusCode != http.StatusOK { + reason := "http_status" + if rateLimited { + reason = "rate_limited" + } + debuglog.Event(ctx, "update.asset.failed."+reason) return nil, errors.New("unexpected release asset status") } data, err := io.ReadAll(io.LimitReader(res.Body, size+1)) diff --git a/internal/update/update.go b/internal/update/update.go index 6427eee..a238416 100644 --- a/internal/update/update.go +++ b/internal/update/update.go @@ -17,6 +17,7 @@ import ( const latestURL = "https://api.github.com/repos/bitbrew-dev/jevwise/releases/latest" const metadataLimit = 1 << 20 +const apiVersion = "2026-03-10" // ErrNoRelease means GitHub has no published stable release. var ErrNoRelease = errors.New("no published stable Jevwise release") @@ -33,7 +34,11 @@ type Release struct { Assets []Asset } -type safeError struct{ cause error } +type safeError struct { + cause error + reason string + status int +} func (e *safeError) Error() string { return "cannot check Jevwise release" } func (e *safeError) Unwrap() error { return e.cause } @@ -62,45 +67,57 @@ func NewClient(client *http.Client) *Client { func (c *Client) Latest(ctx context.Context) (_ Release, resultErr error) { finish := debuglog.Trace(ctx, "update.lookup") defer func() { finish(resultErr) }() - fail := func(err error) (Release, error) { + status := 0 + fail := func(reason string, err error) (Release, error) { if ctx != nil && ctx.Err() != nil { err = ctx.Err() + reason = networkReason(err) } - return Release{}, &safeError{err} + debuglog.Event(ctx, "update.lookup.failed."+reason) + return Release{}, &safeError{cause: err, reason: reason, status: status} } if ctx == nil || c == nil || c.httpClient == nil { - return fail(errors.New("invalid release client or context")) + return fail("invalid_client", errors.New("invalid release client or context")) } if err := ctx.Err(); err != nil { - return fail(err) + return fail(networkReason(err), err) } + debuglog.Event(ctx, "update.lookup.GET "+latestURL) + debuglog.Event(ctx, "update.lookup.api_version."+apiVersion) req, err := http.NewRequestWithContext(ctx, http.MethodGet, latestURL, nil) if err != nil { - return fail(err) + return fail(networkReason(err), err) } req.Header.Set("Accept", "application/vnd.github+json") - req.Header.Set("X-GitHub-Api-Version", "2026-03-10") + req.Header.Set("X-GitHub-Api-Version", apiVersion) req.Header.Set("User-Agent", "jevwise-update") res, err := c.httpClient.Do(req) if err != nil { - return fail(err) + return fail(networkReason(err), err) } defer res.Body.Close() if err := ctx.Err(); err != nil { - return fail(err) + return fail(networkReason(err), err) } + status = res.StatusCode + rateLimited := logHTTP(ctx, "update.lookup", res) if res.StatusCode == http.StatusNotFound { + debuglog.Event(ctx, "update.lookup.no_public_release_or_repository") return Release{}, ErrNoRelease } if res.StatusCode != http.StatusOK { - return fail(errors.New("unexpected release status")) + reason := "http_status" + if rateLimited { + reason = "rate_limited" + } + return fail(reason, errors.New("unexpected release status")) } body, err := io.ReadAll(io.LimitReader(res.Body, metadataLimit+1)) if err != nil { - return fail(err) + return fail("response_read", err) } if len(body) > metadataLimit { - return fail(errors.New("release metadata too large")) + return fail("metadata_size", errors.New("release metadata too large")) } var wire struct { Tag string `json:"tag_name"` @@ -112,23 +129,23 @@ func (c *Client) Latest(ctx context.Context) (_ Release, resultErr error) { } `json:"assets"` } if err := json.Unmarshal(body, &wire); err != nil { - return fail(err) + return fail("metadata_json", err) } if _, err := Compare(wire.Tag, wire.Tag); err != nil { - return fail(err) + return fail("release_tag", err) } if wire.Draft == nil || *wire.Draft || wire.Prerelease == nil || *wire.Prerelease { - return fail(errors.New("release is not explicitly stable")) + return fail("release_not_stable", errors.New("release is not explicitly stable")) } release := Release{Tag: wire.Tag, Assets: make([]Asset, 0, len(wire.Assets))} for _, asset := range wire.Assets { if asset.Name == nil || *asset.Name == "" || asset.Size == nil || *asset.Size < 0 { - return fail(errors.New("invalid release asset")) + return fail("asset_metadata", errors.New("invalid release asset")) } release.Assets = append(release.Assets, Asset{Name: *asset.Name, Size: *asset.Size}) } if err := ctx.Err(); err != nil { - return fail(err) + return fail(networkReason(err), err) } return release, nil }