Skip to content

Always write debug logs to a file #1983

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
jordanstephens wants to merge 3 commits into
base: main
Choose a base branch
from
Open

Always write debug logs to a file #1983

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
5c13aca
always write all logs to debug.log, never print debug to terminal
jordanstephens Mar 12, 2026
11b8925
fix debug output leaking to stdout via term.Println/Printc
jordanstephens Mar 12, 2026
6329370
remove unnecessary DoDebug guards
jordanstephens Mar 13, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
40 changes: 40 additions & 0 deletions src/cmd/cli/main.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,9 +6,12 @@ import (
"log/slog"
"os"
"os/signal"
"path/filepath"
"runtime/debug"
"sync"

"github.com/DefangLabs/defang/src/cmd/cli/command"
"github.com/DefangLabs/defang/src/pkg/cli/client"
"github.com/DefangLabs/defang/src/pkg/logs"
"github.com/DefangLabs/defang/src/pkg/term"
"github.com/DefangLabs/defang/src/pkg/track"
Expand All @@ -28,6 +31,11 @@ func main() {
setUidGidFromFile(homeDir)
}

// 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()
Comment on lines +34 to +37
Copy link
Copy Markdown
Contributor

@coderabbitai coderabbitai Bot Mar 13, 2026

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.


// Handle Ctrl+C so we can exit gracefully
ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt)

Expand All @@ -47,6 +55,7 @@ func main() {
if !ok {
ec = 1 // should not happen since we always return ExitCode
}
flushDebugLog() // os.Exit skips defers, so flush explicitly
os.Exit(int(ec))
}
}
Expand All @@ -56,3 +65,34 @@ func skipLines(buf []byte, n int) []byte {
lines := bytes.SplitN(buf, []byte{'\n'}, n)
return lines[len(lines)-1]
}

