add better unit test for combind logging

engine/convert.go

@@ -33,9 +33,9 @@ func toSpec(spec *Spec, step *Step) *specgen.SpecGenerator {
 	}
 
 	volume := specgen.ContainerStorageConfig{
-		Image:   step.Image,
+		WorkDir:          step.WorkingDir,
-		WorkDir: step.WorkingDir,
+		CreateWorkingDir: true,
-		ShmSize: toPtr(step.ShmSize),
+		ShmSize:          toPtr(step.ShmSize),
 	}
 
 	volumeSet := toVolumeSet(spec, step)
@@ -109,7 +109,7 @@ func toSpec(spec *Spec, step *Step) *specgen.SpecGenerator {
 		ContainerResourceConfig: resource,
 	}
 
-	logrus.Debugf("creating [config=%+v]", config)
+	logrus.Tracef("creating [config=%+v]", config)
 	return config
 }
 

engine/engine.go

@@ -238,12 +238,21 @@ func (e *Podman) Run(ctx context.Context, specv runtime.Spec, stepv runtime.Step
 		}
 		defer logs.Close()
 	} else {
+		var buf bytes.Buffer
+		multiWriter := io.MultiWriter(output, &buf)
+
 		logger.FromContext(ctx).Tracef("tail logging...")
-		err = e.tail(ctx, step.ID, output)
+		err = e.tail(ctx, step.ID, multiWriter)
 		if err != nil {
+			logger.FromContext(ctx).
+				WithError(err).
+				Errorf("failed to tail logs")
 			return nil, errors.TrimExtraInfo(err)
 		}
+
+		logger.FromContext(ctx).Debugf("[tail_logs=%s]", buf.String())
 	}
+
 	// wait for the response
 	return e.waitRetry(ctx, step.ID)
 }
@@ -408,17 +417,17 @@ func (e *Podman) tail(ctx context.Context, id string, output io.Writer) error {
 		Timestamps: toPtr(false),
 	}
 
-	out := make(chan string, 100)
+	out := make(chan string, 1000)
-	error := make(chan string, 100)
+	error := make(chan string, 1000)
 
 	err := containers.Logs(e.conn, id, &opts, out, error)
 	if err != nil {
 		return err
 	}
+	logs := NewChansReadClose(ctx, out, error)
 
 	logger.FromContext(ctx).Debugf("starting log goroutine [id=%s]...", id)
 	go func() {
-		logs := NewChansReadClose(ctx, out, error)
 		io.Copy(output, logs)
 		logs.Close()
 	}()

engine/spec.go

@@ -5,6 +5,8 @@
 package engine
 
 import (
+	"fmt"
+
 	"github.com/drone/runner-go/environ"
 	"github.com/drone/runner-go/pipeline/runtime"
 )
@@ -137,6 +139,17 @@ type (
 
 func (s *Spec) StepLen() int              { return len(s.Steps) }
 func (s *Spec) StepAt(i int) runtime.Step { return s.Steps[i] }
+func (s *Spec) String() string {
+	return fmt.Sprintf(`{
+	Platform: %+v
+	Steps: %+v
+	Internal: %+v
+	Volumes: %+v
+	Network: %+v
+}`, s.Platform, s.Steps, s.Internal,
+		s.Volumes, s.Network,
+	)
+}
 
 //
 // implements the Secret interface
@@ -166,3 +179,48 @@ func (s *Step) Clone() runtime.Step {
 	dst.Envs = environ.Combine(s.Envs)
 	return dst
 }
+func (s *Step) String() string {
+	return fmt.Sprintf(`{
+		ID: %s
+		Auth: %+v
+		Command: %+v
+		CPUPeriod: %d
+		CPUQuota: %d
+		CPUShares: %d
+		CPUSet: %+v
+		Detach: %t
+		DependsOn: %+v
+		Devices: %+v
+		DNS: %+v
+		DNSSearch: %+v
+		Entrypoint: %+v
+		Envs: %+v
+		ErrPolicy: %+v
+		ExtraHosts: %+v
+		IgnoreStdout: %t
+		IgnoreStderr: %t
+		Image: %s
+		Labels: %+v
+		MemSwapLimit: %d
+		MemLimit: %d
+		Name: %s
+		Network: %s
+		Networks: %+v
+		Privileged: %t
+		Pull: %+v
+		RunPolicy: %+v
+		Secrets: %+v
+		ShmSize: %d
+		User: %s
+		Volumes: %+v
+		WorkingDir: %s
+	}`, s.ID, s.Auth, s.Command, s.CPUPeriod,
+		s.CPUQuota, s.CPUShares, s.CPUSet, s.Detach,
+		s.DependsOn, s.Devices, s.DNS, s.DNSSearch,
+		s.Entrypoint, s.Envs, s.ErrPolicy, s.ExtraHosts,
+		s.IgnoreStdout, s.IgnoreStderr, s.Image, s.Labels,
+		s.MemSwapLimit, s.MemLimit, s.Name, s.Network,
+		s.Networks, s.Privileged, s.Pull, s.RunPolicy,
+		s.Secrets, s.ShmSize, s.User, s.Volumes, s.WorkingDir,
+	)
+}

engine/util.go

@@ -67,6 +67,7 @@ func (c *ReaderClose) Read(p []byte) (n int, err error) {
 		}
 
 		n += copy(p, []byte(value.String()))
+		return n, nil
 	}
 
 	return n, io.EOF

