Skip to content

Always write debug logs to a file#1983

Open
jordanstephens wants to merge 3 commits intomainfrom
jordan/debug-log-file
Open

Always write debug logs to a file#1983
jordanstephens wants to merge 3 commits intomainfrom
jordan/debug-log-file

Conversation

@jordanstephens
Copy link
Member

@jordanstephens jordanstephens commented Mar 13, 2026

Description

This PR modifies the behaviour of --debug. Instead of printing debug logs to stdout when --debug is set, we will always write all logs (including debug logs) to ~/.local/state/defang/debug.log. debug logs will never be printed to stdout. But if --debug is set, we will print a message before process exit to indicate where debug logs can be read.

defang whoami
 * Using the "beta" stack on auto from fallback stack

WORKSPACE  SUBSCRIBERTIER  NAME       EMAIL                         PROVIDER  REGION
smallsurf  PERSONAL        smallsurf  jordan+smallsurf@stephens.io  defang    us-west-2  
defang whoami --debug
 * Using the "beta" stack on auto from fallback stack

WORKSPACE  SUBSCRIBERTIER  NAME       EMAIL                         PROVIDER  REGION
smallsurf  PERSONAL        smallsurf  jordan+smallsurf@stephens.io  defang    us-west-2  
 * Debug log written to: /Users/jordan/.local/state/defang/debug.log
cat /Users/jordan/.local/state/defang/debug.log
 - Using tenant "personal tenant" for cluster "fabric-prod1.defang.dev:443"
 - Reading access token from file /Users/jordan/.local/state/defang/fabric-prod1.defang.dev
 - Using tenant "personal tenant" for cluster "fabric-prod1.defang.dev:443"
 - Reading access token from file /Users/jordan/.local/state/defang/fabric-prod1.defang.dev
 - fabricClient 9qfd8z49ns90 /io.defang.v1.FabricController/WhoAmI null
 - fabricClient igbv8sp0pn5p /io.defang.v1.FabricController/GetVersion null
 - Fabric: v0.6.0-1499-gefeb4779 CLI: f734447c-dirty CLI-Min: v3.1.0
 - fabricClient s76zuqbbdgee /io.defang.v1.FabricController/CheckToS null
 - tracking event "WHOAMI INVOKED": [{args []} {err <nil>} {non-interactive false} {provider auto} {CalledAs  whoami} {version f734447c-dirty}]
 - fabricClient tkzbe6jvx5uc /io.defang.v1.FabricController/Track {"anon_id":"7af0de15-0001-4ab2-af8b-d2be914e04b9","event":"WHOAMI INVOKED","properties":{"CalledAs":" whoami","args":"[]","err":"\u003cnil\u003e","non-interactive":"false","provider":"auto","version":"f734447c-dirty"},"os":"darwin","arch":"arm64"}
 - fabricClient p44s22od8p8c /io.defang.v1.FabricController/GetDefaultStack {"project":"nextjs"}
 - Creating auto provider
 * Using the "beta" stack on auto from fallback stack
 - Reading access token from file /Users/jordan/.local/state/defang/fabric-prod1.defang.dev
 - [DEBUG] GET https://auth.defang.io/userinfo
 - fabricClient eoqied3mwvv1 /io.defang.v1.FabricController/WhoAmI null
 - User ID: 4a0e5c21-a508-5397-9d54-d9a908becc08

Linked Issues

Checklist

  • I have performed a self-review of my code
  • I have added appropriate tests
  • I have updated the Defang CLI docs and/or README to reflect my changes, if necessary

Summary by CodeRabbit

  • New Features

    • Debug logs are now automatically and persistently captured to debug.log for comprehensive post-execution diagnostics and troubleshooting without requiring manual intervention.
    • All diagnostic output is continuously recorded throughout execution, providing complete visibility into application behavior and system health.
  • Improvements

    • Refined debug message formatting for improved clarity and readability.

jordanstephens and others added 3 commits March 12, 2026 17:03
- All log levels (including debug) are always written to
  ~/.local/state/defang/debug-*.log, renamed atomically to debug.log on exit
- Debug logs are never printed to the terminal, even with --debug
- If --debug is set, a reminder message is printed on exit with the log path
- slog debug messages now always flow through to the file (Enabled() = true)

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
Replace direct term.Println/Printc calls inside DoDebug() guards with
term.Debug/Debugf so those dumps go to the log file instead of stdout.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
@coderabbitai
Copy link
Contributor

coderabbitai bot commented Mar 13, 2026

📝 Walkthrough

Walkthrough

Introduces persistent, always-on debug logging via a setupDebugLog function that creates a temporary debug log file, wires it through the terminal logger, and atomically flushes it to debug.log on exit. Removes conditional debug output checks throughout the codebase, shifting from runtime-gated logging to unconditional logging controlled by debugLog writer presence.

