|
| 1 | +# Logging Overhaul Plan |
| 2 | + |
| 3 | +## Context |
| 4 | +MSSQLHound currently uses raw `fmt.Printf`/`fmt.Println` for all logging (~149 calls across 10 files). Messages have no timestamps, no log levels, and inconsistent formatting. The goal is to add UTC timestamps and log levels to every message using Go's stdlib `log/slog` (available since Go 1.21, project uses Go 1.24). |
| 5 | + |
| 6 | +## Approach: Use `log/slog` from stdlib |
| 7 | + |
| 8 | +No new packages or dependencies. Create a `*slog.Logger` in `main()`, propagate via struct fields. |
| 9 | + |
| 10 | +### Output format |
| 11 | +``` |
| 12 | +INFO 2026-03-30T14:22:01Z Processing 5 SQL Server(s)... |
| 13 | +INFO 2026-03-30T14:22:01Z [corp.local] Enumerating MSSQL SPNs from Active Directory... |
| 14 | +VERBOSE 2026-03-30T14:22:01Z [corp.local] Found SPNs count=12 host=sql01.corp.local |
| 15 | +WARNING 2026-03-30T14:22:02Z [sql01.corp.local] SPN enumeration failed error="connection refused" |
| 16 | +DEBUG 2026-03-30T14:22:02Z [sql01.corp.local] EPA TLS handshake complete cipher=0x1301 |
| 17 | +``` |
| 18 | + |
| 19 | +- Custom `slog.Handler` implementation in a new file `internal/logging/handler.go` |
| 20 | +- Format: `LEVEL TIMESTAMP [target] message attrs...` |
| 21 | +- Level name is left-aligned, right-padded to 7 chars (longest: `WARNING` and `VERBOSE`) |
| 22 | +- Output goes to **stderr** (standard for logs; keeps stdout clean for data output like tables) |
| 23 | +- Timestamps in UTC RFC3339 format |
| 24 | +- **Target context**: when processing a specific server or domain, a `[target]` tag appears after the timestamp. Implemented via `logger.With("target", serverName)` to create sub-loggers. The custom handler renders the `target` attr specially in brackets, separate from other attrs. |
| 25 | +- Messages without a target (startup, global config) omit the bracket section |
| 26 | + |
| 27 | +### Colors (ANSI escape codes) |
| 28 | +- Auto-detect TTY on stderr (`os.Stderr.Fd()` + `isatty` check or `golang.org/x/term.IsTerminal`). Disable colors when piped. |
| 29 | +- **Level colors**: |
| 30 | + - `ERROR` — red (ANSI 31) |
| 31 | + - `WARNING` — yellow (ANSI 33) |
| 32 | + - `INFO` — white/default (no color) |
| 33 | + - `VERBOSE` — dim/gray (ANSI 90) |
| 34 | + - `DEBUG` — magenta (ANSI 35) |
| 35 | +- **Timestamp** — light blue (ANSI 94) |
| 36 | +- **Target** `[brackets]` — deterministic color per unique target string. Hash the target name to pick from a palette of primary/secondary ANSI colors (red 31, green 32, yellow 33, blue 34, magenta 35, cyan 36). Same target always gets the same color. Use a simple hash (e.g., `fnv32(target) % len(palette)`). |
| 37 | +- **Message text** — default/no color |
| 38 | +- **Attrs** (`key=value`) — dim (ANSI 2) for the key, default for value |
| 39 | + |
| 40 | +### Custom slog levels |
| 41 | +| Name | slog.Level value | Meaning | |
| 42 | +|---|---|---| |
| 43 | +| `ERROR` | `slog.LevelError` (8) | Error conditions | |
| 44 | +| `WARNING` | `slog.LevelWarn` (4) | Warnings | |
| 45 | +| `INFO` | `slog.LevelInfo` (0) | Normal status/progress | |
| 46 | +| `VERBOSE` | `slog.Level(-2)` | Detailed progress (was `logVerbose`) | |
| 47 | +| `DEBUG` | `slog.LevelDebug` (-4) | EPA/TLS/NTLM diagnostics (was `logDebug`/`logf`) | |
| 48 | + |
| 49 | +### Level mapping from current code |
| 50 | +| Current pattern | New level | |
| 51 | +|---|---| |
| 52 | +| `fmt.Printf(...)` (status/progress) | `INFO` | |
| 53 | +| `fmt.Printf("Warning: ...")` | `WARNING` | |
| 54 | +| `fmt.Printf("ERROR: ...")` | `ERROR` | |
| 55 | +| `logVerbose(...)` | `VERBOSE` | |
| 56 | +| `logDebug(...)` / `logf(...)` (EPA diagnostics) | `DEBUG` | |
| 57 | + |
| 58 | +### Flag behavior |
| 59 | +- No flags: minimum level = INFO |
| 60 | +- `--verbose`: minimum level = VERBOSE (shows VERBOSE + INFO + WARNING + ERROR) |
| 61 | +- `--debug`: minimum level = DEBUG (shows everything) |
| 62 | +- `--debug` additionally sets `debug=true` on subsystems (controls EPA test behavior beyond just logging) |
| 63 | + |
| 64 | +## Implementation Phases |
| 65 | + |
| 66 | +### Phase 0: Custom handler (`internal/logging/`) |
| 67 | + |
| 68 | +**New file: [internal/logging/handler.go](go/internal/logging/handler.go)** |
| 69 | +- Implement `slog.Handler` that formats: `LEVEL TIMESTAMP [target] message attrs...` |
| 70 | +- Define custom level constants: `LevelVerbose = slog.Level(-2)` |
| 71 | +- Level name mapping: `-2` → `VERBOSE`, `slog.LevelWarn` → `WARNING` |
| 72 | +- Left-align level name, right-pad to 7 chars |
| 73 | +- Special handling for `target` attr: rendered as `[value]` before the message, not as `key=value` |
| 74 | +- Other attrs appended as `key=value` after the message |
| 75 | +- Thread-safe writer (mutex around writes) |
| 76 | +- `WithAttrs` / `WithGroup` support for creating sub-loggers (e.g., `logger.With("target", server)`) |
| 77 | +- ANSI color support: detect TTY via `golang.org/x/term.IsTerminal(int(os.Stderr.Fd()))` |
| 78 | +- Color each element per the palette defined above (level, timestamp, target, attrs) |
| 79 | +- Target color: `fnv32a(targetString) % 6` maps to one of [blue 34, cyan 36, bright green 92, bright blue 94, bright cyan 96, bright white 97]. These avoid red (ERROR), yellow (WARNING), magenta (DEBUG), and gray (VERBOSE). |
| 80 | +- Accept a `NoColor bool` option to force colors off (for tests or `--no-color` flag) |
| 81 | + |
| 82 | +### Phase 1: Logger setup in main (`cmd/mssqlhound/`) |
| 83 | + |
| 84 | +**[main.go](go/cmd/mssqlhound/main.go)** |
| 85 | +- Create `slog.LevelVar` and `*slog.Logger` with custom `logging.NewHandler(os.Stderr, ...)` in `main()` |
| 86 | +- Add `PersistentPreRunE` to set level from `--verbose`/`--debug` flags |
| 87 | +- Pass logger to `run()` and subcommands |
| 88 | +- Convert 11 `fmt.Printf`/`fmt.Println` calls to `logger.Info`/`logger.Warn` |
| 89 | +- Keep `fmt.Fprintf(os.Stderr, ...)` for cobra error at line 105 (logger may not exist) |
| 90 | + |
| 91 | +**[cmd_test_epa_matrix.go](go/cmd/mssqlhound/cmd_test_epa_matrix.go)** |
| 92 | +- Accept logger parameter from main |
| 93 | +- Convert 8 `fmt.Printf` calls |
| 94 | + |
| 95 | +### Phase 2: Collector (`internal/collector/`) |
| 96 | + |
| 97 | +**[collector.go](go/internal/collector/collector.go)** |
| 98 | +- Add `Logger *slog.Logger` field to `Config` struct |
| 99 | +- Convert 75 `fmt.Printf`/`fmt.Println` calls to appropriate slog levels |
| 100 | +- Convert 49 `c.logVerbose(...)` calls to `c.config.Logger.Log(ctx, logging.LevelVerbose, ...)` |
| 101 | +- Remove `logVerbose` method (line 6128) |
| 102 | +- When processing a server, create a sub-logger: `serverLog := c.config.Logger.With("target", server.ConnectionString)` and use it for all per-server messages |
| 103 | +- For domain-level operations: `domainLog := c.config.Logger.With("target", domain)` |
| 104 | +- Pass logger to `mssql.Client` and `wmi` calls |
| 105 | + |
| 106 | +### Phase 3: MSSQL client (`internal/mssql/`) |
| 107 | + |
| 108 | +**[client.go](go/internal/mssql/client.go)** — 15 fmt calls + 7 logf calls |
| 109 | +- Add `logger *slog.Logger` field, `SetLogger` method |
| 110 | +- Default to `slog.Default()` in `NewClient` |
| 111 | +- Replace `logVerbose`/`logDebug` methods with `c.logger.Debug()` |
| 112 | +- Change `epaTLSDialer.logf` and `epaTDSDialer.logf` fields from `func(string, ...interface{})` to `*slog.Logger` |
| 113 | +- Update dialer `d.logf(...)` calls to `d.logger.Debug(...)` |
| 114 | + |
| 115 | +**[epa_tester.go](go/internal/mssql/epa_tester.go)** — 69 logf calls + 2 fmt calls |
| 116 | +- Add `Logger *slog.Logger` to `EPATestConfig` |
| 117 | +- Remove the `logf` closure (line 91-95) |
| 118 | +- Convert all 69 `logf(...)` calls to `config.Logger.Debug(...)` with `"component", "epa"` attr |
| 119 | +- Convert 2 direct `fmt.Printf` calls |
| 120 | + |
| 121 | +**[epa_auth_provider.go](go/internal/mssql/epa_auth_provider.go)** — 2 fmt calls |
| 122 | +- Add `logger *slog.Logger` field |
| 123 | +- Convert 2 `fmt.Printf("[EPA-auth] ...")` calls |
| 124 | + |
| 125 | +**[powershell_fallback.go](go/internal/mssql/powershell_fallback.go)** — 1 fmt call |
| 126 | +- Add `logger *slog.Logger` field, `SetLogger` method |
| 127 | +- Remove `logVerbose` method, convert call to `p.logger.Debug()` |
| 128 | + |
| 129 | +### Phase 4: Supporting packages |
| 130 | + |
| 131 | +**[epamatrix/epamatrix.go](go/internal/epamatrix/epamatrix.go)** — 24 fmt calls |
| 132 | +- Add `Logger *slog.Logger` to `MatrixConfig` |
| 133 | +- Convert all 24 calls |
| 134 | + |
| 135 | +**[wmi/wmi_windows.go](go/internal/wmi/wmi_windows.go)** — 7 fmt calls |
| 136 | +- Change `GetLocalGroupMembers` and `GetLocalGroupMembersWithFallback` signatures: replace `verbose bool` with `logger *slog.Logger` |
| 137 | +- Update [wmi/wmi_stub.go](go/internal/wmi/wmi_stub.go) signatures to match |
| 138 | +- Update caller in [collector.go:1854](go/internal/collector/collector.go#L1854) |
| 139 | + |
| 140 | +### NOT changed |
| 141 | +- **[epamatrix/table.go](go/internal/epamatrix/table.go)** — `PrintResultsTable`/`Summarize` write formatted table data to `io.Writer`. This is data output, not logging. |
| 142 | +- All `fmt.Errorf(...)` calls (error construction, not logging) |
| 143 | +- All `fmt.Sprintf(...)` calls (string building) |
| 144 | + |
| 145 | +## Verification |
| 146 | +1. `go build ./...` compiles cleanly |
| 147 | +2. `go vet ./...` passes |
| 148 | +3. Run with no flags — only INFO+ messages appear, each with UTC timestamp and level |
| 149 | +4. Run with `--verbose` — DEBUG messages appear |
| 150 | +5. Run with `--debug` — EPA diagnostic messages appear with `component=epa` attribute |
| 151 | +6. Table output (EPA matrix) still renders correctly to stdout without log formatting |
0 commit comments