From 033168228b64cb984a8cc63500cc135847ccd79a Mon Sep 17 00:00:00 2001 From: Casey Lee Date: Tue, 11 Feb 2020 09:10:35 -0800 Subject: [PATCH] cleanup logging Signed-off-by: Casey Lee --- .github/workflows/tag.yml | 1 + go.sum | 2 + pkg/common/git.go | 2 +- pkg/container/docker_build.go | 2 +- pkg/container/docker_logger.go | 37 ++++++++++---- pkg/container/docker_pull.go | 2 +- pkg/container/docker_run.go | 30 ++++++++--- pkg/model/workflow.go | 12 +++++ pkg/runner/logger.go | 71 +++++++++++++++------------ pkg/runner/run_context.go | 27 +++++++++- pkg/runner/runner.go | 6 ++- pkg/runner/step.go | 16 +++++- pkg/runner/testdata/parallel/push.yml | 29 +++++++++++ 13 files changed, 183 insertions(+), 54 deletions(-) create mode 100644 pkg/runner/testdata/parallel/push.yml diff --git a/.github/workflows/tag.yml b/.github/workflows/tag.yml index 98dbffb..abb2ec6 100644 --- a/.github/workflows/tag.yml +++ b/.github/workflows/tag.yml @@ -8,6 +8,7 @@ jobs: release: runs-on: ubuntu-latest steps: + - uses: actions/checkout@v2 - uses: ./.github/workflows/check - uses: ./.github/workflows/integration - uses: goreleaser/goreleaser-action@v1 diff --git a/go.sum b/go.sum index 4727646..fca5e4f 100644 --- a/go.sum +++ b/go.sum @@ -21,6 +21,7 @@ github.com/docker/distribution v2.7.1+incompatible h1:a5mlkVzth6W5A4fOsS3D2EO5BU github.com/docker/distribution v2.7.1+incompatible/go.mod h1:J2gT2udsDAN96Uj4KfcMRqY0/ypR+oyYUYmja8H+y+w= github.com/docker/engine v0.0.0-20181106193140-f5749085e9cb h1:PyjxRdW1mqCmSoxy/6uP01P7CGbsD+woX+oOWbaUPwQ= github.com/docker/engine v0.0.0-20181106193140-f5749085e9cb/go.mod h1:3CPr2caMgTHxxIAZgEMd3uLYPDlRvPqCpyeRf6ncPcY= +github.com/docker/engine v1.13.1 h1:Cks33UT9YBW5Xyc3MtGDq2IPgqfJtJ+qkFaxc2b0Euc= github.com/docker/go-connections v0.4.0 h1:El9xVISelRB7BuFusrZozjnkIM5YnzCViNKohAFqRJQ= github.com/docker/go-connections v0.4.0/go.mod h1:Gbd7IOopHjR8Iph03tsViu4nIes5XhDvyHbTtUxmeec= github.com/docker/go-units v0.3.3 h1:Xk8S3Xj5sLGlG5g67hJmYMmUgXv5N4PhkjJHHqrwnTk= @@ -115,6 +116,7 @@ golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnf golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/crypto v0.0.0-20191202143827-86a70503ff7e h1:egKlR8l7Nu9vHGWbcUV8lqR4987UfUbBd7GbhqGzNYU= golang.org/x/crypto v0.0.0-20191202143827-86a70503ff7e/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto= +golang.org/x/crypto v0.0.0-20200210222208-86ce3cb69678 h1:wCWoJcFExDgyYx2m2hpHgwz8W3+FPdfldvIgzqDIhyg= golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= golang.org/x/lint v0.0.0-20180702182130-06c8688daad7/go.mod h1:UVdnD1Gm6xHRNCYTkRU2/jEulfH38KcIWyp/GAMgvoE= golang.org/x/lint v0.0.0-20181026193005-c67002cb31c3/go.mod h1:UVdnD1Gm6xHRNCYTkRU2/jEulfH38KcIWyp/GAMgvoE= diff --git a/pkg/common/git.go b/pkg/common/git.go index f50a832..c20746d 100644 --- a/pkg/common/git.go +++ b/pkg/common/git.go @@ -192,7 +192,7 @@ type NewGitCloneExecutorInput struct { func NewGitCloneExecutor(input NewGitCloneExecutorInput) Executor { return func(ctx context.Context) error { logger := Logger(ctx) - logger.Infof("git clone '%s' # ref=%s", input.URL, input.Ref) + logger.Infof(" \u2601 git clone '%s' # ref=%s", input.URL, input.Ref) logger.Debugf(" cloning %s to %s", input.URL, input.Dir) if Dryrun(ctx) { diff --git a/pkg/container/docker_build.go b/pkg/container/docker_build.go index 05fce6e..c108da7 100644 --- a/pkg/container/docker_build.go +++ b/pkg/container/docker_build.go @@ -25,7 +25,7 @@ type NewDockerBuildExecutorInput struct { func NewDockerBuildExecutor(input NewDockerBuildExecutorInput) common.Executor { return func(ctx context.Context) error { logger := common.Logger(ctx) - logger.Infof("docker build -t %s %s", input.ImageTag, input.ContextDir) + logger.Infof("%sdocker build -t %s %s", logPrefix, input.ImageTag, input.ContextDir) if common.Dryrun(ctx) { return nil } diff --git a/pkg/container/docker_logger.go b/pkg/container/docker_logger.go index 8a27d41..c47d220 100644 --- a/pkg/container/docker_logger.go +++ b/pkg/container/docker_logger.go @@ -5,9 +5,7 @@ import ( "context" "encoding/json" "errors" - "fmt" "io" - "os" "github.com/nektos/act/pkg/common" "github.com/sirupsen/logrus" @@ -26,6 +24,8 @@ type dockerMessage struct { Progress string `json:"progress"` } +const logPrefix = " \U0001F433 " + func logDockerOutput(ctx context.Context, dockerResponse io.Reader) { logger := common.Logger(ctx) if entry, ok := logger.(*logrus.Entry); ok { @@ -46,16 +46,33 @@ func logDockerOutput(ctx context.Context, dockerResponse io.Reader) { } func streamDockerOutput(ctx context.Context, dockerResponse io.Reader) { - out := os.Stdout - go func() { - <-ctx.Done() - fmt.Println() - }() + /* + out := os.Stdout + go func() { + <-ctx.Done() + //fmt.Println() + }() - _, err := io.Copy(out, dockerResponse) - if err != nil { - logrus.Error(err) + _, err := io.Copy(out, dockerResponse) + if err != nil { + logrus.Error(err) + } + */ + + logger := common.Logger(ctx) + reader := bufio.NewReader(dockerResponse) + + for { + if ctx.Err() != nil { + break + } + line, _, err := reader.ReadLine() + if err == io.EOF { + break + } + logger.Debugf("%s\n", line) } + } func logDockerResponse(logger logrus.FieldLogger, dockerResponse io.ReadCloser, isError bool) error { diff --git a/pkg/container/docker_pull.go b/pkg/container/docker_pull.go index 4e1e5fe..7aa9b89 100644 --- a/pkg/container/docker_pull.go +++ b/pkg/container/docker_pull.go @@ -21,7 +21,7 @@ type NewDockerPullExecutorInput struct { func NewDockerPullExecutor(input NewDockerPullExecutorInput) common.Executor { return func(ctx context.Context) error { logger := common.Logger(ctx) - logger.Infof("docker pull %v", input.Image) + logger.Infof("%sdocker pull %v", logPrefix, input.Image) if common.Dryrun(ctx) { return nil diff --git a/pkg/container/docker_run.go b/pkg/container/docker_run.go index acf7180..b54ab87 100644 --- a/pkg/container/docker_run.go +++ b/pkg/container/docker_run.go @@ -9,6 +9,7 @@ import ( "github.com/docker/docker/api/types" "github.com/docker/docker/api/types/container" "github.com/docker/docker/client" + "github.com/docker/docker/pkg/stdcopy" "github.com/nektos/act/pkg/common" "github.com/pkg/errors" "golang.org/x/crypto/ssh/terminal" @@ -26,6 +27,8 @@ type NewDockerRunExecutorInput struct { Volumes []string Name string ReuseContainers bool + Stdout io.Writer + Stderr io.Writer } // NewDockerRunExecutor function to create a run executor for the container @@ -34,7 +37,7 @@ func NewDockerRunExecutor(input NewDockerRunExecutorInput) common.Executor { cr.input = input return common. - NewInfoExecutor("docker run image=%s entrypoint=%+q cmd=%+q", input.Image, input.Entrypoint, input.Cmd). + NewInfoExecutor("%sdocker run image=%s entrypoint=%+q cmd=%+q", logPrefix, input.Image, input.Entrypoint, input.Cmd). Then( common.NewPipelineExecutor( cr.connect(), @@ -177,11 +180,26 @@ func (cr *containerReference) attach() common.Executor { return errors.WithStack(err) } isTerminal := terminal.IsTerminal(int(os.Stdout.Fd())) - if !isTerminal || os.Getenv("NORAW") != "" { - go logDockerOutput(ctx, out.Reader) - } else { - go streamDockerOutput(ctx, out.Reader) + + var outWriter io.Writer + outWriter = cr.input.Stdout + if outWriter == nil { + outWriter = os.Stdout } + errWriter := cr.input.Stderr + if errWriter == nil { + errWriter = os.Stderr + } + go func() { + if !isTerminal || os.Getenv("NORAW") != "" { + _, err = stdcopy.StdCopy(outWriter, errWriter, out.Reader) + } else { + _, err = io.Copy(outWriter, out.Reader) + } + if err != nil { + common.Logger(ctx).Error(err) + } + }() return nil } } @@ -218,8 +236,6 @@ func (cr *containerReference) wait() common.Executor { if statusCode == 0 { return nil - } else if statusCode == 78 { - return fmt.Errorf("exit with `NEUTRAL`: 78") } return fmt.Errorf("exit with `FAILURE`: %v", statusCode) diff --git a/pkg/model/workflow.go b/pkg/model/workflow.go index df1df8b..da957eb 100644 --- a/pkg/model/workflow.go +++ b/pkg/model/workflow.go @@ -113,6 +113,18 @@ type Step struct { TimeoutMinutes int64 `yaml:"timeout-minutes"` } +// String gets the name of step +func (s *Step) String() string { + if s.Name != "" { + return s.Name + } else if s.Uses != "" { + return s.Uses + } else if s.Run != "" { + return s.Run + } + return s.ID +} + // GetEnv gets the env for a step func (s *Step) GetEnv() map[string]string { rtnEnv := make(map[string]string) diff --git a/pkg/runner/logger.go b/pkg/runner/logger.go index b36b9b9..50b077a 100644 --- a/pkg/runner/logger.go +++ b/pkg/runner/logger.go @@ -2,38 +2,59 @@ package runner import ( "bytes" + "context" "fmt" "io" "os" "strings" + "github.com/nektos/act/pkg/common" + "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh/terminal" ) const ( //nocolor = 0 - red = 31 - green = 32 - yellow = 33 - blue = 36 - gray = 37 + red = 31 + green = 32 + yellow = 33 + blue = 34 + magenta = 35 + cyan = 36 + gray = 37 ) -// NewJobLogger gets the logger for the Job -func NewJobLogger(jobName string, dryrun bool) logrus.FieldLogger { +var colors []int +var nextColor int + +func init() { + nextColor = 0 + colors = []int{ + blue, yellow, green, magenta, red, gray, cyan, + } +} + +// WithJobLogger attaches a new logger to context that is aware of steps +func WithJobLogger(ctx context.Context, jobName string) context.Context { + formatter := new(stepLogFormatter) + formatter.color = colors[nextColor%len(colors)] + nextColor = nextColor + 1 + logger := logrus.New() - logger.SetFormatter(new(jobLogFormatter)) + logger.SetFormatter(formatter) logger.SetOutput(os.Stdout) logger.SetLevel(logrus.GetLevel()) - rtn := logger.WithFields(logrus.Fields{"job_name": jobName, "dryrun": dryrun}) - return rtn + rtn := logger.WithFields(logrus.Fields{"job": jobName, "dryrun": common.Dryrun(ctx)}) + + return common.WithLogger(ctx, rtn) } -type jobLogFormatter struct { +type stepLogFormatter struct { + color int } -func (f *jobLogFormatter) Format(entry *logrus.Entry) ([]byte, error) { +func (f *stepLogFormatter) Format(entry *logrus.Entry) ([]byte, error) { b := &bytes.Buffer{} if f.isColored(entry) { @@ -46,32 +67,20 @@ func (f *jobLogFormatter) Format(entry *logrus.Entry) ([]byte, error) { return b.Bytes(), nil } -func (f *jobLogFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry) { - var levelColor int - switch entry.Level { - case logrus.DebugLevel, logrus.TraceLevel: - levelColor = gray - case logrus.WarnLevel: - levelColor = yellow - case logrus.ErrorLevel, logrus.FatalLevel, logrus.PanicLevel: - levelColor = red - default: - levelColor = blue - } - +func (f *stepLogFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry) { entry.Message = strings.TrimSuffix(entry.Message, "\n") - jobName := entry.Data["job_name"] + jobName := entry.Data["job"] if entry.Data["dryrun"] == true { - fmt.Fprintf(b, "\x1b[%dm*DRYRUN* \x1b[%dm[%s] \x1b[0m%s", green, levelColor, jobName, entry.Message) + fmt.Fprintf(b, "\x1b[1m\x1b[%dm\x1b[7m*DRYRUN*\x1b[0m \x1b[%dm[%s] \x1b[0m%s", gray, f.color, jobName, entry.Message) } else { - fmt.Fprintf(b, "\x1b[%dm[%s] \x1b[0m%s", levelColor, jobName, entry.Message) + fmt.Fprintf(b, "\x1b[%dm[%s] \x1b[0m%s", f.color, jobName, entry.Message) } } -func (f *jobLogFormatter) print(b *bytes.Buffer, entry *logrus.Entry) { +func (f *stepLogFormatter) print(b *bytes.Buffer, entry *logrus.Entry) { entry.Message = strings.TrimSuffix(entry.Message, "\n") - jobName := entry.Data["job_name"] + jobName := entry.Data["job"] if entry.Data["dryrun"] == true { fmt.Fprintf(b, "*DRYRUN* [%s] %s", jobName, entry.Message) @@ -80,7 +89,7 @@ func (f *jobLogFormatter) print(b *bytes.Buffer, entry *logrus.Entry) { } } -func (f *jobLogFormatter) isColored(entry *logrus.Entry) bool { +func (f *stepLogFormatter) isColored(entry *logrus.Entry) bool { isColored := checkIfTerminal(entry.Logger.Out) diff --git a/pkg/runner/run_context.go b/pkg/runner/run_context.go index 81a0c71..8131270 100644 --- a/pkg/runner/run_context.go +++ b/pkg/runner/run_context.go @@ -55,7 +55,19 @@ func (rc *RunContext) Executor() common.Executor { if step.ID == "" { step.ID = fmt.Sprintf("%d", i) } - steps = append(steps, rc.newStepExecutor(step)) + s := step + steps = append(steps, func(ctx context.Context) error { + //common.Logger(ctx).Infof("\U0001F680 Begin %s", step) + //common.Logger(ctx).Infof("\u2728 Begin - %s", step) + common.Logger(ctx).Infof("\u2B50 Begin - %s", s) + err := rc.newStepExecutor(s)(ctx) + if err == nil { + common.Logger(ctx).Infof(" \u2705 Success - %s", s) + } else { + common.Logger(ctx).Errorf(" \u274C Failure - %s", s) + } + return err + }) } return common.NewPipelineExecutor(steps...).Finally(rc.Close) } @@ -116,6 +128,17 @@ func (rc *RunContext) runContainer(containerSpec *model.ContainerSpec) common.Ex entrypoint = strings.Fields(containerSpec.Entrypoint) } + var logWriter io.Writer + logger := common.Logger(ctx) + if entry, ok := logger.(*log.Entry); ok { + logWriter = entry.Writer() + } else if lgr, ok := logger.(*log.Logger); ok { + logWriter = lgr.Writer() + } else { + logger.Errorf("Unable to get writer from logger (type=%T)", logger) + } + logWriter = os.Stdout + return container.NewDockerRunExecutor(container.NewDockerRunExecutorInput{ Cmd: cmd, Entrypoint: entrypoint, @@ -130,6 +153,8 @@ func (rc *RunContext) runContainer(containerSpec *model.ContainerSpec) common.Ex }, Content: map[string]io.Reader{"/github": ghReader}, ReuseContainers: rc.Config.ReuseContainers, + Stdout: logWriter, + Stderr: logWriter, })(ctx) } } diff --git a/pkg/runner/runner.go b/pkg/runner/runner.go index 45f60be..5cde3f1 100644 --- a/pkg/runner/runner.go +++ b/pkg/runner/runner.go @@ -1,6 +1,7 @@ package runner import ( + "context" "io/ioutil" "github.com/nektos/act/pkg/common" @@ -64,5 +65,8 @@ func (runner *runnerImpl) NewRunExecutor(run *model.Run) common.Executor { rc.Config = runner.config rc.Run = run rc.EventJSON = runner.eventJSON - return rc.Executor() + return func(ctx context.Context) error { + ctx = WithJobLogger(ctx, rc.Run.String()) + return rc.Executor()(ctx) + } } diff --git a/pkg/runner/step.go b/pkg/runner/step.go index f2d5bee..f5fd8f1 100644 --- a/pkg/runner/step.go +++ b/pkg/runner/step.go @@ -50,6 +50,7 @@ func (rc *RunContext) newStepExecutor(step *model.Step) common.Executor { containerSpec.Image = fmt.Sprintf("%s:%s", containerSpec.Name, "latest") return common.NewPipelineExecutor( rc.setupAction(containerSpec, filepath.Join(rc.Config.Workdir, step.Uses)), + applyWith(containerSpec, step), rc.pullImage(containerSpec), rc.runContainer(containerSpec), ) @@ -73,6 +74,7 @@ func (rc *RunContext) newStepExecutor(step *model.Step) common.Executor { Dir: cloneDir, }), rc.setupAction(containerSpec, filepath.Join(cloneDir, remoteAction.Path)), + applyWith(containerSpec, step), rc.pullImage(containerSpec), rc.runContainer(containerSpec), ) @@ -81,6 +83,18 @@ func (rc *RunContext) newStepExecutor(step *model.Step) common.Executor { return common.NewErrorExecutor(fmt.Errorf("Unable to determine how to run job:%s step:%+v", rc.Run, step)) } +func applyWith(containerSpec *model.ContainerSpec, step *model.Step) common.Executor { + return func(ctx context.Context) error { + if entrypoint, ok := step.With["entrypoint"]; ok { + containerSpec.Entrypoint = entrypoint + } + if args, ok := step.With["args"]; ok { + containerSpec.Args = args + } + return nil + } +} + // StepEnv returns the env for a step func (rc *RunContext) StepEnv(step *model.Step) map[string]string { env := make(map[string]string) @@ -113,7 +127,7 @@ func (rc *RunContext) StepEnv(step *model.Step) map[string]string { if err != nil { log.Warningf("unable to get git ref: %v", err) } else { - log.Infof("using github ref: %s", ref) + log.Debugf("using github ref: %s", ref) env["GITHUB_REF"] = ref } job := rc.Run.Job() diff --git a/pkg/runner/testdata/parallel/push.yml b/pkg/runner/testdata/parallel/push.yml new file mode 100644 index 0000000..71ad27f --- /dev/null +++ b/pkg/runner/testdata/parallel/push.yml @@ -0,0 +1,29 @@ +name: basic +on: push + +jobs: + build: + runs-on: ubuntu-latest + steps: + - uses: ./actions/action1 + with: + args: echo 'build' + - uses: actions/hello-world-javascript-action@master + with: + who-to-greet: 'Mona the Octocat' + test1: + runs-on: ubuntu-latest + needs: [build] + steps: + - uses: docker://ubuntu:18.04 + with: + args: echo ${GITHUB_REF} | grep nektos/act + - uses: ./actions/docker-url + with: + args: npm install angular-cli + test2: + runs-on: ubuntu-latest + needs: [build] + steps: + - run: echo hello + - run: echo world