log files which are sent to buildkit

When running in verbose mode, log which files are sent to buildkit
including file stats and files which are excluded (ignored).

Signed-off-by: Alex Couture-Beil <alex@earthly.dev>

buildcontext/local.go

@@ -2,10 +2,10 @@ package buildcontext
 
 import (
 	"context"
-	"fmt"
 	"path/filepath"
 
 	"github.com/earthly/earthly/analytics"
+	"github.com/earthly/earthly/conslogging"
 	"github.com/earthly/earthly/domain"
 	"github.com/earthly/earthly/util/gitutil"
 	"github.com/earthly/earthly/util/llbutil"
@@ -18,6 +18,7 @@ import (
 type localResolver struct {
 	gitMetaCache *synccache.SyncCache // local path -> *gitutil.GitMetadata
 	sessionID    string
+	console      conslogging.ConsoleLogger
 }
 
 func (lr *localResolver) resolveLocal(ctx context.Context, ref domain.Reference) (*Data, error) {
@@ -38,7 +39,7 @@ func (lr *localResolver) resolveLocal(ctx context.Context, ref domain.Reference)
 				// remote not detected.
 				if errors.Is(err, gitutil.ErrNoGitBinary) {
 					// TODO: Log this properly in the console.
-					fmt.Printf("Warning: %s\n", err.Error())
+					lr.console.Warnf("Warning: %s\n", err.Error())
 				}
 			} else {
 				return nil, err

buildcontext/provider/provider.go

@@ -5,10 +5,13 @@ package provider
 
 import (
 	"os"
+	"path"
 	"strings"
 	"sync"
 	"time"
 
+	"github.com/earthly/earthly/conslogging"
+
 	"github.com/moby/buildkit/session"
 	"github.com/moby/buildkit/session/filesync"
 	"github.com/pkg/errors"
@@ -41,6 +44,8 @@ type BuildContextProvider struct {
 
 	mu   sync.Mutex
 	dirs map[string]SyncedDir
+
+	console conslogging.ConsoleLogger
 }
 
 // SyncedDir is a directory to be synced across.
@@ -52,9 +57,10 @@ type SyncedDir struct {
 }
 
 // NewBuildContextProvider creates a new provider for sending build context files from client.
-func NewBuildContextProvider() *BuildContextProvider {
+func NewBuildContextProvider(console conslogging.ConsoleLogger) *BuildContextProvider {
 	return &BuildContextProvider{
-		dirs: map[string]SyncedDir{},
+		dirs:    map[string]SyncedDir{},
+		console: console,
 	}
 }
 
@@ -129,10 +135,36 @@ func (bcp *BuildContextProvider) handle(method string, stream grpc.ServerStream)
 
 	followPaths := opts[keyFollowPaths]
 
-	var progress progressCb
-	if bcp.p != nil {
-		progress = bcp.p
-		bcp.p = nil
+	var mutex sync.Mutex
+	console := bcp.console.WithPrefixAndSalt("context", dir.Dir)
+	numStats := 0
+	numSends := 0
+	verboseProgressCB := func(relPath string, status fsutil.VerboseProgressStatus, numBytes int) {
+		mutex.Lock()
+		defer mutex.Unlock()
+		fullPath := path.Join(dir.Dir, relPath)
+		switch status {
+		case fsutil.StatusStat:
+			numStats++
+			//console.VerbosePrintf("sent file stat for %s\n", fullPath) ignored as it is too verbose. TODO add different verbose levels to support ExtraVerbosePrintf
+		case fsutil.StatusSent:
+			console.VerbosePrintf("sent data for %s (%d bytes)\n", fullPath, numBytes)
+			numSends++
+		case fsutil.StatusFailed:
+			console.VerbosePrintf("sent data for %s failed\n", fullPath)
+		case fsutil.StatusSkipped:
+			console.VerbosePrintf("ignoring %s\n", fullPath)
+		default:
+			console.Warnf("unhandled progress status %v (path=%s, numBytes=%d)\n", status, fullPath, numBytes)
+		}
+	}
+
+	progress := func(numBytes int, last bool) {
+		mutex.Lock()
+		defer mutex.Unlock()
+		if last {
+			console.Printf("transfered %d file(s) for context %s (%d bytes, %d file/dir stats)", numSends, dir.Dir, numBytes, numStats)
+		}
 	}
 
 	var doneCh chan error
@@ -141,11 +173,12 @@ func (bcp *BuildContextProvider) handle(method string, stream grpc.ServerStream)
 		bcp.doneCh = nil
 	}
 	err = pr.sendFn(stream, fsutil.NewFS(dir.Dir, &fsutil.WalkOpt{
-		ExcludePatterns: excludes,
-		IncludePatterns: includes,
-		FollowPaths:     followPaths,
-		Map:             dir.Map,
-	}), progress)
+		ExcludePatterns:   excludes,
+		IncludePatterns:   includes,
+		FollowPaths:       followPaths,
+		Map:               dir.Map,
+		VerboseProgressCB: verboseProgressCB,
+	}), progress, verboseProgressCB)
 	if doneCh != nil {
 		if err != nil {
 			doneCh <- err
@@ -175,7 +208,7 @@ type progressCb func(int, bool)
 
 type protocol struct {
 	name   string
-	sendFn func(stream filesync.Stream, fs fsutil.FS, progress progressCb) error
+	sendFn func(stream filesync.Stream, fs fsutil.FS, progress progressCb, verboseProgress fsutil.VerboseProgressCB) error
 	recvFn func(stream grpc.ClientStream, destDir string, cu filesync.CacheUpdater, progress progressCb, mapFunc func(string, *fstypes.Stat) bool) error
 }
 
@@ -195,8 +228,8 @@ var supportedProtocols = []protocol{
 	},
 }
 
-func sendDiffCopy(stream filesync.Stream, fs fsutil.FS, progress progressCb) error {
-	return errors.WithStack(fsutil.Send(stream.Context(), stream, fs, progress))
+func sendDiffCopy(stream filesync.Stream, fs fsutil.FS, progress progressCb, verboseProgress fsutil.VerboseProgressCB) error {
+	return errors.WithStack(fsutil.Send(stream.Context(), stream, fs, progress, verboseProgress))
 }
 
 func recvDiffCopy(ds grpc.ClientStream, dest string, cu filesync.CacheUpdater, progress progressCb, filter func(string, *fstypes.Stat) bool) error {

buildcontext/resolver.go

@@ -8,10 +8,12 @@ import (
 	"github.com/earthly/earthly/ast"
 	"github.com/earthly/earthly/ast/spec"
 	"github.com/earthly/earthly/cleanup"
+	"github.com/earthly/earthly/conslogging"
 	"github.com/earthly/earthly/domain"
 	"github.com/earthly/earthly/util/gitutil"
 	"github.com/earthly/earthly/util/llbutil/pllb"
 	"github.com/earthly/earthly/util/syncutil/synccache"
+
 	gwclient "github.com/moby/buildkit/frontend/gateway/client"
 	"github.com/pkg/errors"
 )
@@ -42,10 +44,11 @@ type Resolver struct {
 	lr *localResolver
 
 	parseCache *synccache.SyncCache // local path -> AST
+	console    conslogging.ConsoleLogger
 }
 
 // NewResolver returns a new NewResolver.
-func NewResolver(sessionID string, cleanCollection *cleanup.Collection, gitLookup *GitLookup) *Resolver {
+func NewResolver(sessionID string, cleanCollection *cleanup.Collection, gitLookup *GitLookup, console conslogging.ConsoleLogger) *Resolver {
 	return &Resolver{
 		gr: &gitResolver{
 			cleanCollection: cleanCollection,
@@ -56,8 +59,10 @@ func NewResolver(sessionID string, cleanCollection *cleanup.Collection, gitLooku
 		lr: &localResolver{
 			gitMetaCache: synccache.New(),
 			sessionID:    sessionID,
+			console:      console,
 		},
 		parseCache: synccache.New(),
+		console:    console,
 	}
 }
 
@@ -81,6 +86,7 @@ func (r *Resolver) Resolve(ctx context.Context, gwClient gwclient.Client, ref do
 		if _, isTarget := ref.(domain.Target); isTarget {
 			localDirs[ref.GetLocalPath()] = ref.GetLocalPath()
 		}
+
 		d, err = r.lr.resolveLocal(ctx, ref)
 		if err != nil {
 			return nil, err

builder/builder.go

@@ -101,7 +101,7 @@ func NewBuilder(ctx context.Context, opt Opt) (*Builder, error) {
 		opt:      opt,
 		resolver: nil, // initialized below
 	}
-	b.resolver = buildcontext.NewResolver(opt.SessionID, opt.CleanCollection, opt.GitLookup)
+	b.resolver = buildcontext.NewResolver(opt.SessionID, opt.CleanCollection, opt.GitLookup, opt.Console)
 	return b, nil
 }
 
@@ -727,7 +727,7 @@ func (b *Builder) saveArtifactLocally(ctx context.Context, artifact domain.Artif
 		}
 
 		// Write to console about this artifact.
-		artifactPath := trimFilePathPrefix(indexOutDir, from)
+		artifactPath := trimFilePathPrefix(indexOutDir, from, console)
 		artifact2 := domain.Artifact{
 			Target:   artifact.Target,
 			Artifact: artifactPath,
@@ -768,10 +768,10 @@ func (b *Builder) tempEarthlyOutDir() (string, error) {
 	return b.outDir, err
 }
 
-func trimFilePathPrefix(prefix string, thePath string) string {
+func trimFilePathPrefix(prefix string, thePath string, console conslogging.ConsoleLogger) string {
 	ret, err := filepath.Rel(prefix, thePath)
 	if err != nil {
-		fmt.Printf("Warning: Could not compute relative path for %s as being relative to %s: %s\n", thePath, prefix, err.Error())
+		console.Warnf("Warning: Could not compute relative path for %s as being relative to %s: %s\n", thePath, prefix, err.Error())
 		return thePath
 	}
 	return ret

buildkitd/Earthfile

@@ -6,12 +6,12 @@ buildkitd:
     IF [ "$BUILDKIT_PROJECT" != "" ]
         IF case "$BUILDKIT_PROJECT" in "../*") true;; "*") false;; esac
             # Assuming this is coming from the main Earthly Earthfile.
-            ARG BUILDKIT_BASE_IMAGE=../$BUILDKIT_PROJECT+build
+            ARG BUILDKIT_BASE_IMAGE=github.com/earthly/buildkit:00025901bf6b30a374e68eecf9fab9c28554bd25+build
         ELSE
-            ARG BUILDKIT_BASE_IMAGE=$BUILDKIT_PROJECT+build
+            ARG BUILDKIT_BASE_IMAGE=github.com/earthly/buildkit:00025901bf6b30a374e68eecf9fab9c28554bd25+build
         END
     ELSE
-        ARG BUILDKIT_BASE_IMAGE=github.com/earthly/buildkit:c896a903b73a001a756c8d40330874451dbe38c4+build
+        ARG BUILDKIT_BASE_IMAGE=github.com/earthly/buildkit:00025901bf6b30a374e68eecf9fab9c28554bd25+build
     END
     FROM $BUILDKIT_BASE_IMAGE
     RUN echo "@edge-community http://dl-cdn.alpinelinux.org/alpine/edge/community" >> /etc/apk/repositories
@@ -61,5 +61,6 @@ update-buildkit:
     LOCALLY
     ARG BUILDKIT_BRANCH=earthly-main
     RUN buildkit_sha1=$(git ls-remote --refs -q https://github.com/earthly/buildkit.git "$BUILDKIT_BRANCH" | awk 'BEGIN { FS = "[ \t]+" } {print $1}') && \
+        test ! -z "$buildkit_sha1" && \
         echo "pinning github.com/earthly/buildkit@${BUILDKIT_BRANCH} to reference git sha1: $buildkit_sha1" && \
-        sed -i 's/\(^[ \t]\+ARG BUILDKIT_BASE_IMAGE=\).*/\1github.com\/earthly\/buildkit:'$buildkit_sha1'+build/g' Earthfile
+        sed -i 's/\(^[ \t]\+ARG BUILDKIT_BASE_IMAGE=github.com\/earthly\/buildkit\).*/\1:'$buildkit_sha1'+build/g' Earthfile

cmd/debugger/main.go

@@ -209,7 +209,7 @@ func main() {
 
 	if debuggerSettings.DebugLevelLogging {
 		logrus.SetLevel(logrus.DebugLevel)
-		conslogger.SetVerbose(true)
+		conslogger = conslogger.WithVerbose(true)
 	}
 
 	ctx := context.Background()

cmd/earthly/main.go

@@ -932,7 +932,9 @@ func (app *earthlyApp) before(context *cli.Context) error {
 		go profhandler()
 	}
 
-	app.console.SetVerbose(app.verbose)
+	if app.verbose {
+		app.console = app.console.WithVerbose(true)
+	}
 
 	if context.IsSet("config") {
 		app.console.Printf("loading config values from %q\n", app.configPath)
@@ -2599,7 +2601,7 @@ func (app *earthlyApp) actionBuildImp(c *cli.Context, flagArgs, nonFlagArgs []st
 	defer os.RemoveAll(cacheLocalDir)
 	defaultLocalDirs := make(map[string]string)
 	defaultLocalDirs["earthly-cache"] = cacheLocalDir
-	buildContextProvider := provider.NewBuildContextProvider()
+	buildContextProvider := provider.NewBuildContextProvider(app.console)
 	buildContextProvider.AddDirs(defaultLocalDirs)
 	attachables := []session.Attachable{
 		llbutil.NewSecretProvider(sc, secretsMap),

conslogging/conslogging.go

@@ -250,14 +250,14 @@ func (cl ConsoleLogger) PrintBytes(data []byte) {
 // VerbosePrintf prints formatted text to the console when verbose flag is set.
 func (cl ConsoleLogger) VerbosePrintf(format string, args ...interface{}) {
 	if cl.verbose {
-		cl.Printf(format, args...)
+		cl.WithMetadataMode(true).Printf(format, args...)
 	}
 }
 
 // VerboseBytes prints bytes directly to the console when verbose flag is set.
 func (cl ConsoleLogger) VerboseBytes(data []byte) {
 	if cl.verbose {
-		cl.PrintBytes(data)
+		cl.WithMetadataMode(true).PrintBytes(data)
 	}
 }
 
@@ -340,7 +340,9 @@ func (cl ConsoleLogger) prettyPrefix() string {
 	return fmt.Sprintf(formatString, fmt.Sprintf("%s%s", prettyPrefix, brackets))
 }
 
-// SetVerbose toggles the verbose level
-func (cl *ConsoleLogger) SetVerbose(verbose bool) {
-	cl.verbose = verbose
+// WithVerbose toggles the verbose level
+func (cl ConsoleLogger) WithVerbose(verbose bool) ConsoleLogger {
+	ret := cl.clone()
+	ret.verbose = verbose
+	return ret
 }

earthfile2llb/earthfile2llb.go

@@ -94,6 +94,7 @@ func Earthfile2LLB(ctx context.Context, target domain.Target, opt ConvertOpt) (m
 	if opt.MetaResolver == nil {
 		opt.MetaResolver = NewCachedMetaResolver(opt.GwClient)
 	}
+
 	// Resolve build context.
 	bc, err := opt.Resolver.Resolve(ctx, opt.GwClient, target)
 	if err != nil {

examples/tests/Earthfile

@@ -94,6 +94,12 @@ copy-test:
         echo "sub" > in/sub/file
     DO +RUN_EARTHLY --earthfile=copy.earth
 
+    RUN echo "output.txt" > .earthignore
+    DO +RUN_EARTHLY --earthfile=copy.earth --extra_args="--verbose"  --post_command="2>output.txt"
+    RUN cat output.txt
+    RUN cat output.txt | grep 'sent file stat for in/root'
+    RUN cat output.txt | grep 'sent data for in/root (5 bytes)'
+
 cache-test:
     # Test that a file can be passed between runs through the mounted cache.
     DO +RUN_EARTHLY --earthfile=cache1.earth --target=+test-pass-file --use_tmpfs=false

go.mod

@@ -44,5 +44,6 @@ replace (
 	github.com/docker/docker => github.com/docker/docker v17.12.0-ce-rc1.0.20200310163718-4634ce647cf2+incompatible
 	github.com/hashicorp/go-immutable-radix => github.com/tonistiigi/go-immutable-radix v0.0.0-20170803185627-826af9ccf0fe
 	github.com/jaguilar/vt100 => github.com/tonistiigi/vt100 v0.0.0-20190402012908-ad4c4a574305
-	github.com/moby/buildkit => github.com/earthly/buildkit v0.7.1-0.20210604003203-c896a903b73a
+	github.com/moby/buildkit => github.com/earthly/buildkit v0.0.0-20210609215831-00025901bf6b
+	github.com/tonistiigi/fsutil => github.com/earthly/fsutil v0.0.0-20210609160335-a94814c540b2
 )