From adcb644e50053f5f879cbe78dbfb3fd43050956d Mon Sep 17 00:00:00 2001 From: Gustavo Lima Date: Sun, 12 Apr 2026 15:28:09 +0200 Subject: [PATCH 1/2] fix(log): send Debug and Trace output to stderr instead of stdout Fixes #851 Debug and Trace calls both used os.Stdout as the write target. When users piped 's5cmd --log debug cat s3://...' into another tool (e.g. xmlstarlet), the diagnostic messages were interleaved with the object payload and corrupted the stream. Only Error already used os.Stderr. This commit applies the same convention to Debug and Trace: diagnostics go to stderr, data goes to stdout. Reproducer: s5cmd --log debug cat s3://bucket/object.xml | xmlstarlet sel ... After this change: Debug/trace lines appear on stderr; stdout carries only object content. --- log/log.go | 4 +- log/log_test.go | 104 ++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 106 insertions(+), 2 deletions(-) create mode 100644 log/log_test.go diff --git a/log/log.go b/log/log.go index 5ec149ac9..c60c1beeb 100644 --- a/log/log.go +++ b/log/log.go @@ -24,12 +24,12 @@ func Init(level string, json bool) { // Trace prints message in trace mode. func Trace(msg Message) { - global.printf(LevelTrace, msg, os.Stdout) + global.printf(LevelTrace, msg, os.Stderr) } // Debug prints message in debug mode. func Debug(msg Message) { - global.printf(LevelDebug, msg, os.Stdout) + global.printf(LevelDebug, msg, os.Stderr) } // Info prints message in info mode. diff --git a/log/log_test.go b/log/log_test.go new file mode 100644 index 000000000..5c9f3437b --- /dev/null +++ b/log/log_test.go @@ -0,0 +1,104 @@ +package log + +import ( + "bytes" + "os" + "strings" + "testing" +) + +// captureOutputs redirects os.Stdout and os.Stderr, calls f, then returns +// whatever was written to each. The caller is responsible for draining the +// logger (e.g. calling Close) inside f before this function reads the pipes. +func captureOutputs(t *testing.T, f func()) (stdout, stderr string) { + t.Helper() + + origStdout := os.Stdout + origStderr := os.Stderr + defer func() { + os.Stdout = origStdout + os.Stderr = origStderr + }() + + rOut, wOut, err := os.Pipe() + if err != nil { + t.Fatal(err) + } + rErr, wErr, err := os.Pipe() + if err != nil { + t.Fatal(err) + } + + os.Stdout = wOut + os.Stderr = wErr + + f() + + wOut.Close() + wErr.Close() + + var bufOut, bufErr bytes.Buffer + if _, err := bufOut.ReadFrom(rOut); err != nil { + t.Fatal(err) + } + if _, err := bufErr.ReadFrom(rErr); err != nil { + t.Fatal(err) + } + return bufOut.String(), bufErr.String() +} + +// reinitOutputCh creates a fresh outputCh so tests don't share state. +func reinitOutputCh() { + outputCh = make(chan output, 10000) +} + +// TestDebugWritesToStderr verifies that Debug messages go to stderr, not stdout. +func TestDebugWritesToStderr(t *testing.T) { + reinitOutputCh() + Init("debug", false) + + stdout, stderr := captureOutputs(t, func() { + Debug(DebugMessage{Err: "hello debug"}) + Close() + }) + + if stdout != "" { + t.Errorf("Debug wrote to stdout, want stderr only; stdout=%q", stdout) + } + if !strings.Contains(stderr, "hello debug") { + t.Errorf("stderr does not contain expected message; stderr=%q", stderr) + } +} + +// TestTraceWritesToStderr verifies that Trace messages go to stderr, not stdout. +func TestTraceWritesToStderr(t *testing.T) { + reinitOutputCh() + Init("trace", false) + + stdout, stderr := captureOutputs(t, func() { + Trace(TraceMessage{Message: "hello trace"}) + Close() + }) + + if stdout != "" { + t.Errorf("Trace wrote to stdout, want stderr only; stdout=%q", stdout) + } + if !strings.Contains(stderr, "hello trace") { + t.Errorf("stderr does not contain expected message; stderr=%q", stderr) + } +} + +// TestInfoWritesToStdout verifies that Info messages continue to go to stdout. +func TestInfoWritesToStdout(t *testing.T) { + reinitOutputCh() + Init("info", false) + + stdout, _ := captureOutputs(t, func() { + Info(ErrorMessage{Err: "hello info"}) + Close() + }) + + if !strings.Contains(stdout, "hello info") { + t.Errorf("Info did not write to stdout; stdout=%q", stdout) + } +} From d000f7b5241a14c2b1e518212ab3fe0821caa882 Mon Sep 17 00:00:00 2001 From: Gustavo Lima Date: Sun, 12 Apr 2026 16:49:17 +0200 Subject: [PATCH 2/2] test(e2e): update assertions for Debug/Trace now going to stderr Companion to the log fix: e2e tests that used --log debug were asserting DEBUG lines in result.Stdout(). Now that Debug and Trace write to stderr, move those expectations to result.Stderr() and assert stdout is empty (or contains only the non-debug lines for mixed-output tests). --- e2e/cp_test.go | 24 ++++++++++++------------ e2e/pipe_test.go | 6 +++--- e2e/sync_test.go | 31 +++++++++++++++++++++++-------- 3 files changed, 38 insertions(+), 23 deletions(-) diff --git a/e2e/cp_test.go b/e2e/cp_test.go index a13b2ceda..5b5a14ea8 100644 --- a/e2e/cp_test.go +++ b/e2e/cp_test.go @@ -2449,12 +2449,12 @@ func TestCopyS3ToLocalWithSameFilenameWithNoClobber(t *testing.T) { result.Assert(t, icmd.Success) - assertLines(t, result.Stdout(), map[int]compareFunc{ + assertLines(t, result.Stdout(), map[int]compareFunc{}) + + assertLines(t, result.Stderr(), map[int]compareFunc{ 0: equals(`DEBUG "cp s3://%v/%v %v": object already exists`, bucket, filename, filename), }) - assertLines(t, result.Stderr(), map[int]compareFunc{}) - expected := fs.Expected(t, fs.WithFile(filename, content)) assert.Assert(t, fs.Equal(workdir.Path(), expected)) } @@ -2571,12 +2571,12 @@ func TestCopyS3ToLocalWithSameFilenameDontOverrideIfS3ObjectIsOlder(t *testing.T // size differs. result.Assert(t, icmd.Success) - assertLines(t, result.Stdout(), map[int]compareFunc{ + assertLines(t, result.Stdout(), map[int]compareFunc{}) + + assertLines(t, result.Stderr(), map[int]compareFunc{ 0: equals(`DEBUG "cp s3://%v/%v %v": object is newer or same age`, bucket, filename, filename), }) - assertLines(t, result.Stderr(), map[int]compareFunc{}) - expected := fs.Expected(t, fs.WithFile(filename, content)) assert.Assert(t, fs.Equal(workdir.Path(), expected)) } @@ -2701,12 +2701,12 @@ func TestCopyLocalFileToS3WithSameFilenameWithNoClobber(t *testing.T) { result.Assert(t, icmd.Success) - assertLines(t, result.Stdout(), map[int]compareFunc{ + assertLines(t, result.Stdout(), map[int]compareFunc{}) + + assertLines(t, result.Stderr(), map[int]compareFunc{ 0: equals(`DEBUG "cp %v s3://%v/%v": object already exists`, filename, bucket, filename), }) - assertLines(t, result.Stderr(), map[int]compareFunc{}) - // assert local filesystem expected := fs.Expected(t, fs.WithFile(filename, newContent)) assert.Assert(t, fs.Equal(workdir.Path(), expected)) @@ -2871,12 +2871,12 @@ func TestCopyLocalFileToS3WithSameFilenameDontOverrideIfS3ObjectIsOlder(t *testi // modtime differs. result.Assert(t, icmd.Success) - assertLines(t, result.Stdout(), map[int]compareFunc{ + assertLines(t, result.Stdout(), map[int]compareFunc{}) + + assertLines(t, result.Stderr(), map[int]compareFunc{ 0: equals(`DEBUG "cp %v s3://%v/%v": object is newer or same age`, filename, bucket, filename), }) - assertLines(t, result.Stderr(), map[int]compareFunc{}) - assert.NilError(t, ensureS3Object(s3client, bucket, filename, content)) } diff --git a/e2e/pipe_test.go b/e2e/pipe_test.go index 25db59558..7e64c5b58 100644 --- a/e2e/pipe_test.go +++ b/e2e/pipe_test.go @@ -221,12 +221,12 @@ func TestUploadStdinToS3WithSameFilenameWithNoClobber(t *testing.T) { result.Assert(t, icmd.Success) - assertLines(t, result.Stdout(), map[int]compareFunc{ + assertLines(t, result.Stdout(), map[int]compareFunc{}) + + assertLines(t, result.Stderr(), map[int]compareFunc{ 0: equals(`DEBUG "pipe s3://%v/%v": object already exists`, bucket, filename), }) - assertLines(t, result.Stderr(), map[int]compareFunc{}) - // expect s3 object is not overridden assert.Assert(t, ensureS3Object(s3client, bucket, filename, content)) } diff --git a/e2e/sync_test.go b/e2e/sync_test.go index d592e6d52..945619c5d 100644 --- a/e2e/sync_test.go +++ b/e2e/sync_test.go @@ -666,7 +666,9 @@ func TestSyncLocalFolderToS3BucketSameObjectsSourceOlder(t *testing.T) { result.Assert(t, icmd.Success) - assertLines(t, result.Stdout(), map[int]compareFunc{ + assertLines(t, result.Stdout(), map[int]compareFunc{}) + + assertLines(t, result.Stderr(), map[int]compareFunc{ 0: equals(`DEBUG "sync %va/another_test_file.txt %va/another_test_file.txt": object is newer or same age and object size matches`, src, dst), 1: equals(`DEBUG "sync %vmain.py %vmain.py": object is newer or same age and object size matches`, src, dst), 2: equals(`DEBUG "sync %vreadme.md %vreadme.md": object is newer or same age and object size matches`, src, dst), @@ -821,7 +823,9 @@ func TestSyncS3BucketToLocalFolderSameObjectsSourceOlder(t *testing.T) { result.Assert(t, icmd.Success) - assertLines(t, result.Stdout(), map[int]compareFunc{ + assertLines(t, result.Stdout(), map[int]compareFunc{}) + + assertLines(t, result.Stderr(), map[int]compareFunc{ 0: equals(`DEBUG "sync %v/a/another_test_file.txt %va/another_test_file.txt": object is newer or same age and object size matches`, bucketPath, dst), 1: equals(`DEBUG "sync %v/main.py %vmain.py": object is newer or same age and object size matches`, bucketPath, dst), 2: equals(`DEBUG "sync %v/readme.md %vreadme.md": object is newer or same age and object size matches`, bucketPath, dst), @@ -1041,7 +1045,9 @@ func TestSyncS3BucketToS3BucketSameSizesSourceOlder(t *testing.T) { result.Assert(t, icmd.Success) - assertLines(t, result.Stdout(), map[int]compareFunc{ + assertLines(t, result.Stdout(), map[int]compareFunc{}) + + assertLines(t, result.Stderr(), map[int]compareFunc{ 0: equals(`DEBUG "sync %v/a/another_test_file.txt %va/another_test_file.txt": object is newer or same age and object size matches`, bucketPath, dst), 1: equals(`DEBUG "sync %v/main.py %vmain.py": object is newer or same age and object size matches`, bucketPath, dst), 2: equals(`DEBUG "sync %v/readme.md %vreadme.md": object is newer or same age and object size matches`, bucketPath, dst), @@ -1103,11 +1109,14 @@ func TestSyncS3BucketToLocalFolderSameObjectsSizeOnly(t *testing.T) { result.Assert(t, icmd.Success) assertLines(t, result.Stdout(), map[int]compareFunc{ + 0: equals(`cp %v/abc/def/main.py %vabc/def/main.py`, bucketPath, dst), + 1: equals(`cp %v/test.py %vtest.py`, bucketPath, dst), + }, sortInput(true)) + + assertLines(t, result.Stderr(), map[int]compareFunc{ 0: equals(`DEBUG "sync %v/a/another_test_file.txt %va/another_test_file.txt": object size matches`, bucketPath, dst), 1: equals(`DEBUG "sync %v/readme.md %vreadme.md": object size matches`, bucketPath, dst), 2: equals(`DEBUG "sync %v/testfile.txt %vtestfile.txt": object size matches`, bucketPath, dst), - 3: equals(`cp %v/abc/def/main.py %vabc/def/main.py`, bucketPath, dst), - 4: equals(`cp %v/test.py %vtest.py`, bucketPath, dst), }, sortInput(true)) expectedFolderLayout := []fs.PathOp{ @@ -1676,11 +1685,14 @@ func TestSyncLocalFolderToS3BucketSameObjectsSizeOnly(t *testing.T) { result.Assert(t, icmd.Success) assertLines(t, result.Stdout(), map[int]compareFunc{ + 0: equals(`cp %vabc/def/main.py %vabc/def/main.py`, src, dst), + 1: equals(`cp %vtestfile.txt %vtestfile.txt`, src, dst), + }, sortInput(true)) + + assertLines(t, result.Stderr(), map[int]compareFunc{ 0: equals(`DEBUG "sync %va/another_test_file.txt %va/another_test_file.txt": object size matches`, src, dst), 1: equals(`DEBUG "sync %vreadme.md %vreadme.md": object size matches`, src, dst), 2: equals(`DEBUG "sync %vtest.py %vtest.py": object size matches`, src, dst), - 3: equals(`cp %vabc/def/main.py %vabc/def/main.py`, src, dst), - 4: equals(`cp %vtestfile.txt %vtestfile.txt`, src, dst), }, sortInput(true)) // expected folder structure without the timestamp. @@ -1751,10 +1763,13 @@ func TestSyncS3BucketToS3BucketSizeOnly(t *testing.T) { result.Assert(t, icmd.Success) assertLines(t, result.Stdout(), map[int]compareFunc{ + 0: equals(`cp %v/main.py %vmain.py`, bucketPath, dst), + }, sortInput(true)) + + assertLines(t, result.Stderr(), map[int]compareFunc{ 0: equals(`DEBUG "sync %v/a/another_test_file.txt %va/another_test_file.txt": object size matches`, bucketPath, dst), 1: equals(`DEBUG "sync %v/readme.md %vreadme.md": object size matches`, bucketPath, dst), 2: equals(`DEBUG "sync %v/testfile.txt %vtestfile.txt": object size matches`, bucketPath, dst), - 3: equals(`cp %v/main.py %vmain.py`, bucketPath, dst), }, sortInput(true)) // assert s3 objects in source