Changes

Cohort / File(s) Summary
Debug Logging Infrastructure
src/cmd/cli/main.go, src/pkg/term/colorizer.go
Introduces setupDebugLog function that creates temporary debug log file and wires it to terminal logger. Adds SetDebugLog method to Term and replaces DoDebug flag checks with debugLog writer presence checks. Routes all log levels through debugLog when set.
Unconditional Debug Output Migration
src/pkg/cli/compose/context.go, src/pkg/cli/compose/loader.go, src/pkg/cli/composeUp.go, src/pkg/cli/generate.go
Removes conditional gating on debug output by eliminating DoDebug checks and converting PrintObject calls to unconditional term.Debug/Debugf calls with improved formatting.
Log Level Handling
src/pkg/logs/slog.go
Simplifies Enabled method for slog.LevelDebug to always return true, removing conditional logic.
Test Updates
src/pkg/term/colorizer_test.go
Adds debugLog buffer wiring and updates test assertions to validate debug output routing through SetDebugLog rather than stderr.

Sequence Diagram

sequenceDiagram
    participant Main as CLI Main
    participant Setup as setupDebugLog
    participant Term as Terminal Logger
    participant File as Debug Log File
    participant Exit as Program Exit

    Main->>Setup: Call setupDebugLog()
    Setup->>File: Create temp debug.log
    Setup->>Term: SetDebugLog(file)
    activate Term
    
    Note over Main,Term: During execution
    Main->>Term: Debug/Debugf calls
    Term->>File: Write log messages
    
    Main->>Exit: Program terminates
    deactivate Term
    Exit->>Setup: Call flush()
    Setup->>File: Close file
    Setup->>File: Rename temp to debug.log
Loading

Estimated code review effort

🎯 4 (Complex) | ⏱️ ~60 minutes

Possibly related PRs

  • Fix unit test delays #1731: Modifies src/pkg/term/colorizer.go and changes debug output routing destination, directly related to the debugLog writer infrastructure introduced here.

Suggested reviewers

  • lionello
  • edwardrf
  • KevyVo

Poem

🐰 Logs that never sleep, always stored,
No more flags to check and explore,
Debug flows where writers lead the way,
Capturing secrets throughout the day,
Forever waiting in debug.log's embrace! 📝✨

🚥 Pre-merge checks | ✅ 2 | ❌ 1

❌ Failed checks (1 warning)

Check name Status Explanation Resolution
Docstring Coverage ⚠️ Warning Docstring coverage is 30.00% which is insufficient. The required threshold is 80.00%. Write docstrings for the functions missing them to satisfy the coverage threshold.
✅ Passed checks (2 passed)
Check name Status Explanation
Description Check ✅ Passed Check skipped - CodeRabbit’s high-level summary is enabled.
Title check ✅ Passed The title 'Always write debug logs to a file' directly and clearly summarizes the main change: introducing persistent file-based debug logging instead of stdout-based conditional logging.

✏️ Tip: You can configure your own custom pre-merge checks in the settings.

✨ Finishing Touches
  • 📝 Generate docstrings (stacked PR)
  • 📝 Generate docstrings (commit on current branch)
🧪 Generate unit tests (beta)
  • Create PR with unit tests
  • Post copyable unit tests in a comment
  • Commit unit tests in branch jordan/debug-log-file
📝 Coding Plan
  • Generate coding plan for human review comments

Warning

There were issues while running some tools. Please review the errors and either fix the tool's configuration or disable the tool if it's a critical failure.

🔧 golangci-lint (2.11.3)

level=warning msg="[linters_context] running gomodguard failed: unable to read module file go.mod: current working directory must have a go.mod file: if you are not using go modules it is suggested to disable this linter"
level=error msg="[linters_context] typechecking error: pattern ./...: directory prefix . does not contain main module or its selected dependencies"


Comment @coderabbitai help to get the list of available commands and usage tips.

Copy link
Contributor

@coderabbitai coderabbitai bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actionable comments posted: 4

🤖 Prompt for all review comments with AI agents
Verify each finding against the current code and only fix it if needed.

