cleanup logging

Signed-off-by: Casey Lee <cplee@nektos.com>

.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

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=

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) {

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
 		}

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() {
+		out := os.Stdout
-		<-ctx.Done()
+		go func() {
-		fmt.Println()
+			<-ctx.Done()
-	}()
+			//fmt.Println()
+		}()
 
-	_, err := io.Copy(out, dockerResponse)
+		_, err := io.Copy(out, dockerResponse)
-	if err != nil {
+		if err != nil {
-		logrus.Error(err)
+			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 {

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

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)
+		var outWriter io.Writer
-		} else {
+		outWriter = cr.input.Stdout
-			go streamDockerOutput(ctx, out.Reader)
+		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)

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)

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
+	red     = 31
-	green  = 32
+	green   = 32
-	yellow = 33
+	yellow  = 33
-	blue   = 36
+	blue    = 34
-	gray   = 37
+	magenta = 35
+	cyan    = 36
+	gray    = 37
 )
 
-// NewJobLogger gets the logger for the Job
+var colors []int
-func NewJobLogger(jobName string, dryrun bool) logrus.FieldLogger {
+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})
+	rtn := logger.WithFields(logrus.Fields{"job": jobName, "dryrun": common.Dryrun(ctx)})
-	return rtn
+
+	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) {
+func (f *stepLogFormatter) 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
-	}
-
 	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)
 

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

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

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()

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