From f4bf23541de5f1d3313a87da9ab5f16714658ec1 Mon Sep 17 00:00:00 2001 From: Jesse Robbins Date: Mon, 13 Apr 2026 09:11:31 -0700 Subject: [PATCH 01/10] Add structured logging with per-run correlation and a logs command Every msgvault invocation now leaves a durable, structured trail on disk without the user having to redirect stderr. The default destination is /logs/msgvault-YYYY-MM-DD.log; stderr keeps receiving the same human-readable text it always has. internal/logging/logging.go: - BuildHandler fans records to two sinks: text on stderr + JSON on a daily log file. Per-process 6-byte hex run_id attached to every record for cross-invocation correlation. - Daily files rotate on size (50 MiB cap, 5 siblings kept). - Degrades to stderr-only if the log directory can't be prepared. cmd/msgvault/cmd/root.go: - Installs the handler as slog default after config load. - Writes "msgvault startup" and "msgvault exit" structured lines with command, sanitized argv, version, os/arch, outcome. - Panic recovery logs stack trace before exit. - New persistent flags: --log-file, --log-level, --no-log-file. - Config gains a [log] section (dir / level / disabled). cmd/msgvault/cmd/logs.go: - New 'msgvault logs' command: tail/filter the on-disk JSON logs. - Flags: -n, -f, --run-id, --level, --grep, --all, --path. internal/tui/model.go: - loadAccounts logs a structured line on success/failure. Addresses #129. Co-Authored-By: Claude Sonnet 4.6 --- cmd/msgvault/cmd/logs.go | 328 ++++++++++++++++++++++++++++++ cmd/msgvault/cmd/root.go | 193 +++++++++++++++--- internal/config/config.go | 30 +++ internal/logging/logging.go | 337 +++++++++++++++++++++++++++++++ internal/logging/logging_test.go | 206 +++++++++++++++++++ internal/tui/model.go | 13 +- 6 files changed, 1081 insertions(+), 26 deletions(-) create mode 100644 cmd/msgvault/cmd/logs.go create mode 100644 internal/logging/logging.go create mode 100644 internal/logging/logging_test.go diff --git a/cmd/msgvault/cmd/logs.go b/cmd/msgvault/cmd/logs.go new file mode 100644 index 00000000..4ae7a72e --- /dev/null +++ b/cmd/msgvault/cmd/logs.go @@ -0,0 +1,328 @@ +package cmd + +import ( + "bufio" + "context" + "encoding/json" + "fmt" + "io" + "os" + "path/filepath" + "sort" + "strings" + "time" + + "github.com/spf13/cobra" +) + +var ( + logsFollow bool + logsLines int + logsRunID string + logsLevel string + logsAll bool + logsGrep string + logsPath bool +) + +var logsCmd = &cobra.Command{ + Use: "logs", + Short: "View and tail msgvault's structured log files", + Long: `Show msgvault's structured log output from the on-disk JSON logs +written to /logs. + +By default this prints the last 50 lines of today's log file in a +compact, human-friendly format (level + run_id + message + the +interesting attrs). Use --follow to tail the file live, --run-id +to filter to a single invocation, --level to filter by severity, +or --grep to filter on a substring match across the whole record. + +Examples: + + msgvault logs # last 50 lines of today's log + msgvault logs -n 200 --follow # tail with --follow + msgvault logs --run-id a1b2c3d4 # just one run + msgvault logs --level error # only errors + msgvault logs --grep deduplicate # substring over the JSON + msgvault logs --all # every log file we still have + msgvault logs --path # print the log path and exit`, + RunE: runLogsCmd, +} + +func runLogsCmd(cmd *cobra.Command, args []string) error { + dir := cfg.LogsDir() + + if logsPath { + fmt.Println(dir) + return nil + } + + files, err := findLogFiles(dir, logsAll) + if err != nil { + return err + } + if len(files) == 0 { + fmt.Printf("No log files in %s\n", dir) + fmt.Println("(Nothing has been logged yet, or --no-log-file was used.)") + return nil + } + + filter := logFilter{ + RunID: logsRunID, + Level: strings.ToLower(logsLevel), + Grep: logsGrep, + } + + // Non-follow mode: load the requested file(s) and print the + // last N filtered lines. "Last N" is computed against the + // filtered subset so --run-id and --level behave intuitively. + if !logsFollow { + return printLogFiles(files, logsLines, filter, cmd.OutOrStdout()) + } + + // Follow mode: print the tail of the most recent file and + // then stream new lines. --all is ignored because tailing + // rotated files would be a trap. + latest := files[len(files)-1] + if err := printLogFiles( + []string{latest}, logsLines, filter, cmd.OutOrStdout(), + ); err != nil { + return err + } + return followLogFile(cmd.Context(), latest, filter, cmd.OutOrStdout()) +} + +// findLogFiles returns the sorted list of log files to read. +// When all is false, it returns only today's file (if it exists). +func findLogFiles(dir string, all bool) ([]string, error) { + if _, err := os.Stat(dir); err != nil { + if os.IsNotExist(err) { + return nil, nil + } + return nil, fmt.Errorf("stat logs dir: %w", err) + } + + if !all { + name := fmt.Sprintf( + "msgvault-%s.log", time.Now().UTC().Format("2006-01-02"), + ) + path := filepath.Join(dir, name) + if _, err := os.Stat(path); err == nil { + return []string{path}, nil + } + // Fall through to the --all scan; maybe we only have + // yesterday's file. + } + + entries, err := os.ReadDir(dir) + if err != nil { + return nil, fmt.Errorf("read logs dir: %w", err) + } + var files []string + for _, e := range entries { + if e.IsDir() { + continue + } + n := e.Name() + if !strings.HasPrefix(n, "msgvault-") || + !(strings.HasSuffix(n, ".log") || + strings.Contains(n, ".log.")) { + continue + } + files = append(files, filepath.Join(dir, n)) + } + sort.Strings(files) + return files, nil +} + +// logFilter represents the user's --run-id / --level / --grep +// filters. An empty field means "no filter on that axis". +type logFilter struct { + RunID string + Level string + Grep string +} + +// matches reports whether a record matches every active filter. +func (f logFilter) matches(raw []byte, rec map[string]any) bool { + if f.RunID != "" { + if got, _ := rec["run_id"].(string); !strings.HasPrefix(got, f.RunID) { + return false + } + } + if f.Level != "" { + if got, _ := rec["level"].(string); !strings.EqualFold(got, f.Level) { + return false + } + } + if f.Grep != "" { + if !strings.Contains(string(raw), f.Grep) { + return false + } + } + return true +} + +// printLogFiles prints the last tailN filtered lines across the +// supplied files. Keeping a fixed-size ring buffer keeps memory +// bounded even on very large log files. +func printLogFiles( + files []string, tailN int, filter logFilter, out io.Writer, +) error { + if tailN <= 0 { + tailN = 50 + } + ring := make([]string, 0, tailN) + push := func(line string) { + if len(ring) == tailN { + ring = ring[1:] + } + ring = append(ring, line) + } + + for _, path := range files { + f, err := os.Open(path) + if err != nil { + return fmt.Errorf("open %s: %w", path, err) + } + scanner := bufio.NewScanner(f) + scanner.Buffer(make([]byte, 1024*1024), 4*1024*1024) + for scanner.Scan() { + raw := scanner.Bytes() + var rec map[string]any + if err := json.Unmarshal(raw, &rec); err != nil { + // Non-JSON lines (shouldn't happen in file + // output, but be safe). + continue + } + if !filter.matches(raw, rec) { + continue + } + push(formatLogRecord(rec)) + } + _ = f.Close() + if err := scanner.Err(); err != nil { + return fmt.Errorf("scan %s: %w", path, err) + } + } + for _, line := range ring { + fmt.Fprintln(out, line) + } + return nil +} + +// followLogFile tails path for new lines as they're written and +// prints those that match filter. Exits when the command context +// is cancelled (Ctrl-C). +func followLogFile( + ctx context.Context, path string, filter logFilter, out io.Writer, +) error { + f, err := os.Open(path) + if err != nil { + return fmt.Errorf("open %s: %w", path, err) + } + defer func() { _ = f.Close() }() + + if _, err := f.Seek(0, io.SeekEnd); err != nil { + return fmt.Errorf("seek end: %w", err) + } + + reader := bufio.NewReader(f) + for { + select { + case <-ctx.Done(): + return nil + default: + } + line, err := reader.ReadBytes('\n') + if len(line) > 0 { + var rec map[string]any + if json.Unmarshal(line, &rec) == nil && + filter.matches(line, rec) { + fmt.Fprintln(out, formatLogRecord(rec)) + } + continue + } + if err != nil && err != io.EOF { + return err + } + select { + case <-ctx.Done(): + return nil + case <-time.After(300 * time.Millisecond): + } + } +} + +// formatLogRecord renders a JSON log record as a compact, human +// readable line. The interesting attributes come after the +// message; we deliberately drop the source attribute for brevity. +func formatLogRecord(rec map[string]any) string { + level, _ := rec["level"].(string) + msg, _ := rec["msg"].(string) + runID, _ := rec["run_id"].(string) + ts, _ := rec["time"].(string) + + // Collect the remaining interesting attributes in a stable + // order. Known low-signal keys are skipped. + skip := map[string]bool{ + "level": true, "msg": true, "run_id": true, + "time": true, "source": true, + } + keys := make([]string, 0, len(rec)) + for k := range rec { + if !skip[k] { + keys = append(keys, k) + } + } + sort.Strings(keys) + + var b strings.Builder + if ts != "" { + // Keep just HH:MM:SS for readability — the file name + // already encodes the date. + if t, err := time.Parse(time.RFC3339Nano, ts); err == nil { + b.WriteString(t.Local().Format("15:04:05")) + b.WriteByte(' ') + } + } + if level != "" { + b.WriteString(fmt.Sprintf("%-5s", level)) + b.WriteByte(' ') + } + if runID != "" { + // Show first 6 chars so the column stays aligned. + short := runID + if len(short) > 6 { + short = short[:6] + } + b.WriteString(short) + b.WriteByte(' ') + } + b.WriteString(msg) + for _, k := range keys { + b.WriteString(" ") + b.WriteString(k) + b.WriteString("=") + b.WriteString(fmt.Sprint(rec[k])) + } + return b.String() +} + +func init() { + logsCmd.Flags().BoolVarP(&logsFollow, "follow", "f", false, + "follow today's log file as new lines are written") + logsCmd.Flags().IntVarP(&logsLines, "lines", "n", 50, + "number of trailing lines to show before following") + logsCmd.Flags().StringVar(&logsRunID, "run-id", "", + "filter to a single run (matches on prefix)") + logsCmd.Flags().StringVar(&logsLevel, "level", "", + "filter by log level: debug, info, warn, error") + logsCmd.Flags().StringVar(&logsGrep, "grep", "", + "substring filter applied to the raw JSON record") + logsCmd.Flags().BoolVar(&logsAll, "all", false, + "read every log file in the logs directory, not just today's") + logsCmd.Flags().BoolVar(&logsPath, "path", false, + "print the log directory path and exit") + rootCmd.AddCommand(logsCmd) +} diff --git a/cmd/msgvault/cmd/root.go b/cmd/msgvault/cmd/root.go index 63a74dcd..fc5879b7 100644 --- a/cmd/msgvault/cmd/root.go +++ b/cmd/msgvault/cmd/root.go @@ -7,22 +7,31 @@ import ( "log/slog" "os" "path/filepath" + "runtime" + "runtime/debug" + "strings" "sync" "github.com/spf13/cobra" "github.com/wesm/msgvault/internal/config" + "github.com/wesm/msgvault/internal/logging" "github.com/wesm/msgvault/internal/oauth" "github.com/wesm/msgvault/internal/store" "golang.org/x/oauth2" ) var ( - cfgFile string - homeDir string - verbose bool - useLocal bool // Force local database even when remote is configured - cfg *config.Config - logger *slog.Logger + cfgFile string + homeDir string + verbose bool + useLocal bool // Force local database even when remote is configured + logFile string + logLevel string + noLogFile bool + cfg *config.Config + logger *slog.Logger + logResult *logging.Result // non-nil after PersistentPreRunE runs + currentRun string // short ID attached to every log record ) var rootCmd = &cobra.Command{ @@ -34,37 +43,145 @@ email data locally with full-text search capabilities. This is the Go implementation providing sync, search, and TUI functionality in a single binary.`, PersistentPreRunE: func(cmd *cobra.Command, args []string) error { - // Skip config loading for commands that don't need it - if cmd.Name() == "version" || cmd.Name() == "update" || cmd.Name() == "quickstart" || cmd.Name() == "completion" || cmd.Name() == cobra.ShellCompRequestCmd || cmd.Name() == cobra.ShellCompNoDescRequestCmd { + // Skip config loading (and therefore logging setup) for + // commands that must run without touching disk or config. + if cmd.Name() == "version" || cmd.Name() == "update" || + cmd.Name() == "quickstart" || cmd.Name() == "completion" || + cmd.Name() == cobra.ShellCompRequestCmd || + cmd.Name() == cobra.ShellCompNoDescRequestCmd { return nil } - // Set up logging - level := slog.LevelInfo - if verbose { - level = slog.LevelDebug - } - logger = slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{ - Level: level, - })) - - // Load config (--home is passed through so it influences - // where config.toml is loaded from, like MSGVAULT_HOME). + // Load config first; logging options live under [log]. var err error cfg, err = config.Load(cfgFile, homeDir) if err != nil { return fmt.Errorf("load config: %w", err) } - - // Ensure home directory exists on first use if err := cfg.EnsureHomeDir(); err != nil { - return fmt.Errorf("create data directory %s: %w", cfg.HomeDir, err) + return fmt.Errorf( + "create data directory %s: %w", + cfg.HomeDir, err, + ) } + // Resolve logging options. CLI flags override config; + // --verbose forces debug level regardless of other + // settings. + var levelOverride *slog.Level + if verbose { + lv := slog.LevelDebug + levelOverride = &lv + } + levelString := logLevel + if levelString == "" { + levelString = cfg.Log.Level + } + logsDir := cfg.LogsDir() + if logFile != "" { + // Treat --log-file as an override for the whole + // path, not just the directory, so power users + // can pipe today's run anywhere. + logsDir = filepath.Dir(logFile) + } + fileDisabled := noLogFile || cfg.Log.Disabled + + logResult, err = logging.BuildHandler(logging.Options{ + LogsDir: logsDir, + FileDisabled: fileDisabled, + LevelOverride: levelOverride, + LevelString: levelString, + }) + if err != nil { + return fmt.Errorf("build logger: %w", err) + } + logger = slog.New(logResult.Handler) + currentRun = logResult.RunID + slog.SetDefault(logger) + + // Startup header: one structured line per run that + // captures everything you'd want to correlate later. + // This is what makes `grep ` actually useful. + logger.Info("msgvault startup", + "command", cmd.CommandPath(), + "args", sanitizeArgs(args), + "version", Version, + "go_version", runtime.Version(), + "os", runtime.GOOS, + "arch", runtime.GOARCH, + "config_path", cfg.ConfigFilePath(), + "data_dir", cfg.Data.DataDir, + "log_file", logResult.FilePath, + "level", logResult.Level.String(), + ) return nil }, } +// sanitizeArgs removes anything that might carry a secret before +// the argv hits the log file. Values for flags known to contain +// credentials (--password, --token, --client-secret, ...) are +// replaced with "". Unknown flags pass through so the +// log still captures the user's intent. +func sanitizeArgs(args []string) []string { + out := make([]string, 0, len(args)) + redactNext := false + sensitive := map[string]bool{ + "--password": true, + "--token": true, + "--client-secret": true, + "--access-token": true, + "--refresh-token": true, + "--client-secrets": true, + } + for _, a := range args { + if redactNext { + out = append(out, "") + redactNext = false + continue + } + if eq := strings.IndexByte(a, '='); eq != -1 { + key := a[:eq] + if sensitive[key] { + out = append(out, key+"=") + continue + } + } + if sensitive[a] { + out = append(out, a) + redactNext = true + continue + } + out = append(out, a) + } + return out +} + +// recoverAndLogPanic catches a panic and records it as a single +// structured log line with a stack trace before re-raising the +// process exit. Called in a deferred statement at the top of +// Execute/ExecuteContext so crashes always leave a trail on disk. +func recoverAndLogPanic() { + r := recover() + if r == nil { + return + } + if logger != nil { + logger.Error("msgvault panic", + "panic", fmt.Sprint(r), + "stack", string(debug.Stack()), + ) + } else { + fmt.Fprintf(os.Stderr, + "msgvault panic: %v\n%s\n", r, debug.Stack(), + ) + } + if logResult != nil { + logResult.Close() + } + os.Exit(2) +} + // Execute runs the root command with a background context. // Prefer ExecuteContext for signal-aware execution. func Execute() error { @@ -73,8 +190,30 @@ func Execute() error { // ExecuteContext runs the root command with the given context, // enabling graceful shutdown when the context is cancelled. +// Installs a panic recovery and closes the log file handler on +// return so every run ends cleanly in the log. func ExecuteContext(ctx context.Context) error { - return rootCmd.ExecuteContext(ctx) + defer recoverAndLogPanic() + defer func() { + if logResult != nil { + logResult.Close() + } + }() + + err := rootCmd.ExecuteContext(ctx) + + // Record the exit outcome so users can see the per-run + // result in the log without parsing error messages. + if logger != nil { + if err != nil { + logger.Info("msgvault exit", + "outcome", "error", "error", err.Error(), + ) + } else { + logger.Info("msgvault exit", "outcome", "ok") + } + } + return err } // oauthSetupHint returns help text for OAuth configuration issues, @@ -279,6 +418,12 @@ func sourceOAuthApp(src *store.Source) string { func init() { rootCmd.PersistentFlags().StringVar(&cfgFile, "config", "", "config file (default: ~/.msgvault/config.toml)") rootCmd.PersistentFlags().StringVar(&homeDir, "home", "", "home directory (overrides MSGVAULT_HOME)") - rootCmd.PersistentFlags().BoolVarP(&verbose, "verbose", "v", false, "verbose output") + rootCmd.PersistentFlags().BoolVarP(&verbose, "verbose", "v", false, "verbose output (implies --log-level=debug)") rootCmd.PersistentFlags().BoolVar(&useLocal, "local", false, "force local database (override remote config)") + rootCmd.PersistentFlags().StringVar(&logFile, "log-file", "", + "override log file path (default: /logs/msgvault-YYYY-MM-DD.log)") + rootCmd.PersistentFlags().StringVar(&logLevel, "log-level", "", + "log level: debug, info, warn, error (default: info)") + rootCmd.PersistentFlags().BoolVar(&noLogFile, "no-log-file", false, + "disable the log file for this run (stderr output stays on)") } diff --git a/internal/config/config.go b/internal/config/config.go index 061262e2..1f0a5047 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -71,6 +71,7 @@ type RemoteConfig struct { // Config represents the msgvault configuration. type Config struct { Data DataConfig `toml:"data"` + Log LogConfig `toml:"log"` OAuth OAuthConfig `toml:"oauth"` Microsoft MicrosoftConfig `toml:"microsoft"` Sync SyncConfig `toml:"sync"` @@ -84,6 +85,26 @@ type Config struct { configPath string // resolved path to the loaded config file } +// LogConfig holds logging configuration. Defaults to writing one +// file per day under ~/.msgvault/logs/ alongside the stderr output +// that every command has always produced. Callers that want to +// suppress file logging entirely can set Disabled or pass the +// --no-log-file flag. +type LogConfig struct { + // Dir is the directory where log files live. Empty means + // "/logs", which is the recommended default. + Dir string `toml:"dir"` + + // Level overrides the default logging level. Accepted values + // are "debug", "info", "warn", "error". Empty means "info" + // (or "debug" when --verbose is passed). + Level string `toml:"level"` + + // Disabled turns off file logging entirely. The CLI will + // continue writing to stderr. + Disabled bool `toml:"disabled"` +} + // DataConfig holds data storage configuration. type DataConfig struct { DataDir string `toml:"data_dir"` @@ -294,6 +315,15 @@ func (c *Config) AnalyticsDir() string { return filepath.Join(c.Data.DataDir, "analytics") } +// LogsDir returns the path to the logs directory. Uses [log].dir +// from config when set; otherwise falls back to /logs. +func (c *Config) LogsDir() string { + if c.Log.Dir != "" { + return c.Log.Dir + } + return filepath.Join(c.Data.DataDir, "logs") +} + // EnsureHomeDir creates the msgvault home directory if it doesn't exist. func (c *Config) EnsureHomeDir() error { return fileutil.SecureMkdirAll(c.HomeDir, 0700) diff --git a/internal/logging/logging.go b/internal/logging/logging.go new file mode 100644 index 00000000..c68d8427 --- /dev/null +++ b/internal/logging/logging.go @@ -0,0 +1,337 @@ +// Package logging builds the slog handler used by every msgvault +// command. +// +// Design goals (CLAUDE.md's "Safety ergonomics" principle, applied +// to observability): +// +// 1. Every CLI run leaves a durable, structured trail on disk +// without the user having to redirect stderr themselves. The +// default log directory is /logs and files are named +// msgvault-YYYY-MM-DD.log (UTC). +// 2. On-disk logs are structured JSON so they're greppable with +// jq and mechanically parseable. Interactive stderr output +// stays human-readable text. +// 3. Every run gets a run_id attribute, attached to every log +// line, so you can grep one invocation out of a shared file +// even when two commands run in parallel. +// 4. Failures in the logging subsystem NEVER break the CLI. If +// the log file can't be opened, BuildHandler degrades to +// stderr-only logging with a one-line warning. +// +// slog.Handler does not ship a fan-out implementation, so this +// package provides a tiny multiHandler that forwards records to +// any number of child handlers. That lets the stderr text handler +// and the file JSON handler stay independent — different formats, +// potentially different levels — without double-serializing the +// same record. +package logging + +import ( + "context" + "crypto/rand" + "encoding/hex" + "errors" + "fmt" + "io" + "log/slog" + "os" + "path/filepath" + "strings" + "time" +) + +// Options controls how BuildHandler constructs the slog handler. +type Options struct { + // LogsDir is the directory in which daily log files are + // written. Required unless FileDisabled is true. + LogsDir string + + // FileDisabled turns off file logging entirely. Stderr + // output still happens. Use this for one-shot runs or for + // tests that want to avoid writing to disk. + FileDisabled bool + + // LevelOverride, when non-nil, forces the level. Otherwise + // the level is taken from LevelString (config) and falls + // back to Info. + LevelOverride *slog.Level + + // LevelString is the textual level from config. Accepts + // "debug", "info", "warn", "warning", "error". Empty means + // "info". + LevelString string + + // MaxFileBytes caps a single log file. When a file exceeds + // this size at open time, it is rotated to a numbered + // suffix (.1, .2, ...) before the current run appends. Zero + // means 50 MiB. + MaxFileBytes int64 + + // KeepRotated caps how many rotated siblings are kept per + // day. Older ones are deleted. Zero means 5. + KeepRotated int + + // Stderr is the writer used for interactive output. Nil + // defaults to os.Stderr. Tests override this to capture. + Stderr io.Writer + + // Now is injected for deterministic filenames in tests. + // Nil defaults to time.Now. + Now func() time.Time +} + +// Result holds the constructed handler plus the resolved log file +// path (empty when file logging is disabled) and any teardown +// closures the caller should run at shutdown. +type Result struct { + Handler slog.Handler + Level slog.Level + RunID string + FilePath string + closers []func() +} + +// Close releases file handles held by the handler. Safe to call +// multiple times. +func (r *Result) Close() { + for i := len(r.closers) - 1; i >= 0; i-- { + r.closers[i]() + } + r.closers = nil +} + +// BuildHandler constructs the slog handler configured according to +// Options. It: +// +// - creates the logs directory on demand, +// - rotates the daily file if it exceeds MaxFileBytes, +// - opens (or creates) today's file in append mode, +// - generates a 6-byte run_id and attaches it to every record, +// - returns a multi-handler that fans records out to a human +// text handler on stderr and a JSON handler on the file. +// +// If the file path can't be prepared, the function continues with +// stderr-only logging and records the degradation in Result.FilePath +// (empty string). +func BuildHandler(opts Options) (*Result, error) { + stderr := opts.Stderr + if stderr == nil { + stderr = os.Stderr + } + now := opts.Now + if now == nil { + now = time.Now + } + if opts.MaxFileBytes <= 0 { + opts.MaxFileBytes = 50 * 1024 * 1024 + } + if opts.KeepRotated <= 0 { + opts.KeepRotated = 5 + } + + level := parseLevel(opts.LevelString) + if opts.LevelOverride != nil { + level = *opts.LevelOverride + } + + res := &Result{Level: level, RunID: newRunID()} + + // Always build the stderr text handler. + stderrH := slog.NewTextHandler(stderr, &slog.HandlerOptions{ + Level: level, + }) + handlers := []slog.Handler{stderrH} + + // Best-effort file handler. + if !opts.FileDisabled && opts.LogsDir != "" { + path, f, err := openDailyLogFile( + opts.LogsDir, now(), + opts.MaxFileBytes, opts.KeepRotated, + ) + switch { + case err == nil: + fileH := slog.NewJSONHandler(f, &slog.HandlerOptions{ + Level: level, + }) + handlers = append(handlers, fileH) + res.FilePath = path + res.closers = append(res.closers, func() { + _ = f.Close() + }) + default: + fmt.Fprintf(stderr, + "warning: could not open msgvault log file in %s: %v "+ + "(continuing with stderr-only logging)\n", + opts.LogsDir, err, + ) + } + } + + var h slog.Handler + if len(handlers) == 1 { + h = handlers[0] + } else { + h = newMultiHandler(handlers...) + } + + // Every record in this process carries run_id so users can + // correlate lines from the shared log file back to a single + // invocation. + h = h.WithAttrs([]slog.Attr{slog.String("run_id", res.RunID)}) + res.Handler = h + return res, nil +} + +// newRunID returns a 6-byte hex string for attaching to every log +// record in this process. The alphabet and length are picked to +// stay short enough to eyeball in a shared log file but wide +// enough that two concurrent runs effectively never collide. +func newRunID() string { + var b [6]byte + if _, err := rand.Read(b[:]); err != nil { + // Fall back to time-based id; collisions are tolerable + // because the user never relies on this for uniqueness + // guarantees — it's a correlation aid, not a key. + return fmt.Sprintf("%012x", time.Now().UnixNano()) + } + return hex.EncodeToString(b[:]) +} + +// openDailyLogFile opens (or creates) /msgvault-YYYY-MM-DD.log +// in append mode. If the file already exists and exceeds maxBytes, +// it is rotated out to a numbered sibling (.1, .2, ...) before +// being reopened fresh. Older siblings beyond keepRotated are +// deleted. +func openDailyLogFile( + dir string, now time.Time, maxBytes int64, keepRotated int, +) (string, *os.File, error) { + if err := os.MkdirAll(dir, 0o700); err != nil { + return "", nil, fmt.Errorf("mkdir logs dir: %w", err) + } + name := fmt.Sprintf( + "msgvault-%s.log", now.UTC().Format("2006-01-02"), + ) + path := filepath.Join(dir, name) + + if fi, err := os.Stat(path); err == nil && fi.Size() >= maxBytes { + if rotErr := rotate(path, keepRotated); rotErr != nil { + return "", nil, fmt.Errorf("rotate: %w", rotErr) + } + } else if err != nil && !errors.Is(err, os.ErrNotExist) { + return "", nil, fmt.Errorf("stat log file: %w", err) + } + + f, err := os.OpenFile( + path, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o600, + ) + if err != nil { + return "", nil, fmt.Errorf("open log file: %w", err) + } + return path, f, nil +} + +// rotate moves path -> path.1, path.1 -> path.2, etc., up to +// keep copies. Files beyond keep are deleted. +func rotate(path string, keep int) error { + // Walk from the oldest to the newest, shifting each slot up + // by one. Start from keep-1 so the last survivor lands at + // path.keep and anything beyond is unlinked. + for i := keep; i >= 1; i-- { + src := fmt.Sprintf("%s.%d", path, i-1) + if i-1 == 0 { + src = path + } + dst := fmt.Sprintf("%s.%d", path, i) + + if i == keep { + // This slot would fall out of the window; remove + // the current occupant if any before shifting. + _ = os.Remove(dst) + } + if _, err := os.Stat(src); err != nil { + if errors.Is(err, os.ErrNotExist) { + continue + } + return err + } + if err := os.Rename(src, dst); err != nil { + return err + } + } + return nil +} + +// parseLevel maps a user-friendly level string to slog.Level. +// Defaults to Info for unknown or empty values. +func parseLevel(s string) slog.Level { + switch strings.ToLower(strings.TrimSpace(s)) { + case "debug": + return slog.LevelDebug + case "warn", "warning": + return slog.LevelWarn + case "error": + return slog.LevelError + case "info", "": + return slog.LevelInfo + default: + return slog.LevelInfo + } +} + +// multiHandler fans slog records out to several child handlers. +// slog.Handler does not ship a fan-out impl, and wrapping a +// io.MultiWriter forces one serialization format for both sinks; +// we want text on stderr and JSON on disk. +type multiHandler struct { + children []slog.Handler +} + +func newMultiHandler(children ...slog.Handler) slog.Handler { + copied := make([]slog.Handler, len(children)) + copy(copied, children) + return &multiHandler{children: copied} +} + +func (m *multiHandler) Enabled( + ctx context.Context, level slog.Level, +) bool { + for _, h := range m.children { + if h.Enabled(ctx, level) { + return true + } + } + return false +} + +func (m *multiHandler) Handle( + ctx context.Context, r slog.Record, +) error { + var firstErr error + for _, h := range m.children { + if !h.Enabled(ctx, r.Level) { + continue + } + if err := h.Handle(ctx, r.Clone()); err != nil && firstErr == nil { + firstErr = err + } + } + return firstErr +} + +func (m *multiHandler) WithAttrs( + attrs []slog.Attr, +) slog.Handler { + nc := make([]slog.Handler, len(m.children)) + for i, h := range m.children { + nc[i] = h.WithAttrs(attrs) + } + return &multiHandler{children: nc} +} + +func (m *multiHandler) WithGroup(name string) slog.Handler { + nc := make([]slog.Handler, len(m.children)) + for i, h := range m.children { + nc[i] = h.WithGroup(name) + } + return &multiHandler{children: nc} +} diff --git a/internal/logging/logging_test.go b/internal/logging/logging_test.go new file mode 100644 index 00000000..764517c3 --- /dev/null +++ b/internal/logging/logging_test.go @@ -0,0 +1,206 @@ +package logging + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "os" + "path/filepath" + "strings" + "testing" + "time" +) + +func TestBuildHandler_WritesToFileAndStderr(t *testing.T) { + dir := t.TempDir() + var stderr bytes.Buffer + fixed := time.Date(2026, 4, 11, 12, 0, 0, 0, time.UTC) + + res, err := BuildHandler(Options{ + LogsDir: dir, + LevelString: "info", + Stderr: &stderr, + Now: func() time.Time { return fixed }, + }) + if err != nil { + t.Fatalf("BuildHandler: %v", err) + } + defer res.Close() + + logger := slog.New(res.Handler) + logger.Info("hello", "key", "value") + + // Stderr got a text record. + if !strings.Contains(stderr.String(), "hello") { + t.Errorf("stderr missing msg: %q", stderr.String()) + } + if !strings.Contains(stderr.String(), "run_id="+res.RunID) { + t.Errorf("stderr missing run_id") + } + + // Log file path uses today's UTC date. + want := filepath.Join(dir, "msgvault-2026-04-11.log") + if res.FilePath != want { + t.Errorf("FilePath = %q, want %q", res.FilePath, want) + } + + // File got a JSON record. + data, err := os.ReadFile(res.FilePath) + if err != nil { + t.Fatalf("read log file: %v", err) + } + var rec map[string]any + if err := json.Unmarshal( + bytes.TrimSpace(data), &rec, + ); err != nil { + t.Fatalf("log file is not JSON: %v\n%s", err, data) + } + if rec["msg"] != "hello" { + t.Errorf("msg = %v, want hello", rec["msg"]) + } + if rec["run_id"] != res.RunID { + t.Errorf("run_id = %v, want %s", rec["run_id"], res.RunID) + } + if rec["level"] != "INFO" { + t.Errorf("level = %v, want INFO", rec["level"]) + } +} + +func TestBuildHandler_FileDisabledKeepsStderr(t *testing.T) { + var stderr bytes.Buffer + res, err := BuildHandler(Options{ + FileDisabled: true, + LevelString: "info", + Stderr: &stderr, + }) + if err != nil { + t.Fatalf("BuildHandler: %v", err) + } + defer res.Close() + + if res.FilePath != "" { + t.Errorf("FilePath = %q, want empty", res.FilePath) + } + slog.New(res.Handler).Info("no-file") + if !strings.Contains(stderr.String(), "no-file") { + t.Errorf("stderr missing msg: %q", stderr.String()) + } +} + +func TestBuildHandler_LevelOverrideBeatsLevelString(t *testing.T) { + var stderr bytes.Buffer + debug := slog.LevelDebug + res, err := BuildHandler(Options{ + FileDisabled: true, + LevelString: "error", + LevelOverride: &debug, + Stderr: &stderr, + }) + if err != nil { + t.Fatalf("BuildHandler: %v", err) + } + defer res.Close() + + if res.Level != slog.LevelDebug { + t.Errorf("Level = %v, want Debug", res.Level) + } + logger := slog.New(res.Handler) + logger.Debug("dbg-line") + if !strings.Contains(stderr.String(), "dbg-line") { + t.Errorf("debug line missing: %q", stderr.String()) + } +} + +func TestRotate_RotatesDailyFileOverLimit(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "msgvault-2026-04-11.log") + // Seed a "big" file so BuildHandler will rotate it. + if err := os.WriteFile( + path, bytes.Repeat([]byte("x"), 200), 0o600, + ); err != nil { + t.Fatalf("seed: %v", err) + } + + res, err := BuildHandler(Options{ + LogsDir: dir, + LevelString: "info", + MaxFileBytes: 100, // force rotation + KeepRotated: 3, + Stderr: &bytes.Buffer{}, + Now: func() time.Time { + return time.Date(2026, 4, 11, 0, 0, 0, 0, time.UTC) + }, + }) + if err != nil { + t.Fatalf("BuildHandler: %v", err) + } + defer res.Close() + + // Old file must now live at .1; new file is path itself. + if _, err := os.Stat(path + ".1"); err != nil { + t.Errorf("rotated sibling missing: %v", err) + } + fi, err := os.Stat(path) + if err != nil { + t.Fatalf("current log missing: %v", err) + } + if fi.Size() >= 200 { + t.Errorf("new log should start empty or small, size=%d", fi.Size()) + } +} + +func TestParseLevel(t *testing.T) { + cases := map[string]slog.Level{ + "": slog.LevelInfo, + "info": slog.LevelInfo, + "INFO": slog.LevelInfo, + "debug": slog.LevelDebug, + "warn": slog.LevelWarn, + "warning": slog.LevelWarn, + "error": slog.LevelError, + "garbage": slog.LevelInfo, + } + for in, want := range cases { + if got := parseLevel(in); got != want { + t.Errorf("parseLevel(%q) = %v, want %v", in, got, want) + } + } +} + +func TestMultiHandler_FansOutAndFiltersByLevel(t *testing.T) { + var textBuf, jsonBuf bytes.Buffer + textH := slog.NewTextHandler(&textBuf, &slog.HandlerOptions{ + Level: slog.LevelWarn, + }) + jsonH := slog.NewJSONHandler(&jsonBuf, &slog.HandlerOptions{ + Level: slog.LevelDebug, + }) + m := newMultiHandler(textH, jsonH) + + logger := slog.New(m.WithAttrs( + []slog.Attr{slog.String("run_id", "abc123")}, + )) + logger.DebugContext(context.Background(), "dbg") + logger.Warn("warned") + + // Text handler ignores debug, JSON handler keeps it. + if strings.Contains(textBuf.String(), "dbg") { + t.Errorf("text handler should not have debug, got %q", + textBuf.String()) + } + if !strings.Contains(jsonBuf.String(), "dbg") { + t.Errorf("json handler missing debug, got %q", jsonBuf.String()) + } + // Both handlers must see the Warn. + if !strings.Contains(textBuf.String(), "warned") { + t.Errorf("text handler missing warn: %q", textBuf.String()) + } + if !strings.Contains(jsonBuf.String(), "warned") { + t.Errorf("json handler missing warn: %q", jsonBuf.String()) + } + // Attr fan-out should include run_id in both. + if !strings.Contains(jsonBuf.String(), "abc123") { + t.Errorf("json handler lost run_id: %q", jsonBuf.String()) + } +} diff --git a/internal/tui/model.go b/internal/tui/model.go index 7f1f7d4e..ce756a01 100644 --- a/internal/tui/model.go +++ b/internal/tui/model.go @@ -4,6 +4,7 @@ package tui import ( "context" "fmt" + "log/slog" "strings" "time" @@ -389,8 +390,16 @@ func (m Model) loadStats() tea.Cmd { func (m Model) loadAccounts() tea.Cmd { return safeCmdWithPanic( func() tea.Msg { - accounts, err := m.engine.ListAccounts(context.Background()) - return accountsLoadedMsg{accounts: accounts, err: err} + ctx := context.Background() + accounts, err := m.engine.ListAccounts(ctx) + if err != nil { + slog.Warn("tui loadAccounts: ListAccounts failed", + "error", err) + return accountsLoadedMsg{err: err} + } + slog.Info("tui loadAccounts ok", + "accounts", len(accounts)) + return accountsLoadedMsg{accounts: accounts} }, func(r any) tea.Msg { return accountsLoadedMsg{err: fmt.Errorf("accounts panic: %v", r)} From 92e7fcf9cee79c82535c6e89906ce9a6f8209d0c Mon Sep 17 00:00:00 2001 From: Jesse Robbins Date: Mon, 13 Apr 2026 09:28:21 -0700 Subject: [PATCH 02/10] Log every user-visible operation with duration and scope Add structured slog calls to search, stats, list-accounts, and the TUI (loadData, loadMessages, loadSearchWithOffset). Each emits start/done/fail lines with duration_ms so the daily log file gives a full audit trail of what ran. Initialise the package-level logger to a stderr text handler at declaration time so code paths that bypass PersistentPreRunE (tests, library embeds) never hit a nil pointer. Co-Authored-By: Claude Sonnet 4.6 --- cmd/msgvault/cmd/list_accounts.go | 4 ++ cmd/msgvault/cmd/root.go | 23 ++++---- cmd/msgvault/cmd/search.go | 29 ++++++++++ cmd/msgvault/cmd/stats.go | 9 ++++ internal/tui/model.go | 88 +++++++++++++++++++++++++++++++ 5 files changed, 144 insertions(+), 9 deletions(-) diff --git a/cmd/msgvault/cmd/list_accounts.go b/cmd/msgvault/cmd/list_accounts.go index 2eb3f424..b21b313b 100644 --- a/cmd/msgvault/cmd/list_accounts.go +++ b/cmd/msgvault/cmd/list_accounts.go @@ -113,6 +113,10 @@ func listLocalAccounts() error { } } + logger.Info("list-accounts", + "sources", len(stats), + ) + if listAccountsJSON { return outputAccountsJSON(stats) } diff --git a/cmd/msgvault/cmd/root.go b/cmd/msgvault/cmd/root.go index fc5879b7..d185001f 100644 --- a/cmd/msgvault/cmd/root.go +++ b/cmd/msgvault/cmd/root.go @@ -21,15 +21,20 @@ import ( ) var ( - cfgFile string - homeDir string - verbose bool - useLocal bool // Force local database even when remote is configured - logFile string - logLevel string - noLogFile bool - cfg *config.Config - logger *slog.Logger + cfgFile string + homeDir string + verbose bool + useLocal bool // Force local database even when remote is configured + logFile string + logLevel string + noLogFile bool + cfg *config.Config + // logger is always non-nil so code paths outside the normal + // PersistentPreRunE flow (tests, library embeds) don't have + // to nil-check before calling logger.Info. PersistentPreRunE + // replaces this with a properly configured multi-handler at + // CLI startup. + logger = slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: slog.LevelInfo})) logResult *logging.Result // non-nil after PersistentPreRunE runs currentRun string // short ID attached to every log record ) diff --git a/cmd/msgvault/cmd/search.go b/cmd/msgvault/cmd/search.go index e3c91988..0b6d74ad 100644 --- a/cmd/msgvault/cmd/search.go +++ b/cmd/msgvault/cmd/search.go @@ -146,13 +146,42 @@ func runLocalSearch(cmd *cobra.Command, queryStr string) error { return err } + // Log the search operation so it's auditable in the daily + // log file alongside every other command. + scopeKind := "all" + scopeValue := "" + if q.AccountID != nil { + scopeKind = "source" + scopeValue = searchAccount + } + logger.Info("search start", + "query", queryStr, + "scope", scopeKind, + "account", scopeValue, + "limit", searchLimit, + "offset", searchOffset, + ) + started := time.Now() + // Create query engine and execute search engine := query.NewSQLiteEngine(s.DB()) results, err := engine.Search(cmd.Context(), q, searchLimit, searchOffset) fmt.Fprintf(os.Stderr, "\r \r") if err != nil { + logger.Warn("search failed", + "query", queryStr, + "duration_ms", time.Since(started).Milliseconds(), + "error", err.Error(), + ) return query.HintRepairEncoding(fmt.Errorf("search: %w", err)) } + logger.Info("search done", + "query", queryStr, + "scope", scopeKind, + "account", scopeValue, + "results", len(results), + "duration_ms", time.Since(started).Milliseconds(), + ) if len(results) == 0 { fmt.Println("No messages found.") diff --git a/cmd/msgvault/cmd/stats.go b/cmd/msgvault/cmd/stats.go index 6160e39f..a66b1181 100644 --- a/cmd/msgvault/cmd/stats.go +++ b/cmd/msgvault/cmd/stats.go @@ -22,8 +22,17 @@ Use --local to force local database.`, stats, err := s.GetStats() if err != nil { + logger.Warn("stats failed", "error", err.Error()) return fmt.Errorf("get stats: %w", err) } + logger.Info("stats", + "messages", stats.MessageCount, + "threads", stats.ThreadCount, + "attachments", stats.AttachmentCount, + "labels", stats.LabelCount, + "accounts", stats.SourceCount, + "db_bytes", stats.DatabaseSize, + ) // Show source indicator if IsRemoteMode() { diff --git a/internal/tui/model.go b/internal/tui/model.go index ce756a01..53151932 100644 --- a/internal/tui/model.go +++ b/internal/tui/model.go @@ -312,6 +312,22 @@ type accountsLoadedMsg struct { err error } +// scopeLabelForLog returns a short, stable string describing the +// current account scope so it can be attached to log records +// without exposing internal ID values. +func (m Model) scopeLabelForLog() string { + switch { + case m.accountFilter != nil: + for _, acc := range m.accounts { + if acc.ID == *m.accountFilter { + return "source:" + acc.Identifier + } + } + return "source:unknown" + } + return "all" +} + // updateCheckMsg is sent when the background update check completes. type updateCheckMsg struct { version string // Latest version if available @@ -321,6 +337,9 @@ type updateCheckMsg struct { // loadData fetches aggregate data based on current view settings. func (m Model) loadData() tea.Cmd { requestID := m.aggregateRequestID + scopeLabel := m.scopeLabelForLog() + viewLabel := m.viewType.String() + searchTerm := m.searchQuery return safeCmdWithPanic( func() tea.Msg { opts := query.AggregateOptions{ @@ -334,6 +353,7 @@ func (m Model) loadData() tea.Cmd { SearchQuery: m.searchQuery, } + start := time.Now() ctx := context.Background() var rows []query.AggregateRow var err error @@ -344,6 +364,23 @@ func (m Model) loadData() tea.Cmd { } else { rows, err = m.engine.Aggregate(ctx, m.viewType, opts) } + if err != nil { + slog.Warn("tui loadData failed", + "view", viewLabel, + "scope", scopeLabel, + "search", searchTerm, + "error", err.Error(), + "duration_ms", time.Since(start).Milliseconds(), + ) + } else { + slog.Info("tui loadData ok", + "view", viewLabel, + "scope", scopeLabel, + "search", searchTerm, + "rows", len(rows), + "duration_ms", time.Since(start).Milliseconds(), + ) + } // When search is active, compute distinct message stats separately. // Summing row.Count across groups overcounts for 1:N views (Recipients, Labels) @@ -492,16 +529,45 @@ func (m Model) loadSearch(queryStr string) tea.Cmd { // loadSearchWithOffset executes the search query with pagination. func (m Model) loadSearchWithOffset(queryStr string, offset int, appendResults bool) tea.Cmd { requestID := m.searchRequestID + modeLabel := "fast" + if m.searchMode != searchModeFast { + modeLabel = "deep" + } + scopeLabel := m.scopeLabelForLog() return safeCmdWithPanic( func() tea.Msg { ctx := context.Background() q := search.Parse(queryStr) + start := time.Now() var results []query.MessageSummary var totalCount int64 var stats *query.TotalStats var err error + defer func() { + if err != nil { + slog.Warn("tui search failed", + "query", queryStr, + "mode", modeLabel, + "scope", scopeLabel, + "offset", offset, + "error", err.Error(), + "duration_ms", time.Since(start).Milliseconds(), + ) + return + } + slog.Info("tui search ok", + "query", queryStr, + "mode", modeLabel, + "scope", scopeLabel, + "offset", offset, + "results", len(results), + "total", totalCount, + "duration_ms", time.Since(start).Milliseconds(), + ) + }() + if m.searchMode == searchModeFast { // Fast search: single-scan with temp table materialization result, fastErr := m.engine.SearchFastWithStats(ctx, q, queryStr, m.searchFilter, m.viewType, searchPageSize, offset) @@ -614,13 +680,35 @@ func (m Model) loadMessages() tea.Cmd { // is true, the results are appended to the existing message list. func (m Model) loadMessagesWithOffset(offset int, appendMode bool) tea.Cmd { requestID := m.loadRequestID + scopeLabel := m.scopeLabelForLog() + searchTerm := m.searchQuery return safeCmdWithPanic( func() tea.Msg { filter := m.buildMessageFilter() filter.Pagination.Limit = messageListPageSize filter.Pagination.Offset = offset + start := time.Now() messages, err := m.engine.ListMessages(context.Background(), filter) + if err != nil { + slog.Warn("tui loadMessages failed", + "scope", scopeLabel, + "search", searchTerm, + "offset", offset, + "append", appendMode, + "error", err.Error(), + "duration_ms", time.Since(start).Milliseconds(), + ) + } else { + slog.Info("tui loadMessages ok", + "scope", scopeLabel, + "search", searchTerm, + "offset", offset, + "append", appendMode, + "count", len(messages), + "duration_ms", time.Since(start).Milliseconds(), + ) + } return messagesLoadedMsg{messages: messages, err: err, requestID: requestID, append: appendMode} }, func(r any) tea.Msg { From f90a59ffefd490f34f03d4f7433465ead98a83af Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 11 Apr 2026 18:37:11 +0000 Subject: [PATCH 03/10] Add database-level structured logging Wires the store's sql.DB through a thin logging adapter so every query leaves a structured trace in the daily log file. Combined with the run_id attribute, this lets you answer "what SQL did that command run?" and "which transaction took 5 seconds?" without reaching for an external profiler. internal/store/db_logger.go: - loggedDB embeds *sql.DB and overrides Query, QueryContext, QueryRow, QueryRowContext, Exec, ExecContext so every call routes through logStmt/logStmtWith. Store methods that do s.db.Query(...) compile unchanged and automatically pick up the logging. - Exec records the rows_affected count so write sizes show up in the log alongside duration and stmt text. - Statement text is normalized (whitespace collapsed) and truncated to MaxStmtChars (default 300) so log lines stay readable and disk usage stays bounded. - Severity routing: * errors -> WARN (always) * slow queries -> WARN when duration >= SlowMs (default 100) * full trace -> INFO for every query (--log-sql) * otherwise -> DEBUG (only visible with --verbose) - Known-benign migration errors ("duplicate column name", "no such module: fts5") are downgraded to DEBUG so every startup doesn't spam expected ALTER TABLE failures. - ConfigureSQLLogging(opts) publishes SlowMs and FullTrace via process-wide atomics so the CLI entry point can update them once at startup without threading options through 32 store.Open call sites. internal/store/store.go: - Store.db changed from *sql.DB to *loggedDB. DB() continues to return *sql.DB so external consumers (DuckDB sqlite_scan, for example) get the raw handle without a logging trampoline. - withTx() now logs transaction begin/commit/rollback with total duration. Transactions slower than SlowMs emit WARN; normal commits emit DEBUG. Rollbacks emit INFO with the triggering error's message in a 'reason' attribute. - queryInChunks / execInChunks generic helpers take a new chunkQuerier interface instead of *sql.DB so they accept either a raw sql.DB (tests) or the logging wrapper (production path). The interface covers exactly the two methods they call. CLI wiring: - --log-sql persistent flag: enables FullTrace (every query at INFO level). Default off. - --log-sql-slow-ms persistent flag: override the slow-query threshold. Zero keeps the 100ms default. - [log].sql_trace and [log].sql_slow_ms in config.toml mirror the flags for per-install defaults. - PersistentPreRunE calls store.ConfigureSQLLogging(...) after building the handler so the first store.Open of the run already sees the configured values. Tests cover Exec logging shape with rows_affected, slow-query promotion to WARN with a synthetic duration, error always logged, QueryRow emission, and normalizeStmt whitespace/truncation behaviour. End-to-end smoke confirmed that the default mode is quiet (no migration noise), --log-sql surfaces every query, and --log-sql-slow-ms 1 warns on everything. --- cmd/msgvault/cmd/root.go | 36 ++++- internal/config/config.go | 12 ++ internal/store/db_logger.go | 253 +++++++++++++++++++++++++++++++ internal/store/db_logger_test.go | 230 ++++++++++++++++++++++++++++ internal/store/store.go | 73 +++++++-- 5 files changed, 585 insertions(+), 19 deletions(-) create mode 100644 internal/store/db_logger.go create mode 100644 internal/store/db_logger_test.go diff --git a/cmd/msgvault/cmd/root.go b/cmd/msgvault/cmd/root.go index d185001f..9c3cd0eb 100644 --- a/cmd/msgvault/cmd/root.go +++ b/cmd/msgvault/cmd/root.go @@ -21,14 +21,16 @@ import ( ) var ( - cfgFile string - homeDir string - verbose bool - useLocal bool // Force local database even when remote is configured - logFile string - logLevel string - noLogFile bool - cfg *config.Config + cfgFile string + homeDir string + verbose bool + useLocal bool // Force local database even when remote is configured + logFile string + logLevel string + noLogFile bool + logSQL bool + logSQLSlow int64 + cfg *config.Config // logger is always non-nil so code paths outside the normal // PersistentPreRunE flow (tests, library embeds) don't have // to nil-check before calling logger.Info. PersistentPreRunE @@ -104,6 +106,19 @@ in a single binary.`, currentRun = logResult.RunID slog.SetDefault(logger) + // Configure the store's SQL logging adapter now that + // slog.Default is set. Flag overrides config; a zero + // SlowMs falls back to the built-in default (100 ms). + sqlTrace := logSQL || cfg.Log.SQLTrace + slowMs := logSQLSlow + if slowMs == 0 { + slowMs = cfg.Log.SQLSlowMs + } + store.ConfigureSQLLogging(store.SQLLogOptions{ + SlowMs: slowMs, + FullTrace: sqlTrace, + }) + // Startup header: one structured line per run that // captures everything you'd want to correlate later. // This is what makes `grep ` actually useful. @@ -431,4 +446,9 @@ func init() { "log level: debug, info, warn, error (default: info)") rootCmd.PersistentFlags().BoolVar(&noLogFile, "no-log-file", false, "disable the log file for this run (stderr output stays on)") + rootCmd.PersistentFlags().BoolVar(&logSQL, "log-sql", false, + "log every SQL query at info level (verbose; for debugging)") + rootCmd.PersistentFlags().Int64Var(&logSQLSlow, "log-sql-slow-ms", 0, + "threshold in ms above which a SQL query is logged as slow "+ + "(default 100; 0 uses the default)") } diff --git a/internal/config/config.go b/internal/config/config.go index 1f0a5047..afaef202 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -103,6 +103,18 @@ type LogConfig struct { // Disabled turns off file logging entirely. The CLI will // continue writing to stderr. Disabled bool `toml:"disabled"` + + // SQLSlowMs is the threshold above which any individual SQL + // query is logged at WARN regardless of the main level. + // Zero means "use the built-in default" (100 ms). Set to a + // very large value to effectively disable slow logging. + SQLSlowMs int64 `toml:"sql_slow_ms"` + + // SQLTrace, when true, logs every SQL query at INFO level + // with statement text, arg count, duration, and error. This + // is voluminous — leave off in normal use and flip it on + // (via config or --log-sql) only when debugging. + SQLTrace bool `toml:"sql_trace"` } // DataConfig holds data storage configuration. diff --git a/internal/store/db_logger.go b/internal/store/db_logger.go new file mode 100644 index 00000000..7d119aee --- /dev/null +++ b/internal/store/db_logger.go @@ -0,0 +1,253 @@ +package store + +import ( + "context" + "database/sql" + "log/slog" + "strings" + "sync/atomic" + "time" +) + +// SQLLogOptions controls the store-level SQL logging behaviour. +// Configured once per process via ConfigureSQLLogging(); every +// Store subsequently opened picks up the values atomically. +type SQLLogOptions struct { + // SlowMs is the threshold above which any query is logged + // at Warn regardless of the normal logging level. Zero + // means "never flag as slow". Defaults to 100 when the + // caller passes a zero-value struct to ConfigureSQLLogging. + SlowMs int64 + + // FullTrace makes every query emit an Info-level log line + // (not just Debug). Use with care — generates one line per + // query, which is enormous volume for anything non-trivial. + FullTrace bool + + // MaxStmtChars truncates logged SQL at this many characters. + // 0 disables truncation. Defaults to 300. + MaxStmtChars int +} + +// Package-level atomic config so every *loggedDB instance in the +// process reads the same settings without passing options through +// every store.Open call. Atomics avoid a mutex on the hot path — +// these values are read for every query. +var ( + sqlLogSlowMs atomic.Int64 + sqlLogFull atomic.Bool + sqlLogMaxChars atomic.Int64 +) + +func init() { + sqlLogSlowMs.Store(100) + sqlLogMaxChars.Store(300) +} + +// ConfigureSQLLogging sets the process-wide SQL logging behaviour. +// Call this after slog.SetDefault but before opening a Store. +func ConfigureSQLLogging(opts SQLLogOptions) { + slow := opts.SlowMs + if slow == 0 { + slow = 100 + } + max := opts.MaxStmtChars + if max == 0 { + max = 300 + } + sqlLogSlowMs.Store(slow) + sqlLogFull.Store(opts.FullTrace) + sqlLogMaxChars.Store(int64(max)) +} + +// loggedDB wraps *sql.DB and emits slog records for every query +// it executes. It embeds *sql.DB so store methods continue to +// compile against the sql.DB method surface — the Query/Exec +// overrides below shadow the embedded ones. +type loggedDB struct { + *sql.DB +} + +func newLoggedDB(db *sql.DB) *loggedDB { + return &loggedDB{DB: db} +} + +// Query logs the statement via logStmt and delegates to the +// embedded sql.DB. Uses a background context to match the +// sql.DB.Query semantics. +func (d *loggedDB) Query( + query string, args ...any, +) (*sql.Rows, error) { + return d.QueryContext(context.Background(), query, args...) +} + +// QueryContext logs the statement and delegates. +func (d *loggedDB) QueryContext( + ctx context.Context, query string, args ...any, +) (*sql.Rows, error) { + start := time.Now() + rows, err := d.DB.QueryContext(ctx, query, args...) + logStmt("query", query, len(args), err, time.Since(start)) + return rows, err +} + +// QueryRow logs and delegates. sql.Row does not expose its error +// until Scan, so we can only record issue time + duration here. +func (d *loggedDB) QueryRow( + query string, args ...any, +) *sql.Row { + return d.QueryRowContext(context.Background(), query, args...) +} + +// QueryRowContext logs and delegates. +func (d *loggedDB) QueryRowContext( + ctx context.Context, query string, args ...any, +) *sql.Row { + start := time.Now() + row := d.DB.QueryRowContext(ctx, query, args...) + logStmt("queryrow", query, len(args), nil, time.Since(start)) + return row +} + +// Exec logs and delegates. +func (d *loggedDB) Exec( + query string, args ...any, +) (sql.Result, error) { + return d.ExecContext(context.Background(), query, args...) +} + +// ExecContext logs and delegates. Records rows affected when +// available so write sizes show up in the log. +func (d *loggedDB) ExecContext( + ctx context.Context, query string, args ...any, +) (sql.Result, error) { + start := time.Now() + res, err := d.DB.ExecContext(ctx, query, args...) + elapsed := time.Since(start) + rowsAffected := int64(-1) + if err == nil && res != nil { + if n, rerr := res.RowsAffected(); rerr == nil { + rowsAffected = n + } + } + logStmtWith("exec", query, len(args), err, elapsed, + slog.Int64("rows_affected", rowsAffected), + ) + return res, err +} + +// Begin logs and delegates. The returned *sql.Tx is NOT wrapped — +// queries issued inside the transaction are not individually +// logged. Transaction lifecycle (begin / commit / rollback) is +// logged from Store.withTx, which is the single entry point for +// transactional work. +func (d *loggedDB) Begin() (*sql.Tx, error) { + return d.DB.Begin() +} + +// BeginTx matches the sql.DB signature. +func (d *loggedDB) BeginTx( + ctx context.Context, opts *sql.TxOptions, +) (*sql.Tx, error) { + return d.DB.BeginTx(ctx, opts) +} + +// logStmt is the common emitter used by Query / Exec / QueryRow. +func logStmt( + kind, query string, nargs int, + err error, elapsed time.Duration, +) { + logStmtWith(kind, query, nargs, err, elapsed) +} + +// logStmtWith is the explicit form that lets callers add extra +// structured attributes (used by Exec to report rows_affected). +func logStmtWith( + kind, query string, nargs int, + err error, elapsed time.Duration, extra ...slog.Attr, +) { + stmt := normalizeStmt(query, int(sqlLogMaxChars.Load())) + ms := elapsed.Milliseconds() + slowMs := sqlLogSlowMs.Load() + fullTrace := sqlLogFull.Load() + + // Base attributes that are on every line. + attrs := []any{ + "kind", kind, + "stmt", stmt, + "nargs", nargs, + "duration_ms", ms, + } + for _, a := range extra { + attrs = append(attrs, a) + } + + switch { + case err != nil: + attrs = append(attrs, "error", err.Error()) + if isBenignMigrationError(err) { + // Expected during idempotent migrations; don't + // spam WARN in the per-run log for every startup. + slog.Debug("sql benign error", attrs...) + } else { + slog.Warn("sql error", attrs...) + } + case slowMs > 0 && ms >= slowMs: + slog.Warn("sql slow", attrs...) + case fullTrace: + slog.Info("sql", attrs...) + default: + // Debug level: only visible when the handler is at + // Debug (e.g. --verbose). Produces zero allocations + // when the handler short-circuits on Enabled(). + slog.Debug("sql", attrs...) + } +} + +// isBenignMigrationError returns true for SQLite errors that the +// store layer intentionally tolerates: idempotent ALTER TABLE +// migrations that re-run on every InitSchema (duplicate column), +// and optional FTS5 module missing in builds without the fts5 +// tag. Matching on error substrings is pragmatic because those +// messages are stable across go-sqlite3 versions. +func isBenignMigrationError(err error) bool { + if err == nil { + return false + } + msg := err.Error() + return strings.Contains(msg, "duplicate column name") || + strings.Contains(msg, "no such module: fts5") +} + +// normalizeStmt collapses whitespace in a SQL statement and +// truncates it to maxChars. Truncation is marked with an +// ellipsis so the log consumer can tell. Intended for human log +// reading — not for reconstructing the exact SQL. +func normalizeStmt(q string, maxChars int) string { + // Fast path: if there's no whitespace to collapse AND the + // statement is within budget, skip the allocation. + if len(q) <= maxChars && !strings.ContainsAny(q, "\n\t") { + return strings.TrimSpace(q) + } + + var b strings.Builder + b.Grow(len(q)) + prevSpace := false + for _, r := range q { + switch r { + case ' ', '\t', '\n', '\r': + if !prevSpace { + b.WriteByte(' ') + prevSpace = true + } + default: + b.WriteRune(r) + prevSpace = false + } + } + s := strings.TrimSpace(b.String()) + if maxChars > 0 && len(s) > maxChars { + s = s[:maxChars] + "..." + } + return s +} diff --git a/internal/store/db_logger_test.go b/internal/store/db_logger_test.go new file mode 100644 index 00000000..2ac506e5 --- /dev/null +++ b/internal/store/db_logger_test.go @@ -0,0 +1,230 @@ +package store + +import ( + "bytes" + "context" + "database/sql" + "encoding/json" + "errors" + "log/slog" + "strings" + "testing" + "time" + + _ "github.com/mattn/go-sqlite3" +) + +// captureSlog installs a JSON handler over buf as the default +// slog logger for the duration of a test. Returns a cleanup +// closure that restores the previous default. +func captureSlog(t *testing.T, level slog.Level) *bytes.Buffer { + t.Helper() + var buf bytes.Buffer + prev := slog.Default() + slog.SetDefault(slog.New(slog.NewJSONHandler( + &buf, &slog.HandlerOptions{Level: level}, + ))) + t.Cleanup(func() { slog.SetDefault(prev) }) + return &buf +} + +// openLoggedMem opens an in-memory sqlite DB wrapped by loggedDB. +func openLoggedMem(t *testing.T) *loggedDB { + t.Helper() + db, err := sql.Open("sqlite3", ":memory:") + if err != nil { + t.Fatalf("open mem db: %v", err) + } + t.Cleanup(func() { _ = db.Close() }) + if _, err := db.Exec( + "CREATE TABLE t(id INTEGER PRIMARY KEY, val TEXT)", + ); err != nil { + t.Fatalf("create table: %v", err) + } + return newLoggedDB(db) +} + +func TestLoggedDB_ExecLogsStatement(t *testing.T) { + // Force full trace so every exec shows up at INFO. + ConfigureSQLLogging(SQLLogOptions{FullTrace: true}) + t.Cleanup(func() { ConfigureSQLLogging(SQLLogOptions{}) }) + + buf := captureSlog(t, slog.LevelDebug) + db := openLoggedMem(t) + + res, err := db.Exec( + "INSERT INTO t (val) VALUES (?)", "hello", + ) + if err != nil { + t.Fatalf("exec: %v", err) + } + if n, _ := res.RowsAffected(); n != 1 { + t.Errorf("rows_affected = %d, want 1", n) + } + + // Find the sql line in the captured output. + rec := findLogLine(t, buf, "sql") + if rec["kind"] != "exec" { + t.Errorf("kind = %v, want exec", rec["kind"]) + } + if !strings.Contains( + rec["stmt"].(string), "INSERT INTO t", + ) { + t.Errorf("stmt missing: %v", rec["stmt"]) + } + if rec["rows_affected"].(float64) != 1 { + t.Errorf("rows_affected = %v, want 1", rec["rows_affected"]) + } + if rec["nargs"].(float64) != 1 { + t.Errorf("nargs = %v, want 1", rec["nargs"]) + } +} + +func TestLogStmt_SlowQueryPromotedToWarn(t *testing.T) { + // Drive the emitter directly with a synthetic elapsed time + // to avoid flakiness from "actually make a query slow". + ConfigureSQLLogging(SQLLogOptions{SlowMs: 50}) + t.Cleanup(func() { ConfigureSQLLogging(SQLLogOptions{}) }) + + buf := captureSlog(t, slog.LevelDebug) + logStmtWith( + "exec", "INSERT INTO t VALUES (?)", 1, + nil, 100*time.Millisecond, + ) + + rec := findLogLineByMsg(t, buf, "sql slow") + if rec == nil { + t.Fatalf("no sql slow line found; buf=%s", + buf.String()) + } + if rec["level"] != "WARN" { + t.Errorf("level = %v, want WARN", rec["level"]) + } + if rec["duration_ms"].(float64) != 100 { + t.Errorf("duration_ms = %v, want 100", + rec["duration_ms"]) + } +} + +func TestLoggedDB_ErrorAlwaysLogged(t *testing.T) { + ConfigureSQLLogging(SQLLogOptions{}) + buf := captureSlog(t, slog.LevelDebug) + db := openLoggedMem(t) + + _, err := db.ExecContext( + context.Background(), "INSERT INTO no_such_table VALUES (1)", + ) + if err == nil { + t.Fatal("expected exec error") + } + if !errors.Is(err, err) { + t.Errorf("bad error shape") + } + + rec := findLogLineByMsg(t, buf, "sql error") + if rec == nil { + t.Fatalf("no sql error line; buf=%s", buf.String()) + } + if rec["level"] != "WARN" { + t.Errorf("level = %v, want WARN", rec["level"]) + } + if _, ok := rec["error"]; !ok { + t.Errorf("error attr missing: %v", rec) + } +} + +func TestLoggedDB_QueryRowLogsButNoError(t *testing.T) { + ConfigureSQLLogging(SQLLogOptions{FullTrace: true}) + t.Cleanup(func() { ConfigureSQLLogging(SQLLogOptions{}) }) + + buf := captureSlog(t, slog.LevelDebug) + db := openLoggedMem(t) + + if _, err := db.Exec( + "INSERT INTO t (val) VALUES ('row')", + ); err != nil { + t.Fatalf("seed: %v", err) + } + var got string + if err := db.QueryRow( + "SELECT val FROM t WHERE id = ?", 1, + ).Scan(&got); err != nil { + t.Fatalf("queryrow: %v", err) + } + if got != "row" { + t.Errorf("got = %q, want row", got) + } + + // Expect to see both an exec line and a queryrow line. + seen := map[string]bool{} + for _, rec := range decodeAll(t, buf) { + if kind, ok := rec["kind"].(string); ok { + seen[kind] = true + } + } + if !seen["exec"] || !seen["queryrow"] { + t.Errorf("missing kinds; seen=%v", seen) + } +} + +func TestNormalizeStmt_CollapsesWhitespace(t *testing.T) { + in := "SELECT\n *\nFROM\n\tt WHERE id = ?" + got := normalizeStmt(in, 0) + want := "SELECT * FROM t WHERE id = ?" + if got != want { + t.Errorf("got %q want %q", got, want) + } +} + +func TestNormalizeStmt_TruncatesLong(t *testing.T) { + in := strings.Repeat("a", 500) + got := normalizeStmt(in, 100) + if len(got) != 103 || !strings.HasSuffix(got, "...") { + t.Errorf("bad truncation: len=%d tail=%q", + len(got), got[len(got)-3:]) + } +} + +// ---- test helpers ---- + +// findLogLine returns the first record whose msg matches exactly. +func findLogLine( + t *testing.T, buf *bytes.Buffer, msg string, +) map[string]any { + t.Helper() + for _, rec := range decodeAll(t, buf) { + if rec["msg"] == msg { + return rec + } + } + t.Fatalf("no log line with msg=%q; buf=%s", msg, buf.String()) + return nil +} + +// findLogLineByMsg is like findLogLine but returns nil rather +// than failing so callers can assert absence. +func findLogLineByMsg( + t *testing.T, buf *bytes.Buffer, msg string, +) map[string]any { + t.Helper() + for _, rec := range decodeAll(t, buf) { + if rec["msg"] == msg { + return rec + } + } + return nil +} + +func decodeAll(t *testing.T, buf *bytes.Buffer) []map[string]any { + t.Helper() + var out []map[string]any + dec := json.NewDecoder(bytes.NewReader(buf.Bytes())) + for { + var rec map[string]any + if err := dec.Decode(&rec); err != nil { + break + } + out = append(out, rec) + } + return out +} diff --git a/internal/store/store.go b/internal/store/store.go index cfff52d5..99bc56b4 100644 --- a/internal/store/store.go +++ b/internal/store/store.go @@ -6,9 +6,11 @@ import ( "embed" "errors" "fmt" + "log/slog" "os" "path/filepath" "strings" + "time" "github.com/mattn/go-sqlite3" ) @@ -17,8 +19,14 @@ import ( var schemaFS embed.FS // Store provides database operations for msgvault. +// +// The db field wraps a *sql.DB with a thin logging adapter that +// emits slog records for every Query / Exec / QueryRow call. +// Because loggedDB embeds *sql.DB and overrides the instrumented +// methods, existing store code that does s.db.Query(...) compiles +// unchanged and automatically routes through the logger. type Store struct { - db *sql.DB + db *loggedDB dbPath string readOnly bool // Opened via OpenReadOnly; skips WAL checkpoint on close fts5Available bool // Whether FTS5 is available for full-text search @@ -82,7 +90,7 @@ func Open(dbPath string) (*Store, error) { } return &Store{ - db: db, + db: newLoggedDB(db), dbPath: dbPath, }, nil } @@ -117,7 +125,7 @@ func OpenReadOnly(dbPath string) (*Store, error) { db.SetMaxOpenConns(4) s := &Store{ - db: db, + db: newLoggedDB(db), dbPath: dbPath, readOnly: true, } @@ -166,30 +174,73 @@ func (s *Store) CheckpointWAL() error { return nil } -// DB returns the underlying database connection for advanced queries. +// DB returns the underlying *sql.DB for consumers that need to +// pass the raw handle elsewhere (e.g. the DuckDB engine's +// sqlite_scan wrapper). The wrapper's structured-logging +// behaviour is bypassed for those consumers — they're operating +// at a different abstraction layer. func (s *Store) DB() *sql.DB { - return s.db + return s.db.DB } -// withTx executes fn within a database transaction. If fn returns an error, -// the transaction is rolled back; otherwise it is committed. +// withTx executes fn within a database transaction. If fn returns +// an error, the transaction is rolled back; otherwise it is +// committed. This is the single entry point for transactional +// work in the store, so it is also where transaction lifecycle +// events are logged (begin / commit / rollback + total duration). +// Queries issued by fn go through *sql.Tx directly and are not +// individually logged — the transaction timing usually gives you +// enough signal, and itemizing them would require wrapping tx +// throughout the codebase. func (s *Store) withTx(fn func(tx *sql.Tx) error) error { + start := time.Now() + slog.Debug("sql tx begin") tx, err := s.db.Begin() if err != nil { + slog.Warn("sql tx begin failed", "error", err.Error()) return fmt.Errorf("begin tx: %w", err) } if err := fn(tx); err != nil { - _ = tx.Rollback() + if rbErr := tx.Rollback(); rbErr != nil { + slog.Warn("sql tx rollback failed", + "error", rbErr.Error(), + "fn_error", err.Error(), + "duration_ms", time.Since(start).Milliseconds()) + } else { + slog.Info("sql tx rollback", + "reason", err.Error(), + "duration_ms", time.Since(start).Milliseconds()) + } return err } - return tx.Commit() + if err := tx.Commit(); err != nil { + slog.Warn("sql tx commit failed", + "error", err.Error(), + "duration_ms", time.Since(start).Milliseconds()) + return err + } + ms := time.Since(start).Milliseconds() + if slowMs := sqlLogSlowMs.Load(); slowMs > 0 && ms >= slowMs { + slog.Warn("sql tx slow", "duration_ms", ms) + } else { + slog.Debug("sql tx commit", "duration_ms", ms) + } + return nil } // queryInChunks executes a parameterized IN-query in chunks to stay within // SQLite's parameter limit. queryTemplate must contain a single %s placeholder // for the comma-separated "?" list. The prefix args are prepended before each // chunk's args (e.g., a source_id filter). -func queryInChunks[T any](db *sql.DB, ids []T, prefixArgs []interface{}, queryTemplate string, fn func(*sql.Rows) error) error { +// chunkQuerier abstracts the subset of *sql.DB that queryInChunks +// and execInChunks actually use, so the helpers accept either a +// raw *sql.DB (tests) or the logging wrapper (production path). +type chunkQuerier interface { + Query(query string, args ...any) (*sql.Rows, error) + Exec(query string, args ...any) (sql.Result, error) +} + +func queryInChunks[T any](db chunkQuerier, ids []T, prefixArgs []interface{}, queryTemplate string, fn func(*sql.Rows) error) error { const chunkSize = 500 for i := 0; i < len(ids); i += chunkSize { end := i + chunkSize @@ -258,7 +309,7 @@ func insertInChunks(tx *sql.Tx, totalRows int, valuesPerRow int, queryPrefix str // to stay within SQLite's parameter limit. queryTemplate must contain a single %s // placeholder for the comma-separated "?" list. The prefix args are prepended before // each chunk's args (e.g., a message_id filter). -func execInChunks[T any](db *sql.DB, ids []T, prefixArgs []interface{}, queryTemplate string) error { +func execInChunks[T any](db chunkQuerier, ids []T, prefixArgs []interface{}, queryTemplate string) error { const chunkSize = 500 for i := 0; i < len(ids); i += chunkSize { end := i + chunkSize From 0f5822270a3a42e690202fa1a156300f9e5c9f41 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 11 Apr 2026 18:42:33 +0000 Subject: [PATCH 04/10] tui: suppress stderr log output while in alt-screen Bubble Tea takes over the terminal in alternate-screen mode. Any slog write to stderr (e.g. the tui loadAccounts / loadData / loadMessages diagnostic lines from the previous commits) corrupts the render because Bubble Tea and slog end up racing for the same file descriptor. Fix: swap slog.Default() to a file-only logger for the duration of the TUI run, restore it on return. The daily log file keeps receiving every tui log line so 'msgvault logs -f' in another pane still works exactly as before. internal/logging/logging.go: - Expose the JSON file handler as Result.FileHandler alongside the existing multi-handler. - Add Result.FileOnlyLogger() which returns a logger bound to just the file sink, pre-attributed with the run_id so the file entries correlate with the rest of the run. Returns a discardHandler-backed logger when file logging is disabled so the caller's swap still suppresses stderr. - Add a minimal discardHandler type so FileOnlyLogger never hands back nil. cmd/msgvault/cmd/tui.go: - Before p.Run() save slog.Default, swap to the file-only logger, defer the restore. Only reads logResult if it's non-nil so tests that bypass PersistentPreRunE still work. --- cmd/msgvault/cmd/tui.go | 13 +++++++++++ internal/logging/logging.go | 45 ++++++++++++++++++++++++++++++++----- 2 files changed, 53 insertions(+), 5 deletions(-) diff --git a/cmd/msgvault/cmd/tui.go b/cmd/msgvault/cmd/tui.go index fb98fa74..fb716d44 100644 --- a/cmd/msgvault/cmd/tui.go +++ b/cmd/msgvault/cmd/tui.go @@ -3,6 +3,7 @@ package cmd import ( "encoding/json" "fmt" + "log/slog" "os" "path/filepath" "strings" @@ -157,6 +158,18 @@ Remote Mode: }) p := tea.NewProgram(model, tea.WithAltScreen()) + // Swap the slog default to a file-only logger for the + // duration of the TUI. Bubble Tea owns the terminal in + // alt-screen mode; any stderr write from slog corrupts + // the render. The daily log file still receives + // everything, so 'msgvault logs -f' in another pane + // continues to work for diagnostics. + prevLogger := slog.Default() + if logResult != nil { + slog.SetDefault(logResult.FileOnlyLogger()) + } + defer slog.SetDefault(prevLogger) + if _, err := p.Run(); err != nil { return fmt.Errorf("run tui: %w", err) } diff --git a/internal/logging/logging.go b/internal/logging/logging.go index c68d8427..9e33ac30 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -83,14 +83,48 @@ type Options struct { // Result holds the constructed handler plus the resolved log file // path (empty when file logging is disabled) and any teardown // closures the caller should run at shutdown. +// +// FileHandler is the JSON-to-disk handler in isolation (nil when +// file logging is disabled). TUI-style commands that take over the +// terminal swap their slog.Default() to this handler so slog writes +// don't corrupt the alternate-screen rendering. type Result struct { - Handler slog.Handler - Level slog.Level - RunID string - FilePath string - closers []func() + Handler slog.Handler + FileHandler slog.Handler + Level slog.Level + RunID string + FilePath string + closers []func() } +// FileOnlyLogger returns a logger that only writes to the daily +// log file and skips stderr entirely. Returns a discard logger +// when file logging is disabled. The returned logger already +// carries the process-wide run_id attribute so TUI-emitted +// records correlate with the rest of the run in the log file. +func (r *Result) FileOnlyLogger() *slog.Logger { + if r.FileHandler == nil { + // No file handler; give the caller a discard logger so + // their slog.Default() swap keeps the TUI quiet. + return slog.New(discardHandler{}) + } + return slog.New( + r.FileHandler.WithAttrs( + []slog.Attr{slog.String("run_id", r.RunID)}, + ), + ) +} + +// discardHandler silently drops every record. Used as the +// fall-through default when file logging is disabled AND the +// caller wants to suppress stderr too. +type discardHandler struct{} + +func (discardHandler) Enabled(context.Context, slog.Level) bool { return false } +func (discardHandler) Handle(context.Context, slog.Record) error { return nil } +func (d discardHandler) WithAttrs([]slog.Attr) slog.Handler { return d } +func (d discardHandler) WithGroup(string) slog.Handler { return d } + // Close releases file handles held by the handler. Safe to call // multiple times. func (r *Result) Close() { @@ -154,6 +188,7 @@ func BuildHandler(opts Options) (*Result, error) { Level: level, }) handlers = append(handlers, fileH) + res.FileHandler = fileH res.FilePath = path res.closers = append(res.closers, func() { _ = f.Close() From dcd19fd4eda229b1835abddeff815231be0c0db9 Mon Sep 17 00:00:00 2001 From: Jesse Robbins Date: Mon, 13 Apr 2026 10:17:43 -0700 Subject: [PATCH 05/10] fix: address review feedback on structured logging - findLogFiles: sort log files chronologically instead of lexicographically so rotated files (.log.1, .log.2) appear before the active .log for the same date, fixing --all ordering and ring-buffer tail correctness. - --log-file: thread the full path through logging.Options.FilePath so the flag actually overrides the log file path as documented, not just the directory. - followLogFile: buffer partial lines when ReadBytes returns a fragment at EOF mid-write, preventing silent loss of live log lines that span two reads. Co-Authored-By: Claude Sonnet 4.6 --- cmd/msgvault/cmd/logs.go | 44 ++++++++++++++++++++++++++++++++----- cmd/msgvault/cmd/root.go | 7 +----- internal/logging/logging.go | 27 ++++++++++++++++++----- 3 files changed, 61 insertions(+), 17 deletions(-) diff --git a/cmd/msgvault/cmd/logs.go b/cmd/msgvault/cmd/logs.go index 4ae7a72e..183a9650 100644 --- a/cmd/msgvault/cmd/logs.go +++ b/cmd/msgvault/cmd/logs.go @@ -131,10 +131,30 @@ func findLogFiles(dir string, all bool) ([]string, error) { } files = append(files, filepath.Join(dir, n)) } - sort.Strings(files) + sort.Slice(files, func(i, j int) bool { + return logFileSortKey(files[i]) < logFileSortKey(files[j]) + }) return files, nil } +// logFileSortKey returns a string that sorts log files chronologically: +// rotated files (.log.1, .log.2) come before the active .log for the +// same date, and higher rotation indices (older) sort earlier. +func logFileSortKey(path string) string { + name := filepath.Base(path) + // msgvault-2026-04-11.log -> date=2026-04-11 suffix=999 (active, last) + // msgvault-2026-04-11.log.1 -> date=2026-04-11 suffix=001 + // msgvault-2026-04-11.log.2 -> date=2026-04-11 suffix=002 + if idx := strings.LastIndex(name, ".log."); idx >= 0 { + date := name[:idx+4] // through ".log" + num := name[idx+5:] + return date + fmt.Sprintf(".%03s", num) + } + // Active file (no rotation suffix) sorts after all rotations + // for the same date. + return name + ".999" +} + // logFilter represents the user's --run-id / --level / --grep // filters. An empty field means "no filter on that axis". type logFilter struct { @@ -228,6 +248,7 @@ func followLogFile( } reader := bufio.NewReader(f) + var partial []byte for { select { case <-ctx.Done(): @@ -236,12 +257,23 @@ func followLogFile( } line, err := reader.ReadBytes('\n') if len(line) > 0 { - var rec map[string]any - if json.Unmarshal(line, &rec) == nil && - filter.matches(line, rec) { - fmt.Fprintln(out, formatLogRecord(rec)) + if len(partial) > 0 { + line = append(partial, line...) + partial = nil + } + // If the line doesn't end with a newline, it's a + // partial read — buffer it until more data arrives. + if line[len(line)-1] != '\n' { + partial = append(partial[:0], line...) + // fall through to the sleep + } else { + var rec map[string]any + if json.Unmarshal(line, &rec) == nil && + filter.matches(line, rec) { + fmt.Fprintln(out, formatLogRecord(rec)) + } + continue } - continue } if err != nil && err != io.EOF { return err diff --git a/cmd/msgvault/cmd/root.go b/cmd/msgvault/cmd/root.go index 9c3cd0eb..ff754ce1 100644 --- a/cmd/msgvault/cmd/root.go +++ b/cmd/msgvault/cmd/root.go @@ -85,16 +85,11 @@ in a single binary.`, levelString = cfg.Log.Level } logsDir := cfg.LogsDir() - if logFile != "" { - // Treat --log-file as an override for the whole - // path, not just the directory, so power users - // can pipe today's run anywhere. - logsDir = filepath.Dir(logFile) - } fileDisabled := noLogFile || cfg.Log.Disabled logResult, err = logging.BuildHandler(logging.Options{ LogsDir: logsDir, + FilePath: logFile, FileDisabled: fileDisabled, LevelOverride: levelOverride, LevelString: levelString, diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 9e33ac30..dc67345b 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -46,6 +46,10 @@ type Options struct { // written. Required unless FileDisabled is true. LogsDir string + // FilePath, when non-empty, overrides the log file path + // entirely (bypassing the daily-name convention and LogsDir). + FilePath string + // FileDisabled turns off file logging entirely. Stderr // output still happens. Use this for one-shot runs or for // tests that want to avoid writing to disk. @@ -177,11 +181,24 @@ func BuildHandler(opts Options) (*Result, error) { handlers := []slog.Handler{stderrH} // Best-effort file handler. - if !opts.FileDisabled && opts.LogsDir != "" { - path, f, err := openDailyLogFile( - opts.LogsDir, now(), - opts.MaxFileBytes, opts.KeepRotated, - ) + if !opts.FileDisabled && (opts.LogsDir != "" || opts.FilePath != "") { + var path string + var f *os.File + var err error + if opts.FilePath != "" { + // Explicit path: use it directly, no rotation. + if mkErr := os.MkdirAll(filepath.Dir(opts.FilePath), 0o700); mkErr != nil { + err = fmt.Errorf("mkdir for log file: %w", mkErr) + } else { + path = opts.FilePath + f, err = os.OpenFile(path, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o600) + } + } else { + path, f, err = openDailyLogFile( + opts.LogsDir, now(), + opts.MaxFileBytes, opts.KeepRotated, + ) + } switch { case err == nil: fileH := slog.NewJSONHandler(f, &slog.HandlerOptions{ From 6de9fc227078bd6c01f122694072fa9f57af3cbf Mon Sep 17 00:00:00 2001 From: Jesse Robbins Date: Mon, 13 Apr 2026 10:53:24 -0700 Subject: [PATCH 06/10] =?UTF-8?q?fix:=20lint=20=E2=80=94=20remove=20unused?= =?UTF-8?q?=20var,=20suppress=20errcheck,=20apply=20staticcheck?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Remove unused currentRun variable, add explicit _ discards for fmt.Fprint* return values, and apply linter auto-fixes for De Morgan's law and Sprintf-in-WriteString patterns. Co-Authored-By: Claude Opus 4.6 (1M context) --- cmd/msgvault/cmd/logs.go | 11 +++++------ cmd/msgvault/cmd/root.go | 5 ++--- internal/logging/logging.go | 6 +++--- 3 files changed, 10 insertions(+), 12 deletions(-) diff --git a/cmd/msgvault/cmd/logs.go b/cmd/msgvault/cmd/logs.go index 183a9650..e21c033e 100644 --- a/cmd/msgvault/cmd/logs.go +++ b/cmd/msgvault/cmd/logs.go @@ -125,8 +125,7 @@ func findLogFiles(dir string, all bool) ([]string, error) { } n := e.Name() if !strings.HasPrefix(n, "msgvault-") || - !(strings.HasSuffix(n, ".log") || - strings.Contains(n, ".log.")) { + (!strings.HasSuffix(n, ".log") && !strings.Contains(n, ".log.")) { continue } files = append(files, filepath.Join(dir, n)) @@ -226,7 +225,7 @@ func printLogFiles( } } for _, line := range ring { - fmt.Fprintln(out, line) + _, _ = fmt.Fprintln(out, line) } return nil } @@ -270,7 +269,7 @@ func followLogFile( var rec map[string]any if json.Unmarshal(line, &rec) == nil && filter.matches(line, rec) { - fmt.Fprintln(out, formatLogRecord(rec)) + _, _ = fmt.Fprintln(out, formatLogRecord(rec)) } continue } @@ -319,7 +318,7 @@ func formatLogRecord(rec map[string]any) string { } } if level != "" { - b.WriteString(fmt.Sprintf("%-5s", level)) + fmt.Fprintf(&b, "%-5s", level) b.WriteByte(' ') } if runID != "" { @@ -336,7 +335,7 @@ func formatLogRecord(rec map[string]any) string { b.WriteString(" ") b.WriteString(k) b.WriteString("=") - b.WriteString(fmt.Sprint(rec[k])) + fmt.Fprint(&b, rec[k]) } return b.String() } diff --git a/cmd/msgvault/cmd/root.go b/cmd/msgvault/cmd/root.go index ff754ce1..8884f98a 100644 --- a/cmd/msgvault/cmd/root.go +++ b/cmd/msgvault/cmd/root.go @@ -37,8 +37,7 @@ var ( // replaces this with a properly configured multi-handler at // CLI startup. logger = slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: slog.LevelInfo})) - logResult *logging.Result // non-nil after PersistentPreRunE runs - currentRun string // short ID attached to every log record + logResult *logging.Result // non-nil after PersistentPreRunE runs ) var rootCmd = &cobra.Command{ @@ -98,7 +97,7 @@ in a single binary.`, return fmt.Errorf("build logger: %w", err) } logger = slog.New(logResult.Handler) - currentRun = logResult.RunID + // logResult.RunID is available for any command that needs it. slog.SetDefault(logger) // Configure the store's SQL logging adapter now that diff --git a/internal/logging/logging.go b/internal/logging/logging.go index dc67345b..7424da58 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -199,8 +199,8 @@ func BuildHandler(opts Options) (*Result, error) { opts.MaxFileBytes, opts.KeepRotated, ) } - switch { - case err == nil: + switch err { + case nil: fileH := slog.NewJSONHandler(f, &slog.HandlerOptions{ Level: level, }) @@ -211,7 +211,7 @@ func BuildHandler(opts Options) (*Result, error) { _ = f.Close() }) default: - fmt.Fprintf(stderr, + _, _ = fmt.Fprintf(stderr, "warning: could not open msgvault log file in %s: %v "+ "(continuing with stderr-only logging)\n", opts.LogsDir, err, From cf80b82425c6209beddef68ce8e5efaba4b25742 Mon Sep 17 00:00:00 2001 From: Jesse Robbins Date: Mon, 13 Apr 2026 11:24:12 -0700 Subject: [PATCH 07/10] fix: close log file handles so tests and Docker cleanup can remove temp dirs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The log file handle was only closed in ExecuteContext's defer, but tests invoke commands directly via rootCmd.Execute() — leaving the file open. On Windows this blocks TempDir cleanup ("file is being used by another process"); in Docker the root-owned logs dir can't be removed by the host runner. - Add PersistentPostRunE that closes logResult after every command. - Close any previous logResult at the top of PersistentPreRunE so repeated test invocations don't leak handles. - Change log directory permissions from 0700 to 0755 so Docker host cleanup can traverse directories created by the container. Co-Authored-By: Claude Opus 4.6 (1M context) --- cmd/msgvault/cmd/root.go | 16 ++++++++++++++++ internal/logging/logging.go | 4 ++-- 2 files changed, 18 insertions(+), 2 deletions(-) diff --git a/cmd/msgvault/cmd/root.go b/cmd/msgvault/cmd/root.go index 8884f98a..00b33b99 100644 --- a/cmd/msgvault/cmd/root.go +++ b/cmd/msgvault/cmd/root.go @@ -86,6 +86,13 @@ in a single binary.`, logsDir := cfg.LogsDir() fileDisabled := noLogFile || cfg.Log.Disabled + // Close a previous log handler if tests re-enter + // PersistentPreRunE without going through ExecuteContext. + if logResult != nil { + logResult.Close() + logResult = nil + } + logResult, err = logging.BuildHandler(logging.Options{ LogsDir: logsDir, FilePath: logFile, @@ -130,6 +137,15 @@ in a single binary.`, ) return nil }, + PersistentPostRunE: func(cmd *cobra.Command, args []string) error { + // Close the log file so Windows tests (and Docker + // containers) can clean up temp directories immediately. + if logResult != nil { + logResult.Close() + logResult = nil + } + return nil + }, } // sanitizeArgs removes anything that might carry a secret before diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 7424da58..3a19dcdc 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -187,7 +187,7 @@ func BuildHandler(opts Options) (*Result, error) { var err error if opts.FilePath != "" { // Explicit path: use it directly, no rotation. - if mkErr := os.MkdirAll(filepath.Dir(opts.FilePath), 0o700); mkErr != nil { + if mkErr := os.MkdirAll(filepath.Dir(opts.FilePath), 0o755); mkErr != nil { err = fmt.Errorf("mkdir for log file: %w", mkErr) } else { path = opts.FilePath @@ -257,7 +257,7 @@ func newRunID() string { func openDailyLogFile( dir string, now time.Time, maxBytes int64, keepRotated int, ) (string, *os.File, error) { - if err := os.MkdirAll(dir, 0o700); err != nil { + if err := os.MkdirAll(dir, 0o755); err != nil { return "", nil, fmt.Errorf("mkdir logs dir: %w", err) } name := fmt.Sprintf( From fb87bef99b73771f0b2c0106b71ec75ccf241ee3 Mon Sep 17 00:00:00 2001 From: Jesse Robbins Date: Mon, 13 Apr 2026 15:49:47 -0700 Subject: [PATCH 08/10] fix: address structured logging review feedback - Fix exit log dropped on success: remove PersistentPostRunE close that ran before ExecuteContext could emit the exit record; the deferred close in ExecuteContext already handles shutdown. - Redact sensitive input from logs: positional args (emails, queries) logged as argc at info, full values at debug only. Search and TUI log query_len/has_search/has_account instead of raw text. Account scope uses "filtered" instead of the email address. - Fix log.dir path handling: expand ~ and resolve relative paths for cfg.Log.Dir in config.Load(), consistent with data_dir and oauth paths. Addresses: wesm/msgvault#263 (comment) Co-Authored-By: Claude Opus 4.6 (1M context) --- cmd/msgvault/cmd/root.go | 24 ++++++++++++------------ cmd/msgvault/cmd/search.go | 28 +++++++++++++--------------- internal/config/config.go | 2 ++ internal/tui/model.go | 27 +++++++++++---------------- 4 files changed, 38 insertions(+), 43 deletions(-) diff --git a/cmd/msgvault/cmd/root.go b/cmd/msgvault/cmd/root.go index 00b33b99..db337314 100644 --- a/cmd/msgvault/cmd/root.go +++ b/cmd/msgvault/cmd/root.go @@ -36,7 +36,7 @@ var ( // to nil-check before calling logger.Info. PersistentPreRunE // replaces this with a properly configured multi-handler at // CLI startup. - logger = slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: slog.LevelInfo})) + logger = slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: slog.LevelInfo})) logResult *logging.Result // non-nil after PersistentPreRunE runs ) @@ -122,10 +122,12 @@ in a single binary.`, // Startup header: one structured line per run that // captures everything you'd want to correlate later. - // This is what makes `grep ` actually useful. + // Positional args may contain email addresses, search + // queries, or other PII — log only the count at info + // level and the full (sanitized) values at debug. logger.Info("msgvault startup", "command", cmd.CommandPath(), - "args", sanitizeArgs(args), + "argc", len(args), "version", Version, "go_version", runtime.Version(), "os", runtime.GOOS, @@ -135,17 +137,15 @@ in a single binary.`, "log_file", logResult.FilePath, "level", logResult.Level.String(), ) + logger.Debug("msgvault startup args", + "args", sanitizeArgs(args), + ) return nil }, - PersistentPostRunE: func(cmd *cobra.Command, args []string) error { - // Close the log file so Windows tests (and Docker - // containers) can clean up temp directories immediately. - if logResult != nil { - logResult.Close() - logResult = nil - } - return nil - }, + // Note: log file closing is handled by ExecuteContext's deferred + // shutdown, which runs after the exit record is written. Do not + // close logResult in PersistentPostRunE — doing so drops the + // "msgvault exit" log line on successful runs. } // sanitizeArgs removes anything that might carry a secret before diff --git a/cmd/msgvault/cmd/search.go b/cmd/msgvault/cmd/search.go index 0b6d74ad..23318452 100644 --- a/cmd/msgvault/cmd/search.go +++ b/cmd/msgvault/cmd/search.go @@ -146,21 +146,20 @@ func runLocalSearch(cmd *cobra.Command, queryStr string) error { return err } - // Log the search operation so it's auditable in the daily - // log file alongside every other command. - scopeKind := "all" - scopeValue := "" - if q.AccountID != nil { - scopeKind = "source" - scopeValue = searchAccount - } + // Log the search operation. Raw query text and account + // identifiers may contain PII — log coarse metadata at + // info and full values only at debug. + hasAccount := q.AccountID != nil logger.Info("search start", - "query", queryStr, - "scope", scopeKind, - "account", scopeValue, + "query_len", len(queryStr), + "has_account", hasAccount, "limit", searchLimit, "offset", searchOffset, ) + logger.Debug("search start detail", + "query", queryStr, + "account", searchAccount, + ) started := time.Now() // Create query engine and execute search @@ -169,16 +168,15 @@ func runLocalSearch(cmd *cobra.Command, queryStr string) error { fmt.Fprintf(os.Stderr, "\r \r") if err != nil { logger.Warn("search failed", - "query", queryStr, + "query_len", len(queryStr), "duration_ms", time.Since(started).Milliseconds(), "error", err.Error(), ) return query.HintRepairEncoding(fmt.Errorf("search: %w", err)) } logger.Info("search done", - "query", queryStr, - "scope", scopeKind, - "account", scopeValue, + "query_len", len(queryStr), + "has_account", hasAccount, "results", len(results), "duration_ms", time.Since(started).Milliseconds(), ) diff --git a/internal/config/config.go b/internal/config/config.go index afaef202..415cbced 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -284,6 +284,7 @@ func Load(path, homeDir string) (*Config, error) { // Expand ~ in paths cfg.Data.DataDir = expandPath(cfg.Data.DataDir) + cfg.Log.Dir = expandPath(cfg.Log.Dir) cfg.OAuth.ClientSecrets = expandPath(cfg.OAuth.ClientSecrets) for name, app := range cfg.OAuth.Apps { app.ClientSecrets = expandPath(app.ClientSecrets) @@ -294,6 +295,7 @@ func Load(path, homeDir string) (*Config, error) { // directory so behavior doesn't depend on the working directory. if explicit { cfg.Data.DataDir = resolveRelative(cfg.Data.DataDir, cfg.HomeDir) + cfg.Log.Dir = resolveRelative(cfg.Log.Dir, cfg.HomeDir) cfg.OAuth.ClientSecrets = resolveRelative(cfg.OAuth.ClientSecrets, cfg.HomeDir) for name, app := range cfg.OAuth.Apps { app.ClientSecrets = resolveRelative(app.ClientSecrets, cfg.HomeDir) diff --git a/internal/tui/model.go b/internal/tui/model.go index 53151932..87b480e6 100644 --- a/internal/tui/model.go +++ b/internal/tui/model.go @@ -313,17 +313,12 @@ type accountsLoadedMsg struct { } // scopeLabelForLog returns a short, stable string describing the -// current account scope so it can be attached to log records -// without exposing internal ID values. +// current account scope so it can be attached to log records. +// Uses "filtered" rather than the account identifier to avoid +// persisting email addresses in the log file. func (m Model) scopeLabelForLog() string { - switch { - case m.accountFilter != nil: - for _, acc := range m.accounts { - if acc.ID == *m.accountFilter { - return "source:" + acc.Identifier - } - } - return "source:unknown" + if m.accountFilter != nil { + return "filtered" } return "all" } @@ -368,7 +363,7 @@ func (m Model) loadData() tea.Cmd { slog.Warn("tui loadData failed", "view", viewLabel, "scope", scopeLabel, - "search", searchTerm, + "has_search", searchTerm != "", "error", err.Error(), "duration_ms", time.Since(start).Milliseconds(), ) @@ -376,7 +371,7 @@ func (m Model) loadData() tea.Cmd { slog.Info("tui loadData ok", "view", viewLabel, "scope", scopeLabel, - "search", searchTerm, + "has_search", searchTerm != "", "rows", len(rows), "duration_ms", time.Since(start).Milliseconds(), ) @@ -548,7 +543,7 @@ func (m Model) loadSearchWithOffset(queryStr string, offset int, appendResults b defer func() { if err != nil { slog.Warn("tui search failed", - "query", queryStr, + "query_len", len(queryStr), "mode", modeLabel, "scope", scopeLabel, "offset", offset, @@ -558,7 +553,7 @@ func (m Model) loadSearchWithOffset(queryStr string, offset int, appendResults b return } slog.Info("tui search ok", - "query", queryStr, + "query_len", len(queryStr), "mode", modeLabel, "scope", scopeLabel, "offset", offset, @@ -693,7 +688,7 @@ func (m Model) loadMessagesWithOffset(offset int, appendMode bool) tea.Cmd { if err != nil { slog.Warn("tui loadMessages failed", "scope", scopeLabel, - "search", searchTerm, + "has_search", searchTerm != "", "offset", offset, "append", appendMode, "error", err.Error(), @@ -702,7 +697,7 @@ func (m Model) loadMessagesWithOffset(offset int, appendMode bool) tea.Cmd { } else { slog.Info("tui loadMessages ok", "scope", scopeLabel, - "search", searchTerm, + "has_search", searchTerm != "", "offset", offset, "append", appendMode, "count", len(messages), From 33c3d6a3086f8fee572e83dd819f4b3f59706700 Mon Sep 17 00:00:00 2001 From: Jesse Robbins Date: Mon, 13 Apr 2026 16:09:01 -0700 Subject: [PATCH 09/10] fix: make file logging opt-in, fix panic defer order and log rotation sort - File logging is now opt-in by default. Enable via [log] enabled=true, [log] dir="...", or --log-file. Without any of these, msgvault only writes to stderr (the pre-existing behavior users expect). This eliminates the surprise disk-persistence surface for sensitive data. - Fix panic logging loss: swap defer order in ExecuteContext so recoverAndLogPanic runs while the file handle is still open. Previously logResult.Close() ran first (LIFO), silently dropping the panic record. - Fix rotated log chronological order: .log.5 (oldest) now sorts before .log.1 (newest), with the active .log file last. Previously the suffix sort was ascending, putting newer rotations before older. Co-Authored-By: Claude Opus 4.6 (1M context) --- cmd/msgvault/cmd/logs.go | 18 +++++++++++++----- cmd/msgvault/cmd/root.go | 9 +++++++-- internal/config/config.go | 20 +++++++++++--------- internal/logging/logging.go | 6 +++--- 4 files changed, 34 insertions(+), 19 deletions(-) diff --git a/cmd/msgvault/cmd/logs.go b/cmd/msgvault/cmd/logs.go index e21c033e..3856172e 100644 --- a/cmd/msgvault/cmd/logs.go +++ b/cmd/msgvault/cmd/logs.go @@ -138,16 +138,24 @@ func findLogFiles(dir string, all bool) ([]string, error) { // logFileSortKey returns a string that sorts log files chronologically: // rotated files (.log.1, .log.2) come before the active .log for the -// same date, and higher rotation indices (older) sort earlier. +// same date. Higher rotation indices are older (.log.5 predates .log.1), +// so they sort first by inverting the suffix. func logFileSortKey(path string) string { name := filepath.Base(path) // msgvault-2026-04-11.log -> date=2026-04-11 suffix=999 (active, last) - // msgvault-2026-04-11.log.1 -> date=2026-04-11 suffix=001 - // msgvault-2026-04-11.log.2 -> date=2026-04-11 suffix=002 + // msgvault-2026-04-11.log.5 -> date=2026-04-11 suffix=000 (oldest rotation) + // msgvault-2026-04-11.log.1 -> date=2026-04-11 suffix=004 (newest rotation) if idx := strings.LastIndex(name, ".log."); idx >= 0 { date := name[:idx+4] // through ".log" - num := name[idx+5:] - return date + fmt.Sprintf(".%03s", num) + num := 0 + fmt.Sscanf(name[idx+5:], "%d", &num) + // Invert: higher rotation number = older = should sort first. + // 999 is reserved for the active file, so cap at 998. + inverted := 998 - num + if inverted < 0 { + inverted = 0 + } + return fmt.Sprintf("%s.%03d", date, inverted) } // Active file (no rotation suffix) sorts after all rotations // for the same date. diff --git a/cmd/msgvault/cmd/root.go b/cmd/msgvault/cmd/root.go index db337314..f2c8d008 100644 --- a/cmd/msgvault/cmd/root.go +++ b/cmd/msgvault/cmd/root.go @@ -84,7 +84,9 @@ in a single binary.`, levelString = cfg.Log.Level } logsDir := cfg.LogsDir() - fileDisabled := noLogFile || cfg.Log.Disabled + // File logging is opt-in: requires [log].enabled, + // [log].dir, or --log-file. --no-log-file overrides. + fileDisabled := noLogFile || (logFile == "" && !cfg.Log.Enabled && cfg.Log.Dir == "") // Close a previous log handler if tests re-enter // PersistentPreRunE without going through ExecuteContext. @@ -223,12 +225,15 @@ func Execute() error { // Installs a panic recovery and closes the log file handler on // return so every run ends cleanly in the log. func ExecuteContext(ctx context.Context) error { - defer recoverAndLogPanic() + // Defers run LIFO: close the log file first, then recover + // panics. This ensures the panic record is written while the + // file handle is still open. defer func() { if logResult != nil { logResult.Close() } }() + defer recoverAndLogPanic() err := rootCmd.ExecuteContext(ctx) diff --git a/internal/config/config.go b/internal/config/config.go index 415cbced..49a3cf90 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -85,14 +85,15 @@ type Config struct { configPath string // resolved path to the loaded config file } -// LogConfig holds logging configuration. Defaults to writing one -// file per day under ~/.msgvault/logs/ alongside the stderr output -// that every command has always produced. Callers that want to -// suppress file logging entirely can set Disabled or pass the -// --no-log-file flag. +// LogConfig holds logging configuration. File logging is opt-in: +// set enabled = true or dir = "..." to write structured JSON logs +// to disk. Without either, msgvault only writes to stderr (which +// is the default behavior users already expect). The --log-file +// CLI flag also enables file logging for a single run. type LogConfig struct { // Dir is the directory where log files live. Empty means - // "/logs", which is the recommended default. + // "/logs". Setting this implicitly enables file + // logging. Dir string `toml:"dir"` // Level overrides the default logging level. Accepted values @@ -100,9 +101,10 @@ type LogConfig struct { // (or "debug" when --verbose is passed). Level string `toml:"level"` - // Disabled turns off file logging entirely. The CLI will - // continue writing to stderr. - Disabled bool `toml:"disabled"` + // Enabled turns on persistent file logging. When false (the + // default), the CLI only writes to stderr. Set to true, or + // set dir, to opt in to durable on-disk logs. + Enabled bool `toml:"enabled"` // SQLSlowMs is the threshold above which any individual SQL // query is logged at WARN regardless of the main level. diff --git a/internal/logging/logging.go b/internal/logging/logging.go index 3a19dcdc..623abc47 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -4,9 +4,9 @@ // Design goals (CLAUDE.md's "Safety ergonomics" principle, applied // to observability): // -// 1. Every CLI run leaves a durable, structured trail on disk -// without the user having to redirect stderr themselves. The -// default log directory is /logs and files are named +// 1. When enabled (opt-in via config or CLI flag), every CLI run +// leaves a durable, structured trail on disk. The default log +// directory is /logs and files are named // msgvault-YYYY-MM-DD.log (UTC). // 2. On-disk logs are structured JSON so they're greppable with // jq and mechanically parseable. Interactive stderr output From 21c9a2266fb19a89da96aef3a5198d98b22943ee Mon Sep 17 00:00:00 2001 From: Jesse Robbins Date: Mon, 13 Apr 2026 16:27:49 -0700 Subject: [PATCH 10/10] fix: check fmt.Sscanf return value in log sort key Co-Authored-By: Claude Opus 4.6 (1M context) --- cmd/msgvault/cmd/logs.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cmd/msgvault/cmd/logs.go b/cmd/msgvault/cmd/logs.go index 3856172e..91a3dcf8 100644 --- a/cmd/msgvault/cmd/logs.go +++ b/cmd/msgvault/cmd/logs.go @@ -148,7 +148,7 @@ func logFileSortKey(path string) string { if idx := strings.LastIndex(name, ".log."); idx >= 0 { date := name[:idx+4] // through ".log" num := 0 - fmt.Sscanf(name[idx+5:], "%d", &num) + _, _ = fmt.Sscanf(name[idx+5:], "%d", &num) // Invert: higher rotation number = older = should sort first. // 999 is reserved for the active file, so cap at 998. inverted := 998 - num