diff --git a/README.md b/README.md index 367b7d8..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. @@ -104,6 +105,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, 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. + ## 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/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/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/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 2a4df24..02bb79f 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) @@ -74,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 + "/" @@ -88,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]) @@ -96,15 +104,19 @@ 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 { 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 } @@ -112,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") @@ -127,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/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..a238416 100644 --- a/internal/update/update.go +++ b/internal/update/update.go @@ -11,10 +11,13 @@ import ( "strconv" "strings" "time" + + "github.com/bitbrew-dev/jevwise/internal/debuglog" ) 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") @@ -31,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 } @@ -57,46 +64,60 @@ func NewClient(client *http.Client) *Client { } // Latest obtains bounded metadata for the newest stable release. -func (c *Client) Latest(ctx context.Context) (Release, error) { - fail := func(err error) (Release, error) { +func (c *Client) Latest(ctx context.Context) (_ Release, resultErr error) { + finish := debuglog.Trace(ctx, "update.lookup") + defer func() { finish(resultErr) }() + 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"` @@ -108,23 +129,23 @@ func (c *Client) Latest(ctx context.Context) (Release, 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 } 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)