Skip to content

fix(log): send Debug and Trace output to stderr (#851) #860

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
gustcol wants to merge 2 commits into
base: master
Choose a base branch
from
Open

fix(log): send Debug and Trace output to stderr (#851) #860

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
adcb644
fix(log): send Debug and Trace output to stderr instead of stdout
gustcol Apr 12, 2026
d000f7b
test(e2e): update assertions for Debug/Trace now going to stderr
gustcol Apr 12, 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
24 changes: 12 additions & 12 deletions e2e/cp_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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))
}
Expand Down Expand Up @@ -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))
}
Expand Down Expand Up @@ -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))
Expand Down Expand Up @@ -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))
}

Expand Down
6 changes: 3 additions & 3 deletions e2e/pipe_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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))
}
Expand Down
31 changes: 23 additions & 8 deletions e2e/sync_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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),
Expand Down Expand Up @@ -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),
Expand Down Expand Up @@ -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),
Expand Down Expand Up @@ -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{
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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
Expand Down
4 changes: 2 additions & 2 deletions log/log.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
104 changes: 104 additions & 0 deletions log/log_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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)
}
}
Loading