// setupDebugLog creates a temp debug log file, wires it into DefaultTerm, and
// returns a flush function that closes and atomically renames the file to
// debug.log. The flush function is idempotent — safe to call multiple times.
func setupDebugLog() func() {
stateDir := client.StateDir
if err := os.MkdirAll(stateDir, 0700); err != nil {
return func() {}
}

finalPath := filepath.Join(stateDir, "debug.log")
f, err := os.CreateTemp(stateDir, "debug-*.log")
if err != nil {
return func() {}
Comment thread
lionello marked this conversation as resolved.
}
tmpPath := f.Name()

term.SetDebugLog(f)

var once sync.Once
return func() {
once.Do(func() {
term.SetDebugLog(nil)
f.Close()
os.Rename(tmpPath, finalPath) //nolint:errcheck
if term.DoDebug() {
term.Infof("Debug log written to: %s", finalPath)
Copy link
Copy Markdown
Member

@lionello lionello Mar 16, 2026

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
Copy Markdown
Member Author

@jordanstephens jordanstephens Mar 16, 2026

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?

}
Comment on lines +90 to +95
Copy link
Copy Markdown
Contributor

@coderabbitai coderabbitai Bot Mar 13, 2026

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.

})
}
}
5 changes: 2 additions & 3 deletions src/pkg/cli/compose/context.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -446,9 +446,8 @@ func createArchive(ctx context.Context, root string, dockerfile string, contentT

doProgress := term.StdoutCanColor() && term.IsTerminal()
err := walkContextFolder(root, dockerfile, writeIgnoreFileYes, func(path string, de os.DirEntry, slashPath string) error {
if term.DoDebug() {
term.Debug("Adding", slashPath)
} else if doProgress {
term.Debug("Adding", slashPath)
if doProgress {
term.Printf("%4d %s\r", fileCount, slashPath)
defer term.ClearLine()
}
Expand Down
6 changes: 2 additions & 4 deletions src/pkg/cli/compose/loader.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -118,10 +118,8 @@ func (l *Loader) loadProject(ctx context.Context, suppressWarn bool) (*Project,
return nil, err
}

if term.DoDebug() {
b, _ := yaml.Marshal(project)
term.Println(string(b))
}
b, _ := yaml.Marshal(project)
term.Debug(string(b))

l.cached = project
return project, nil
Expand Down
10 changes: 6 additions & 4 deletions src/pkg/cli/composeUp.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -203,10 +203,12 @@ func ComposeUp(ctx context.Context, fabric client.FabricClient, provider client.
term.Warn("Unable to update deployment history; deployment will proceed anyway.")
}

if term.DoDebug() {
term.Println("Project:", project.Name)
for _, serviceInfo := range resp.Services {
PrintObject(serviceInfo.Service.Name, serviceInfo)
term.Debugf("Project: %s", project.Name)
for _, serviceInfo := range resp.Services {
if b, err := MarshalPretty(serviceInfo.Service.Name, serviceInfo); err != nil {
term.Debugf("MarshalPretty error: %v", err)
} else {
term.Debug(string(b))
}
}
return resp, project, nil
Expand Down
12 changes: 3 additions & 9 deletions src/pkg/cli/generate.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -36,15 +36,9 @@ func GenerateWithAI(ctx context.Context, client client.FabricClient, args Genera
return nil, err
}

if term.DoDebug() {
// Print the files that were generated
for _, file := range response.Files {
term.Printc(term.DebugColor, file.Name+"\n```")
term.Printc(term.DebugColor, file.Content)
term.Printc(term.DebugColor, "```")
term.Println("")
term.Println("")
}
// file.Content can be large; skip string formatting when debug output won't be captured
for _, file := range response.Files {
term.Debugf("%s\n```\n%s\n```\n", file.Name, file.Content)
}

// Write each file to disk
Expand Down
3 changes: 0 additions & 3 deletions src/pkg/logs/slog.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -66,9 +66,6 @@ func (h *termHandler) Handle(ctx context.Context, r slog.Record) error {
}

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

@lionello lionello Mar 16, 2026

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.

return h.t.DoDebug()
}
return true
}

Expand Down
45 changes: 36 additions & 9 deletions src/pkg/term/colorizer.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,8 @@ type Term struct {
hasDarkBg bool

warnings []string

debugLog io.Writer // always-on file writer for all log levels; nil until set
}

var DefaultTerm = NewTerm(os.Stdin, os.Stdout, os.Stderr)
Expand Down Expand Up @@ -85,6 +87,16 @@ func (t *Term) SetDebug(debug bool) {
t.debug = debug
}

func (t *Term) SetDebugLog(w io.Writer) {
t.debugLog = w
}

func (t *Term) teeLog(msg string) {
if t.debugLog != nil {
fmt.Fprint(t.debugLog, msg)
}
}

func (t *Term) SetJSON(json bool) {
if json {
t.ForceColor(false)
Expand Down Expand Up @@ -211,17 +223,19 @@ func (t *Term) Printf(format string, v ...any) (int, error) {
}

func (t *Term) Debug(v ...any) (int, error) {
if !t.debug {
if t.debugLog == nil {
return 0, nil
}
return output(t.err, DebugColor, ensurePrefix(debugPrefix, fmt.Sprintln(v...)))
msg := ensurePrefix(debugPrefix, fmt.Sprintln(v...))
return fmt.Fprint(t.debugLog, msg)
}

func (t *Term) Debugf(format string, v ...any) (int, error) {
if !t.debug {
if t.debugLog == nil {
return 0, nil
}
return output(t.err, DebugColor, ensureNewline(ensurePrefix(debugPrefix, fmt.Sprintf(format, v...))))
msg := ensureNewline(ensurePrefix(debugPrefix, fmt.Sprintf(format, v...)))
return fmt.Fprint(t.debugLog, msg)
}

func (t *Term) outOrErr() *termenv.Output {
Expand All @@ -232,32 +246,41 @@ func (t *Term) outOrErr() *termenv.Output {
}

func (t *Term) Info(v ...any) (int, error) {
return output(t.outOrErr(), InfoColor, ensurePrefix(infoPrefix, fmt.Sprintln(v...)))
msg := ensurePrefix(infoPrefix, fmt.Sprintln(v...))
t.teeLog(msg)
return output(t.outOrErr(), InfoColor, msg)
}

func (t *Term) Infof(format string, v ...any) (int, error) {
return output(t.outOrErr(), InfoColor, ensureNewline(ensurePrefix(infoPrefix, fmt.Sprintf(format, v...))))
msg := ensureNewline(ensurePrefix(infoPrefix, fmt.Sprintf(format, v...)))
t.teeLog(msg)
return output(t.outOrErr(), InfoColor, msg)
}

func (t *Term) Warn(v ...any) (int, error) {
msg := ensurePrefix(warnPrefix, fmt.Sprintln(v...))
t.warnings = append(t.warnings, msg)
t.teeLog(msg)
return output(t.outOrErr(), WarnColor, msg)
}

func (t *Term) Warnf(format string, v ...any) (int, error) {
msg := ensureNewline(ensurePrefix(warnPrefix, fmt.Sprintf(format, v...)))
t.warnings = append(t.warnings, msg)
t.teeLog(msg)
return output(t.outOrErr(), WarnColor, msg)
}

func (t *Term) Error(v ...any) (int, error) {
return output(t.err, ErrorColor, fmt.Sprintln(v...))
msg := fmt.Sprintln(v...)
t.teeLog(msg)
return output(t.err, ErrorColor, msg)
}

func (t *Term) Errorf(format string, v ...any) (int, error) {
line := ensureNewline(fmt.Sprintf(format, v...))
return output(t.err, ErrorColor, line)
msg := ensureNewline(fmt.Sprintf(format, v...))
t.teeLog(msg)
return output(t.err, ErrorColor, msg)
}

// Deprecated: use proper error handling instead
Expand Down Expand Up @@ -372,6 +395,10 @@ func SetDebug(debug bool) {
DefaultTerm.SetDebug(debug)
}

func SetDebugLog(w io.Writer) {
DefaultTerm.SetDebugLog(w)
}

func SetJSON(json bool) {
DefaultTerm.SetJSON(json)
}
Expand Down
25 changes: 19 additions & 6 deletions src/pkg/term/colorizer_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -74,9 +74,10 @@ func TestAddingPrefix(t *testing.T) {
t.Cleanup(func() {
DefaultTerm = defaultTerm
})
var stdout, stderr bytes.Buffer
var stdout, stderr, debugLog bytes.Buffer
DefaultTerm = NewTerm(os.Stdin, &stdout, &stderr)
DefaultTerm.SetDebug(true)
DefaultTerm.SetDebugLog(&debugLog)

Debug("Hello, World!")
Debugf("Hello, %s!", "World")
Expand Down Expand Up @@ -110,16 +111,28 @@ func TestAddingPrefix(t *testing.T) {
}
}

expectedErr := []string{
if stderr.String() != "" {
t.Errorf("Expected stderr to be empty (debug goes to log file), got %q", stderr.String())
}

expectedLog := []string{
" - Hello, World!",
" - Hello, World!",
" - Hello, World!",
" - Hello, World!",
" * Hello, World!",
" * Hello, World!",
" * Hello, World!",
" * Hello, World!",
" ! Hello, World!",
" ! Hello, World!",
" ! Hello, World!",
" ! Hello, World!",
}
gotErr := strings.Split(strings.TrimRight(stderr.String(), "\n"), "\n")
for i, line := range gotErr {
if line != expectedErr[i] {
t.Errorf("Expected line %v in stderr to be %q, got %q", i, expectedErr[i], line)
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)
Comment on lines +132 to +135
Copy link
Copy Markdown
Contributor

@coderabbitai coderabbitai Bot Mar 13, 2026

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.

}
}
}
Expand Down
Loading