engine/util_test.go

@@ -7,21 +7,24 @@ package engine
 import (
 	"bytes"
 	"context"
-	"fmt"
 	"io"
+	"strconv"
+	"strings"
 	"testing"
 	"time"
+
+	"github.com/sirupsen/logrus"
 )
 
 func TestChansToReader(t *testing.T) {
 	ctx := context.Background()
 
 	stdout := make(chan string, 1000)
+	stderr := make(chan string, 1000)
 
-	logs := NewChansReadClose(ctx, stdout)
+	logs := NewChansReadClose(ctx, stdout, stderr)
 
 	mockLogs := []string{
-		"\u0008",
 		"this is a log 1\n",
 		"this is a log 2\n",
 		"this is a log 3\n",
@@ -38,17 +41,71 @@ func TestChansToReader(t *testing.T) {
 
 	go func(mock []string) {
 		for i := range mock {
-			time.Sleep(2)
+			time.Sleep(500 * time.Millisecond)
-			fmt.Printf("sending [mock=%s]\n", mock[i])
+			if i%3 == 0 {
-			stdout <- mock[i]
+				stderr <- "err " + mock[i]
+				continue
+			}
+
+			stdout <- "out " + mock[i]
 		}
-		fmt.Println("closing channel...")
 		logs.Close()
 	}(mockLogs)
 
-	fmt.Println("starting std copy...")
 	output := bytes.NewBuffer([]byte{})
-	io.Copy(output, logs)
+	n, err := io.Copy(output, logs)
+	if err != nil {
+		logrus.Errorf("failed to copy reader to ouput [error=%s]", err.Error())
+		t.Fail()
+	}
 
-	fmt.Print(output.String())
+	logrus.Infof("[bytes=%d] [logs=%s]\n",
+		n, output.String(),
+	)
+	splitResult := strings.Split(output.String(), "\n")
+	for i := range mockLogs {
+		if i%3 == 0 {
+			if !checkStrErr(i, splitResult[i]) {
+				logrus.Errorf("logs do not match\n\t[expect=%s]\n\t[got=%s]",
+					"err "+mockLogs[i], splitResult[i],
+				)
+				t.Fail()
+			}
+			continue
+		}
+
+		if !checkStrOut(i, splitResult[i]) {
+			logrus.Errorf("logs do not match\n\t[expect=%s]\n\t[got=%s]",
+				"out "+mockLogs[i], splitResult[i],
+			)
+			t.Fail()
+		}
+	}
+}
+
+func checkStrErr(line int, strerr string) bool {
+	if strerr[:3] != "err" {
+		return false
+	}
+
+	return checkStr(line, strerr)
+}
+
+func checkStrOut(line int, strout string) bool {
+	if strout[:3] != "out" {
+		return false
+	}
+
+	return checkStr(line, strout)
+}
+
+func checkStr(line int, str string) bool {
+	split := strings.Split(str, " ")
+
+	n, err := strconv.Atoi(split[len(split)-1])
+	if err != nil {
+		panic(err)
+	}
+
+	return line+1 == n
 }