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 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) + } +}