Inline comments:
In `@src/cmd/cli/main.go`:
- Around line 34-37: The always-on debug file setup (setupDebugLog() /
flushDebugLog()) causes term.Debug* payloads (used in
src/pkg/cli/compose/loader.go, src/pkg/cli/generate.go,
src/pkg/cli/composeUp.go) to be written to disk even when --debug is off; change
main.go to initialize the debug log only when the debug flag is enabled (or an
equivalent runtime setting) by checking the parsed CLI debug option before
calling setupDebugLog(), and ensure any deferred flushDebugLog() is only
registered when setupDebugLog() was actually called so debug dumps are only
persisted when the explicit debug flag is set.
- Around line 73-81: The current setup silently disables logging when
os.MkdirAll or os.CreateTemp fails; instead preserve the error and surface a
warning when the returned cleanup/flush closure runs. Capture the error(s) from
os.MkdirAll and os.CreateTemp (the variables stateDir, f, err, finalPath) and
return a closure that, on flush, checks for a non-nil error and emits a clear
warning (to stderr or the existing logger) explaining why the debug/log file
wasn't created and what the error was, while still performing any existing
flush/close behavior when f was successfully created.
- Around line 90-95: The success message is printed even if f.Close() or
os.Rename(tmpPath, finalPath) fail; update the debug-log finalization in the
block that calls term.SetDebugLog(nil) so you check and handle the error results
of f.Close() and os.Rename (remove the //nolint:errcheck suppression), only call
term.Infof("Debug log written to: %s", finalPath) when both operations succeed,
and call term.Errorf/term.Warnf or return the error if either Close or Rename
fails so callers see the failure; reference the f.Close(), os.Rename(tmpPath,
finalPath), term.DoDebug(), and term.Infof calls when making this change.

In `@src/pkg/term/colorizer_test.go`:
- Around line 132-135: The test currently only iterates gotLog and can miss
truncated output; add an explicit length assertion comparing len(gotLog) and
len(expectedLog) before the loop (e.g., t.Fatalf or t.Errorf on mismatch) or
change the loop to iterate over expectedLog so every expected line is validated;
refer to gotLog, expectedLog and debugLog.String() to locate where to add the
length check and fail fast if sizes differ.

ℹ️ Review info
⚙️ Run configuration

Configuration used: defaults

Review profile: CHILL

Plan: Pro

Run ID: 4891a146-325f-4f28-8940-c46d4f02997d

📥 Commits

Reviewing files that changed from the base of the PR and between 30946a2 and 6329370.

📒 Files selected for processing (8)
  • src/cmd/cli/main.go
  • src/pkg/cli/compose/context.go
  • src/pkg/cli/compose/loader.go
  • src/pkg/cli/composeUp.go
  • src/pkg/cli/generate.go
  • src/pkg/logs/slog.go
  • src/pkg/term/colorizer.go
  • src/pkg/term/colorizer_test.go
💤 Files with no reviewable changes (1)
  • src/pkg/logs/slog.go

Comment on lines +34 to +37
// Set up always-on debug log file; all log levels are written here.
// defer handles the normal-exit path; the explicit call handles os.Exit.
flushDebugLog := setupDebugLog()
defer flushDebugLog()
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Potential issue | 🟠 Major

Always-on log setup now persists high-risk debug payloads by default.

Because setupDebugLog() runs for every invocation, the new term.Debug* dumps in src/pkg/cli/compose/loader.go, src/pkg/cli/generate.go, and src/pkg/cli/composeUp.go now land on disk even when --debug is off. Those payloads include full compose YAML and generated file contents, so this change silently retains secrets and proprietary source unless those call sites are redacted or kept behind the explicit debug flag.

🤖 Prompt for AI Agents
Verify each finding against the current code and only fix it if needed.

In `@src/cmd/cli/main.go` around lines 34 - 37, The always-on debug file setup
(setupDebugLog() / flushDebugLog()) causes term.Debug* payloads (used in
src/pkg/cli/compose/loader.go, src/pkg/cli/generate.go,
src/pkg/cli/composeUp.go) to be written to disk even when --debug is off; change
main.go to initialize the debug log only when the debug flag is enabled (or an
equivalent runtime setting) by checking the parsed CLI debug option before
calling setupDebugLog(), and ensure any deferred flushDebugLog() is only
registered when setupDebugLog() was actually called so debug dumps are only
persisted when the explicit debug flag is set.

Comment on lines +90 to +95
term.SetDebugLog(nil)
f.Close()
os.Rename(tmpPath, finalPath) //nolint:errcheck
if term.DoDebug() {
term.Infof("Debug log written to: %s", finalPath)
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Potential issue | 🟠 Major

🧩 Analysis chain

🌐 Web query:

In Go's standard library, what does os.Rename do on Windows when the destination file already exists? Does it replace the file atomically or return an error?

💡 Result:

On Windows, os.Rename(old, new) calls the Windows API MoveFileEx with the MOVEFILE_REPLACE_EXISTING flag, so if new already exists and is not a directory, it will attempt to replace/overwrite it rather than failing just because it exists. [1][2]

However, Go explicitly documents that on non-Unix platforms (including Windows) Rename is not an atomic operation, even within the same directory. So you should not rely on it being an atomic replace on Windows. [3]

Sources:
[1] Go source: internal/syscall/windows.Rename uses MoveFileEx(..., MOVEFILE_REPLACE_EXISTING)
[2] Microsoft docs: MoveFileEx can replace an existing file with MOVEFILE_REPLACE_EXISTING
[3] Go docs for os.Rename (non-Unix rename not atomic)


Check Close and Rename results before printing the success message.

A failed f.Close() or os.Rename() still leads to "Debug log written to…", which can point at a partially written or non-existent file. The //nolint:errcheck directive suppresses these critical errors—move the success message inside an error check or handle the failures explicitly.

🤖 Prompt for AI Agents
Verify each finding against the current code and only fix it if needed.

In `@src/cmd/cli/main.go` around lines 90 - 95, The success message is printed
even if f.Close() or os.Rename(tmpPath, finalPath) fail; update the debug-log
finalization in the block that calls term.SetDebugLog(nil) so you check and
handle the error results of f.Close() and os.Rename (remove the
//nolint:errcheck suppression), only call term.Infof("Debug log written to: %s",
finalPath) when both operations succeed, and call term.Errorf/term.Warnf or
return the error if either Close or Rename fails so callers see the failure;
reference the f.Close(), os.Rename(tmpPath, finalPath), term.DoDebug(), and
term.Infof calls when making this change.

Comment on lines +132 to +135
gotLog := strings.Split(strings.TrimRight(debugLog.String(), "\n"), "\n")
for i, line := range gotLog {
if line != expectedLog[i] {
t.Errorf("Expected line %v in debug log to be %q, got %q", i, expectedLog[i], line)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Potential issue | 🟡 Minor

Assert the debug-log length before comparing lines.

This loop only walks gotLog, so truncated output with a matching prefix still passes. Add a length check first, or iterate expectedLog instead.

Proposed fix
 gotLog := strings.Split(strings.TrimRight(debugLog.String(), "\n"), "\n")
-for i, line := range gotLog {
-	if line != expectedLog[i] {
-		t.Errorf("Expected line %v in debug log to be %q, got %q", i, expectedLog[i], line)
-	}
-}
+if len(gotLog) != len(expectedLog) {
+	t.Fatalf("Expected %d lines in debug log, got %d: %q", len(expectedLog), len(gotLog), gotLog)
+}
+for i, expected := range expectedLog {
+	if gotLog[i] != expected {
+		t.Errorf("Expected line %v in debug log to be %q, got %q", i, expected, gotLog[i])
+	}
+}
📝 Committable suggestion

‼️ IMPORTANT
Carefully review the code before committing. Ensure that it accurately replaces the highlighted code, contains no missing lines, and has no issues with indentation. Thoroughly test & benchmark the code to ensure it meets the requirements.

Suggested change
gotLog := strings.Split(strings.TrimRight(debugLog.String(), "\n"), "\n")
for i, line := range gotLog {
if line != expectedLog[i] {
t.Errorf("Expected line %v in debug log to be %q, got %q", i, expectedLog[i], line)
gotLog := strings.Split(strings.TrimRight(debugLog.String(), "\n"), "\n")
if len(gotLog) != len(expectedLog) {
t.Fatalf("Expected %d lines in debug log, got %d: %q", len(expectedLog), len(gotLog), gotLog)
}
for i, expected := range expectedLog {
if gotLog[i] != expected {
t.Errorf("Expected line %v in debug log to be %q, got %q", i, expected, gotLog[i])
}
}
🤖 Prompt for AI Agents
Verify each finding against the current code and only fix it if needed.

In `@src/pkg/term/colorizer_test.go` around lines 132 - 135, The test currently
only iterates gotLog and can miss truncated output; add an explicit length
assertion comparing len(gotLog) and len(expectedLog) before the loop (e.g.,
t.Fatalf or t.Errorf on mismatch) or change the loop to iterate over expectedLog
so every expected line is validated; refer to gotLog, expectedLog and
debugLog.String() to locate where to add the length check and fail fast if sizes
differ.

Copy link
Member

@lionello lionello left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I can see the utility of this, but think it should be opt-in.

I actually planned to remove term.Debug, in favor of using Go's log or slog package. Those both follow an extensible model of being able to route logs to anything, even "tee" to existing term and file/endpoint/…

The reason is that it would make our CLI packages more usable elsewhere, in our server code, without terminal dependencies.

f.Close()
os.Rename(tmpPath, finalPath) //nolint:errcheck
if term.DoDebug() {
term.Infof("Debug log written to: %s", finalPath)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This feels weird: when --debug we print an info message? Why bother? We always write to the log file.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if we don't write this message, how will the user know how to read the debug logs?

}

func (h *termHandler) Enabled(ctx context.Context, level slog.Level) bool {
if level == slog.LevelDebug {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is why I think we should use the logging infrastructure: the termHandler log-level decides what gets printed, the logger decides what gets logged/written to file.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants