Skip to content
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.

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

Fix no logs in stdout/stderr if uses stdoutConfig #6162

Merged
merged 1 commit into from
Mar 28, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
62 changes: 13 additions & 49 deletions cmd/entrypoint/runner.go
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,6 @@ import (
"context"
"fmt"
"io"
"log"
"os"
"os/exec"
"os/signal"
Expand Down Expand Up @@ -84,26 +83,25 @@ func (rr *realRunner) Run(ctx context.Context, args ...string) error {

cmd := exec.CommandContext(ctx, name, args...)

// Build a list of tee readers that we'll read from after the command is
// started. If we are not configured to tee stdout/stderr this will be
// empty and contents will not be copied.
var readers []*namedReader
// if a standard output file is specified
// create the log file and add to the std multi writer
if rr.stdoutPath != "" {
stdout, err := newTeeReader(cmd.StdoutPipe, rr.stdoutPath)
stdout, err := newStdLogWriter(rr.stdoutPath)
if err != nil {
return err
}
readers = append(readers, stdout)
defer stdout.Close()
cmd.Stdout = io.MultiWriter(os.Stdout, stdout)
} else {
// This needs to be set in an else since StdoutPipe will fail if cmd.Stdout is already set.
cmd.Stdout = os.Stdout
}
if rr.stderrPath != "" {
stderr, err := newTeeReader(cmd.StderrPipe, rr.stderrPath)
stderr, err := newStdLogWriter(rr.stderrPath)
if err != nil {
return err
}
readers = append(readers, stderr)
defer stderr.Close()
cmd.Stderr = io.MultiWriter(os.Stderr, stderr)
} else {
cmd.Stderr = os.Stderr
}
Expand Down Expand Up @@ -134,22 +132,6 @@ func (rr *realRunner) Run(ctx context.Context, args ...string) error {
}
}()

wg := new(sync.WaitGroup)
for _, r := range readers {
wg.Add(1)
// Read concurrently so that we can pipe stdout and stderr at the same
// time.
go func(r *namedReader) {
defer wg.Done()
if _, err := io.ReadAll(r); err != nil {
log.Printf("error reading to %s: %v", r.name, err)
}
}(r)
}

// Wait for stdout/err buffers to finish reading before returning.
wg.Wait()

// Wait for command to exit
if err := cmd.Wait(); err != nil {
if ctx.Err() == context.DeadlineExceeded {
Expand All @@ -161,19 +143,11 @@ func (rr *realRunner) Run(ctx context.Context, args ...string) error {
return nil
}

// newTeeReader creates a new Reader that copies data from the given pipe function
// (i.e. cmd.StdoutPipe, cmd.StderrPipe) into a file specified by path.
// The file is opened with os.O_WRONLY|os.O_CREATE|os.O_APPEND, and will not
// newStdLogWriter create a new file writer that used for collecting std log
// the file is opened with os.O_WRONLY|os.O_CREATE|os.O_APPEND, and will not
// override any existing content in the path. This means that the same file can
// be used for multiple streams if desired.
// The behavior of the Reader is the same as io.TeeReader - reads from the pipe
// will be written to the file.
func newTeeReader(pipe func() (io.ReadCloser, error), path string) (*namedReader, error) {
in, err := pipe()
if err != nil {
return nil, fmt.Errorf("error creating pipe: %w", err)
}

// be used for multiple streams if desired. note that close after use
Copy link
Member

Choose a reason for hiding this comment

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

Is this docstring missing after "note that close after use"?

Copy link
Member Author

Choose a reason for hiding this comment

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

It's not missing, I just modified the note here and added it to where it was used.
notes related to teaReader are no longer needed here

func newStdLogWriter(path string) (*os.File, error) {
if err := os.MkdirAll(filepath.Dir(path), os.ModePerm); err != nil {
return nil, fmt.Errorf("error creating parent directory: %w", err)
}
Expand All @@ -182,15 +156,5 @@ func newTeeReader(pipe func() (io.ReadCloser, error), path string) (*namedReader
return nil, fmt.Errorf("error opening %s: %w", path, err)
}

return &namedReader{
name: path,
Reader: io.TeeReader(in, f),
}, nil
}

// namedReader is just a helper struct that lets us give a reader a name for
// logging purposes.
type namedReader struct {
io.Reader
name string
return f, nil
}
40 changes: 40 additions & 0 deletions cmd/entrypoint/runner_test.go
Original file line number Diff line number Diff line change
@@ -1,9 +1,11 @@
package main

import (
"bytes"
"context"
"errors"
"fmt"
"io"
"os"
"path/filepath"
"strings"
Expand Down Expand Up @@ -39,10 +41,48 @@ func TestRealRunnerStdoutAndStderrPaths(t *testing.T) {
stdoutPath: filepath.Join(tmp, "stdout"),
stderrPath: filepath.Join(tmp, "subpath/stderr"),
}

// capture the std{out/err} output to verify whether we print log in the std
oldStdout := os.Stdout // keep backup of the real stdout
outReader, outWriter, _ := os.Pipe()
os.Stdout = outWriter

oldStderr := os.Stderr
errReader, errWriter, _ := os.Pipe()
os.Stderr = errWriter
Comment on lines +46 to +52
Copy link
Member

Choose a reason for hiding this comment

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

This seems brittle since it modifies global state.

How about we:

  1. Modify realRunner to take in io.Writers
  2. Have main.go initialize the multiwriters if the flag is set.
  3. If the writers are nil, default to os.Stdout/Stderr

This way in tests we can just use a buffer and remove a bunch of the path manipulation?

Copy link
Member Author

Choose a reason for hiding this comment

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

The test here is to verify that logs can be printed to standard output. If you modify realRunner to accept io.Writers, you need to pass in os.stdout, which is the same as the current situation.


if err := rr.Run(context.Background(), "sh", "-c", fmt.Sprintf("echo %s && echo %s >&2", expectedString, expectedString)); err != nil {
t.Fatalf("Unexpected error: %v", err)
}

outC := make(chan string)
errC := make(chan string)
// copy the output in a separate goroutine so realRunner command can't block indefinitely
go func() {
var stdOutBuf bytes.Buffer
io.Copy(&stdOutBuf, outReader)
outC <- stdOutBuf.String()

var stdErrBuf bytes.Buffer
io.Copy(&stdErrBuf, errReader)
errC <- stdErrBuf.String()
}()
// back to normal state
outWriter.Close()
errWriter.Close()
os.Stdout = oldStdout // restoring the real stdout
os.Stderr = oldStderr // restoring the real stderr
stdOut := <-outC
stdErr := <-errC

// echo command will auto add \n in end, so we should remove trailing newline
if strings.TrimSuffix(stdOut, "\n") != expectedString {
t.Fatalf("Unexpected stdout output: %s, wanted stdout output: %s", stdOut, expectedString)
}
if strings.TrimSuffix(stdErr, "\n") != expectedString {
t.Fatalf("Unexpected stderr output: %s, wanted stderr output: %s", stdErr, expectedString)
}

for _, path := range []string{"stdout", "subpath/stderr"} {
if got, err := os.ReadFile(filepath.Join(tmp, path)); err != nil {
t.Fatalf("Unexpected error: %v", err)
Expand Down