driver: add logging support to bootstrap

Signed-off-by: Tonis Tiigi <tonistiigi@gmail.com>

build/build.go

@@ -3,19 +3,17 @@ package build
 import (
 	"context"
 	"io"
-	"os"
 	"path/filepath"
 	"strconv"
 	"strings"
 
-	"github.com/containerd/console"
 	"github.com/containerd/containerd/platforms"
 	"github.com/moby/buildkit/client"
 	"github.com/moby/buildkit/session"
-	"github.com/moby/buildkit/util/progress/progressui"
 	specs "github.com/opencontainers/image-spec/specs-go/v1"
 	"github.com/pkg/errors"
 	"github.com/tonistiigi/buildx/driver"
+	"github.com/tonistiigi/buildx/util/progress"
 	"golang.org/x/sync/errgroup"
 )
 
@@ -41,7 +39,7 @@ type Inputs struct {
 	InStream       io.Reader
 }
 
-func Build(ctx context.Context, drivers []driver.Driver, opt Options, pw *ProgressWriter) (*client.SolveResponse, error) {
+func Build(ctx context.Context, drivers []driver.Driver, opt Options, pw progress.Writer) (*client.SolveResponse, error) {
 	if len(drivers) == 0 {
 		return nil, errors.Errorf("driver required for build")
 	}
@@ -50,8 +48,11 @@ func Build(ctx context.Context, drivers []driver.Driver, opt Options, pw *Progre
 		return nil, errors.Errorf("multiple drivers currently not supported")
 	}
 
-	c, err := driver.Boot(ctx, drivers[0], pw.Status())
+	pwOld := pw
+	c, pw, err := driver.Boot(ctx, drivers[0], pw)
 	if err != nil {
+		close(pwOld.Status())
+		<-pwOld.Done()
 		return nil, err
 	}
 
@@ -141,48 +142,6 @@ func Build(ctx context.Context, drivers []driver.Driver, opt Options, pw *Progre
 	return resp, nil
 }
 
-type ProgressWriter struct {
-	status chan *client.SolveStatus
-	done   <-chan struct{}
-	err    error
-}
-
-func (pw *ProgressWriter) Done() <-chan struct{} {
-	return pw.done
-}
-
-func (pw *ProgressWriter) Err() error {
-	return pw.err
-}
-
-func (pw *ProgressWriter) Status() chan *client.SolveStatus {
-	if pw == nil {
-		return nil
-	}
-	return pw.status
-}
-
-func NewProgressWriter(ctx context.Context, out *os.File, mode string) *ProgressWriter {
-	statusCh := make(chan *client.SolveStatus)
-	doneCh := make(chan struct{})
-
-	pw := &ProgressWriter{
-		status: statusCh,
-		done:   doneCh,
-	}
-
-	go func() {
-		var c console.Console
-		if cons, err := console.ConsoleFromFile(out); err == nil && (mode == "auto" || mode == "tty") {
-			c = cons
-		}
-		// not using shared context to not disrupt display but let is finish reporting errors
-		pw.err = progressui.DisplaySolveStatus(ctx, "", c, out, statusCh)
-		close(doneCh)
-	}()
-	return pw
-}
-
 func LoadInputs(inp Inputs, target *client.SolveOpt) error {
 	if inp.ContextPath == "" {
 		return errors.New("please specify build context (e.g. \".\" for the current directory)")

commands/build.go

@@ -12,6 +12,7 @@ import (
 	"github.com/spf13/cobra"
 	"github.com/tonistiigi/buildx/build"
 	"github.com/tonistiigi/buildx/driver"
+	"github.com/tonistiigi/buildx/util/progress"
 )
 
 type buildOptions struct {
@@ -100,7 +101,7 @@ func runBuild(dockerCli command.Cli, in buildOptions) error {
 
 	ctx2, cancel := context.WithCancel(context.TODO())
 	defer cancel()
-	pw := build.NewProgressWriter(ctx2, os.Stderr, in.progress)
+	pw := progress.NewPrinter(ctx2, os.Stderr, in.progress)
 
 	_, err = build.Build(ctx, []driver.Driver{d}, opts, pw)
 

driver/docker/driver.go

@@ -13,6 +13,7 @@ import (
 	"github.com/moby/buildkit/client"
 	"github.com/pkg/errors"
 	"github.com/tonistiigi/buildx/driver"
+	"github.com/tonistiigi/buildx/util/progress"
 )
 
 type Driver struct {
@@ -20,41 +21,50 @@ type Driver struct {
 	version dockertypes.Version
 }
 
-func (d *Driver) Bootstrap(ctx context.Context, l driver.Logger) error {
+func (d *Driver) Bootstrap(ctx context.Context, l progress.Logger) error {
-	_, err := d.DockerAPI.ContainerInspect(ctx, d.Name)
+	return progress.Wrap("[internal] booting buildkit", l, func(sub progress.SubLogger) error {
-	if err != nil {
+		_, err := d.DockerAPI.ContainerInspect(ctx, d.Name)
-		if dockerclient.IsErrNotFound(err) {
+		if err != nil {
-			return d.create(ctx, l)
+			if dockerclient.IsErrNotFound(err) {
+				return d.create(ctx, sub)
+			}
+			return err
 		}
-		return err
+		return d.start(ctx, sub)
-	}
+	})
-	return d.start(ctx, l)
 }
 
-func (d *Driver) create(ctx context.Context, l driver.Logger) error {
+func (d *Driver) create(ctx context.Context, l progress.SubLogger) error {
-	rc, err := d.DockerAPI.ImageCreate(ctx, "moby/buildkit", types.ImageCreateOptions{})
+	if err := l.Wrap("pulling image moby/buildkit", func() error {
-	if err != nil {
+		rc, err := d.DockerAPI.ImageCreate(ctx, "moby/buildkit", types.ImageCreateOptions{})
+		if err != nil {
+			return err
+		}
+		_, err = io.Copy(ioutil.Discard, rc)
+		return err
+	}); err != nil {
 		return err
 	}
-	_, err = io.Copy(ioutil.Discard, rc)
+	if err := l.Wrap("creating container "+d.Name, func() error {
-	if err != nil {
+		_, err := d.DockerAPI.ContainerCreate(ctx, &container.Config{
-		return err
+			Image: "moby/buildkit",
-	}
+		}, &container.HostConfig{
-	_, err = d.DockerAPI.ContainerCreate(ctx, &container.Config{
+			Privileged: true,
-		Image: "moby/buildkit",
+		}, &network.NetworkingConfig{}, d.Name)
-	}, &container.HostConfig{
+		if err != nil {
-		Privileged: true,
+			return err
-	}, &network.NetworkingConfig{}, d.Name)
+		}
-	if err != nil {
+		if err := d.start(ctx, l); err != nil {
-		return err
+			return err
-	}
+		}
-	if err := d.start(ctx, l); err != nil {
+		return nil
+	}); err != nil {
 		return err
 	}
 	return nil
 }
 
-func (d *Driver) start(ctx context.Context, l driver.Logger) error {
+func (d *Driver) start(ctx context.Context, l progress.SubLogger) error {
 	return d.DockerAPI.ContainerStart(ctx, d.Name, types.ContainerStartOptions{})
 }
 

driver/driver.go

@@ -2,16 +2,16 @@ package driver
 
 import (
 	"context"
+	"time"
 
 	"github.com/moby/buildkit/client"
 	"github.com/pkg/errors"
+	"github.com/tonistiigi/buildx/util/progress"
 )
 
 var ErrNotRunning = errors.Errorf("driver not running")
 var ErrNotConnecting = errors.Errorf("driver not connection")
 
-type Logger func(*client.SolveStatus)
-
 type Status int
 
 const (
@@ -27,31 +27,31 @@ type Info struct {
 }
 
 type Driver interface {
-	Bootstrap(context.Context, Logger) error
+	Bootstrap(context.Context, progress.Logger) error
 	Info(context.Context) (*Info, error)
 	Stop(ctx context.Context, force bool) error
 	Rm(ctx context.Context, force bool) error
 	Client(ctx context.Context) (*client.Client, error)
 }
 
-func Boot(ctx context.Context, d Driver, status chan *client.SolveStatus) (*client.Client, error) {
+func Boot(ctx context.Context, d Driver, pw progress.Writer) (*client.Client, progress.Writer, error) {
 	try := 0
 	for {
 		info, err := d.Info(ctx)
 		if err != nil {
-			return nil, err
+			return nil, nil, err
 		}
 		try++
 		if info.Status != Running {
 			if try > 2 {
-				return nil, errors.Errorf("failed to bootstrap %T driver in attempts", d)
+				return nil, nil, errors.Errorf("failed to bootstrap %T driver in attempts", d)
 			}
 			if err := d.Bootstrap(ctx, func(s *client.SolveStatus) {
-				if status != nil {
+				if pw != nil {
-					status <- s
+					pw.Status() <- s
 				}
 			}); err != nil {
-				return nil, err
+				return nil, nil, err
 			}
 		}
 
@@ -60,10 +60,72 @@ func Boot(ctx context.Context, d Driver, status chan *client.SolveStatus) (*clie
 			if errors.Cause(err) == ErrNotRunning && try <= 2 {
 				continue
 			}
-			return nil, err
+			return nil, nil, err
 		}
-		return c, nil
+		return c, newResetWriter(pw), nil
 	}
-
+}
-	return nil, errors.Errorf("boot not implemented")
+
+func newResetWriter(in progress.Writer) progress.Writer {
+	w := &pw{Writer: in, status: make(chan *client.SolveStatus), tm: time.Now()}
+	go func() {
+		for {
+			select {
+			case <-in.Done():
+				return
+			case st, ok := <-w.status:
+				if !ok {
+					close(in.Status())
+					return
+				}
+				if w.diff == nil {
+					for _, v := range st.Vertexes {
+						if v.Started != nil {
+							d := v.Started.Sub(w.tm)
+							w.diff = &d
+						}
+					}
+				}
+				if w.diff != nil {
+					for _, v := range st.Vertexes {
+						if v.Started != nil {
+							d := v.Started.Add(-*w.diff)
+							v.Started = &d
+						}
+						if v.Completed != nil {
+							d := v.Completed.Add(-*w.diff)
+							v.Completed = &d
+						}
+					}
+					for _, v := range st.Statuses {
+						if v.Started != nil {
+							d := v.Started.Add(-*w.diff)
+							v.Started = &d
+						}
+						if v.Completed != nil {
+							d := v.Completed.Add(-*w.diff)
+							v.Completed = &d
+						}
+						v.Timestamp = v.Timestamp.Add(-*w.diff)
+					}
+					for _, v := range st.Logs {
+						v.Timestamp = v.Timestamp.Add(-*w.diff)
+					}
+				}
+				in.Status() <- st
+			}
+		}
+	}()
+	return w
+}
+
+type pw struct {
+	progress.Writer
+	tm     time.Time
+	diff   *time.Duration
+	status chan *client.SolveStatus
+}
+
+func (p *pw) Status() chan *client.SolveStatus {
+	return p.status
 }

go.mod

@@ -22,6 +22,7 @@ require (
 	github.com/denisenkom/go-mssqldb v0.0.0-20190315220205-a8ed825ac853 // indirect
 	github.com/docker/cli v0.0.0-20190321234815-f40f9c240ab0
 	github.com/docker/compose-on-kubernetes v0.4.19-0.20190128150448-356b2919c496 // indirect
+	github.com/docker/docker v1.14.0-0.20190319215453-e7b5f7dbe98c
 	github.com/docker/docker-credential-helpers v0.6.1 // indirect
 	github.com/docker/go v1.5.1-1.0.20160303222718-d30aec9fd63c // indirect
 	github.com/docker/go-connections v0.4.0 // indirect

util/progress/printer.go

@@ -0,0 +1,52 @@
+package progress
+
+import (
+	"context"
+	"os"
+
+	"github.com/containerd/console"
+	"github.com/moby/buildkit/client"
+	"github.com/moby/buildkit/util/progress/progressui"
+)
+
+type printer struct {
+	status chan *client.SolveStatus
+	done   <-chan struct{}
+	err    error
+}
+
+func (p *printer) Done() <-chan struct{} {
+	return p.done
+}
+
+func (p *printer) Err() error {
+	return p.err
+}
+
+func (p *printer) Status() chan *client.SolveStatus {
+	if p == nil {
+		return nil
+	}
+	return p.status
+}
+
+func NewPrinter(ctx context.Context, out *os.File, mode string) Writer {
+	statusCh := make(chan *client.SolveStatus)
+	doneCh := make(chan struct{})
+
+	pw := &printer{
+		status: statusCh,
+		done:   doneCh,
+	}
+
+	go func() {
+		var c console.Console
+		if cons, err := console.ConsoleFromFile(out); err == nil && (mode == "auto" || mode == "tty") {
+			c = cons
+		}
+		// not using shared context to not disrupt display but let is finish reporting errors
+		pw.err = progressui.DisplaySolveStatus(ctx, "", c, out, statusCh)
+		close(doneCh)
+	}()
+	return pw
+}

util/progress/progress.go

@@ -0,0 +1,90 @@
+package progress
+
+import (
+	"time"
+
+	"github.com/moby/buildkit/client"
+	"github.com/moby/buildkit/identity"
+	"github.com/opencontainers/go-digest"
+)
+
+type Logger func(*client.SolveStatus)
+
+type SubLogger interface {
+	Wrap(name string, fn func() error) error
+	Log(stream int, dt []byte)
+}
+
+func Wrap(name string, l Logger, fn func(SubLogger) error) (err error) {
+	dgst := digest.FromBytes([]byte(identity.NewID()))
+	tm := time.Now()
+	l(&client.SolveStatus{
+		Vertexes: []*client.Vertex{{
+			Digest:  dgst,
+			Name:    name,
+			Started: &tm,
+		}},
+	})
+
+	defer func() {
+		tm2 := time.Now()
+		errMsg := ""
+		if err != nil {
+			errMsg = err.Error()
+		}
+		l(&client.SolveStatus{
+			Vertexes: []*client.Vertex{{
+				Digest:    dgst,
+				Name:      name,
+				Started:   &tm,
+				Completed: &tm2,
+				Error:     errMsg,
+			}},
+		})
+	}()
+
+	return fn(&subLogger{dgst, l})
+}
+
+type subLogger struct {
+	dgst   digest.Digest
+	logger Logger
+}
+
+func (sl *subLogger) Wrap(name string, fn func() error) (err error) {
+	tm := time.Now()
+	sl.logger(&client.SolveStatus{
+		Statuses: []*client.VertexStatus{{
+			Vertex:    sl.dgst,
+			ID:        name,
+			Timestamp: time.Now(),
+			Started:   &tm,
+		}},
+	})
+
+	defer func() {
+		tm2 := time.Now()
+		sl.logger(&client.SolveStatus{
+			Statuses: []*client.VertexStatus{{
+				Vertex:    sl.dgst,
+				ID:        name,
+				Timestamp: time.Now(),
+				Started:   &tm,
+				Completed: &tm2,
+			}},
+		})
+	}()
+
+	return fn()
+}
+
+func (sl *subLogger) Log(stream int, dt []byte) {
+	sl.logger(&client.SolveStatus{
+		Logs: []*client.VertexLog{{
+			Vertex:    sl.dgst,
+			Stream:    stream,
+			Data:      dt,
+			Timestamp: time.Now(),
+		}},
+	})
+}

util/progress/writer.go

@@ -0,0 +1,11 @@
+package progress
+
+import (
+	"github.com/moby/buildkit/client"
+)
+
+type Writer interface {
+	Done() <-chan struct{}
+	Err() error
+	Status() chan *client.SolveStatus
+}

vendor/modules.txt

@@ -149,6 +149,8 @@ github.com/docker/distribution/metrics
 # github.com/docker/docker v1.14.0-0.20190319215453-e7b5f7dbe98c
 github.com/docker/docker/client
 github.com/docker/docker/api/types
+github.com/docker/docker/api/types/container
+github.com/docker/docker/api/types/network
 github.com/docker/docker/api/types/events
 github.com/docker/docker/api/types/filters
 github.com/docker/docker/api/types/registry
@@ -157,17 +159,16 @@ github.com/docker/docker/pkg/system
 github.com/docker/docker/pkg/term
 github.com/docker/docker/registry
 github.com/docker/docker/api
-github.com/docker/docker/api/types/container
 github.com/docker/docker/api/types/image
-github.com/docker/docker/api/types/network
 github.com/docker/docker/api/types/swarm
 github.com/docker/docker/api/types/time
 github.com/docker/docker/api/types/versions
 github.com/docker/docker/api/types/volume
 github.com/docker/docker/errdefs
-github.com/docker/docker/pkg/jsonmessage
-github.com/docker/docker/api/types/blkiodev
 github.com/docker/docker/api/types/mount
+github.com/docker/docker/api/types/blkiodev
+github.com/docker/docker/api/types/strslice
+github.com/docker/docker/pkg/jsonmessage
 github.com/docker/docker/pkg/idtools
 github.com/docker/docker/pkg/mount
 github.com/docker/docker/pkg/term/windows
@@ -175,9 +176,8 @@ github.com/docker/docker/pkg/ioutils
 github.com/docker/docker/pkg/stringid
 github.com/docker/docker/pkg/tarsum
 github.com/docker/docker/registry/resumable
-github.com/docker/docker/pkg/fileutils
-github.com/docker/docker/api/types/strslice
 github.com/docker/docker/api/types/swarm/runtime
+github.com/docker/docker/pkg/fileutils
 github.com/docker/docker/pkg/longpath
 # github.com/docker/docker-credential-helpers v0.6.1
 github.com/docker/docker-credential-helpers/client
@@ -253,7 +253,6 @@ github.com/moby/buildkit/session/sshforward/sshprovider
 github.com/moby/buildkit/util/progress/progressui
 github.com/moby/buildkit/session/auth/authprovider
 github.com/moby/buildkit/util/appcontext
-github.com/moby/buildkit/util/appdefaults
 github.com/moby/buildkit/api/services/control
 github.com/moby/buildkit/api/types
 github.com/moby/buildkit/client/buildid
@@ -268,6 +267,7 @@ github.com/moby/buildkit/session/filesync
 github.com/moby/buildkit/session/grpchijack
 github.com/moby/buildkit/solver/pb
 github.com/moby/buildkit/util/apicaps
+github.com/moby/buildkit/util/appdefaults
 github.com/moby/buildkit/util/entitlements
 github.com/moby/buildkit/session/secrets
 github.com/moby/buildkit/session/sshforward
@@ -358,8 +358,8 @@ golang.org/x/net/trace
 golang.org/x/net/http/httpguts
 golang.org/x/net/http2/hpack
 golang.org/x/net/idna
-golang.org/x/net/internal/timeseries
 golang.org/x/net/proxy
+golang.org/x/net/internal/timeseries
 golang.org/x/net/context/ctxhttp
 golang.org/x/net/internal/socks
 # golang.org/x/sync v0.0.0-20180314180146-1d60e4601c6f