From e97f40041917ab0e46a7f6e7dcde827dcc7fe014 Mon Sep 17 00:00:00 2001 From: Daniel Schlegel Date: Wed, 27 May 2026 19:14:04 +0200 Subject: [PATCH 1/6] feat: record and surface cache miss reasons for auto-skip When auto-skip computes a target hash and finds a cache miss (the hash is not in the skip DB), users previously had no visibility into what inputs were hashed and why the target needs to run. This change adds a HashLog to Stats that records every significant input that contributes to the cache key: - Built-in args (earthly version, platform, CI flag) - VERSION block flags - ARG, LET, SET values (with expanded values) - FROM (base image or target) - BUILD / COPY target dependencies (with resolved hash) - COPY file (individual file paths that were content-hashed) - RUN and all other commands (name + expanded args) - WITH DOCKER (load targets + args) - IF / ELSE IF conditions - FOR loop variable and per-iteration values - WAIT / TRY structural blocks - IMPORT statements - Overriding build args passed via --build-arg On a cache miss both initAutoSkip (top-level --auto-skip flag) and checkAutoSkip (BUILD --auto-skip) print the full log at verbose level so developers can see exactly which inputs earthbuild is sensitive to. New tests in inputgraph/hash_log_test.go cover: - ARG default values appear in the log - LET and SET values appear in the log - BUILD dep target hash appears in the log - ARG override produces a different hash and a 'build arg' entry - Multiple ARG declarations are all individually recorded New testdata fixture: inputgraph/testdata/cache-miss-reason/Earthfile --- cmd/earthly/subcmd/build_cmd.go | 10 + earthfile2llb/converter.go | 12 +- inputgraph/hash_log_test.go | 237 ++++++++++++++++++ inputgraph/loader.go | 93 ++++++- .../testdata/cache-miss-reason/Earthfile | 25 ++ 5 files changed, 366 insertions(+), 11 deletions(-) create mode 100644 inputgraph/hash_log_test.go create mode 100644 inputgraph/testdata/cache-miss-reason/Earthfile diff --git a/cmd/earthly/subcmd/build_cmd.go b/cmd/earthly/subcmd/build_cmd.go index 7ce9c4a732..f3ba277b80 100644 --- a/cmd/earthly/subcmd/build_cmd.go +++ b/cmd/earthly/subcmd/build_cmd.go @@ -927,6 +927,16 @@ func (b *Build) initAutoSkip( return nil, true, nil } + // Cache miss: log the inputs that were hashed so the user can understand + // what will cause this target to be rebuilt. + if len(stats.HashLog) > 0 { + console.VerbosePrintf("cache miss for %s — hashed inputs:", targetStr) + + for _, entry := range stats.HashLog { + console.VerbosePrintf(" %-16s %s", entry.Label, entry.Detail) + } + } + addHashFn := func() { err := skipDB.Add(ctx, target.StringCanonical(), targetHash) if err != nil { diff --git a/earthfile2llb/converter.go b/earthfile2llb/converter.go index cd98f3a724..e300753cbc 100644 --- a/earthfile2llb/converter.go +++ b/earthfile2llb/converter.go @@ -2333,7 +2333,7 @@ func (c *Converter) checkAutoSkip( return false, nil, err } - targetHash, _, err := inputgraph.HashTarget(ctx, inputgraph.HashOpt{ + targetHash, hashStats, err := inputgraph.HashTarget(ctx, inputgraph.HashOpt{ Target: target, Console: c.opt.Console, CI: c.opt.IsCI, @@ -2357,6 +2357,16 @@ func (c *Converter) checkAutoSkip( return true, nil, nil } + // Cache miss: log the inputs that were hashed so the user can understand + // what will cause this target to be rebuilt. + if len(hashStats.HashLog) > 0 { + console.VerbosePrintf("cache miss for %s — hashed inputs:", target.String()) + + for _, entry := range hashStats.HashLog { + console.VerbosePrintf(" %-16s %s", entry.Label, entry.Detail) + } + } + return exists, func() { err := c.opt.BuildkitSkipper.Add(ctx, target.StringCanonical(), targetHash) if err != nil { diff --git a/inputgraph/hash_log_test.go b/inputgraph/hash_log_test.go new file mode 100644 index 0000000000..a169c7a5cd --- /dev/null +++ b/inputgraph/hash_log_test.go @@ -0,0 +1,237 @@ +package inputgraph + +import ( + "context" + "os" + "slices" + "sync" + "testing" + + "github.com/EarthBuild/earthbuild/conslogging" + "github.com/EarthBuild/earthbuild/domain" + "github.com/EarthBuild/earthbuild/variables" + "github.com/stretchr/testify/require" +) + +// newTestConsole returns a no-op console suitable for unit tests. +func newTestConsole() conslogging.ConsoleLogger { + return conslogging.New(os.Stderr, &sync.Mutex{}, conslogging.NoColor, 0, conslogging.Info, false) +} + +// testdataCacheMissReason is the path to the testdata fixture used by the hash +// log tests. +const testdataCacheMissReason = "./testdata/cache-miss-reason" + +// labelSet returns the set of distinct Label values in a HashLog. +func labelSet(log []HashInput) map[string]struct{} { + s := make(map[string]struct{}, len(log)) + for _, e := range log { + s[e.Label] = struct{}{} + } + + return s +} + +// detailsForLabel returns all Detail values for entries with the given label. +func detailsForLabel(log []HashInput, label string) []string { + var out []string + + for _, e := range log { + if e.Label == label { + out = append(out, e.Detail) + } + } + + return out +} + +// TestHashLogPopulatedForARG verifies that ARG inputs are recorded in the +// hash log with the expanded value. +func TestHashLogPopulatedForARG(t *testing.T) { + t.Parallel() + + r := require.New(t) + + target := domain.Target{ + LocalPath: testdataCacheMissReason, + Target: "simple-arg", + } + + hash, stats, err := HashTarget(context.Background(), HashOpt{ + Console: newTestConsole(), + Target: target, + }) + + r.NoError(err) + r.NotEmpty(hash) + r.NotEmpty(stats.HashLog, "HashLog should be populated") + + labels := labelSet(stats.HashLog) + r.Contains(labels, "ARG", "expected an ARG entry in the hash log") + + argDetails := detailsForLabel(stats.HashLog, "ARG") + r.NotEmpty(argDetails) + + // The default value "hello" should appear in the detail. + r.True(slices.Contains(argDetails, "MESSAGE=hello"), + "expected ARG entry 'MESSAGE=hello' in hash log, got: %v", argDetails) +} + +// TestHashLogPopulatedForLETandSET verifies that LET and SET inputs are +// recorded in the hash log. +func TestHashLogPopulatedForLETandSET(t *testing.T) { + t.Parallel() + + r := require.New(t) + + target := domain.Target{ + LocalPath: testdataCacheMissReason, + Target: "with-let", + } + + hash, stats, err := HashTarget(context.Background(), HashOpt{ + Console: newTestConsole(), + Target: target, + }) + + r.NoError(err) + r.NotEmpty(hash) + r.NotEmpty(stats.HashLog) + + labels := labelSet(stats.HashLog) + r.Contains(labels, "LET", "expected a LET entry in the hash log") + r.Contains(labels, "SET", "expected a SET entry in the hash log") + + letDetails := detailsForLabel(stats.HashLog, "LET") + r.NotEmpty(letDetails) + r.Contains(letDetails[0], "x=initial") + + setDetails := detailsForLabel(stats.HashLog, "SET") + r.NotEmpty(setDetails) + r.Contains(setDetails[0], "x=updated") +} + +// TestHashLogContainsDepTarget verifies that when a target depends on another +// local target via BUILD, the dependency is recorded in the hash log. +func TestHashLogContainsDepTarget(t *testing.T) { + t.Parallel() + + r := require.New(t) + + target := domain.Target{ + LocalPath: testdataCacheMissReason, + Target: "with-dep", + } + + hash, stats, err := HashTarget(context.Background(), HashOpt{ + Console: newTestConsole(), + Target: target, + }) + + r.NoError(err) + r.NotEmpty(hash) + r.NotEmpty(stats.HashLog) + + labels := labelSet(stats.HashLog) + r.Contains(labels, "dep target", "expected a 'dep target' entry for the BUILD dependency") + + depDetails := detailsForLabel(stats.HashLog, "dep target") + r.NotEmpty(depDetails) + + // The detail should mention the dependency target canonical name. + r.True( + slices.ContainsFunc(depDetails, func(d string) bool { return containsSubstr(d, "simple-arg") }), + "expected dep target entry mentioning '+simple-arg', got: %v", depDetails, + ) +} + +// TestHashLogChangesWithARGOverride verifies that overriding an ARG produces a +// different hash AND records the override in the hash log. +func TestHashLogChangesWithARGOverride(t *testing.T) { + t.Parallel() + + r := require.New(t) + + ctx := context.Background() + cons := newTestConsole() + + target := domain.Target{ + LocalPath: testdataCacheMissReason, + Target: "simple-arg", + } + + // Hash with default ARG value. + hashDefault, statsDefault, err := HashTarget(ctx, HashOpt{Console: cons, Target: target}) + r.NoError(err) + r.NotEmpty(hashDefault) + + // Hash with an overriding build arg. + overriding, err := variables.ParseCommandLineArgs([]string{"MESSAGE=world"}) + r.NoError(err) + + hashOverride, statsOverride, err := HashTarget(ctx, HashOpt{ + Console: cons, + Target: target, + OverridingVars: overriding, + }) + r.NoError(err) + r.NotEmpty(hashOverride) + + // The hashes must differ. + r.NotEqual(hashDefault, hashOverride, "override should produce a different hash") + + // The override run must have a "build arg" entry in the log. + r.NotEmpty(statsOverride.HashLog) + + labels := labelSet(statsOverride.HashLog) + r.Contains(labels, "build arg", "expected a 'build arg' entry for the override") + + // The default run must NOT have a "build arg" entry (no overrides given). + defaultLabels := labelSet(statsDefault.HashLog) + _, hasBuildArg := defaultLabels["build arg"] + r.False(hasBuildArg, "expected no 'build arg' entry when no override is given") +} + +// TestHashLogMultipleARGs verifies that all ARG declarations for a target are +// individually recorded in the hash log. +func TestHashLogMultipleARGs(t *testing.T) { + t.Parallel() + + r := require.New(t) + + target := domain.Target{ + LocalPath: testdataCacheMissReason, + Target: "multi-arg", + } + + hash, stats, err := HashTarget(context.Background(), HashOpt{ + Console: newTestConsole(), + Target: target, + }) + + r.NoError(err) + r.NotEmpty(hash) + r.NotEmpty(stats.HashLog) + + argDetails := detailsForLabel(stats.HashLog, "ARG") + r.GreaterOrEqual(len(argDetails), 2, "expected at least two ARG entries (FIRST and SECOND)") + + detailsSet := make(map[string]struct{}, len(argDetails)) + for _, d := range argDetails { + detailsSet[d] = struct{}{} + } + + r.Contains(detailsSet, "FIRST=one") + r.Contains(detailsSet, "SECOND=two") +} + +// containsSubstr reports whether substr appears within s. +func containsSubstr(s, substr string) bool { + for i := range len(s) - len(substr) + 1 { + if s[i:i+len(substr)] == substr { + return true + } + } + + return false +} diff --git a/inputgraph/loader.go b/inputgraph/loader.go index 2ef509210c..9cadc488f7 100644 --- a/inputgraph/loader.go +++ b/inputgraph/loader.go @@ -34,37 +34,57 @@ var ( errComplexCondition = errors.New("condition cannot be evaluated") ) +// HashInput records a single labelled input that contributed to a target's +// cache hash. Collecting these allows callers to explain a cache miss. +type HashInput struct { + // Label is a human-readable name for the kind of input (e.g. "ARG", "RUN", + // "COPY file", "FROM target"). + Label string + // Detail is additional context (e.g. the expanded value, file path, or + // dependency target name). + Detail string +} + // Stats contains some statistics about the hashing process. type Stats struct { - StartTime time.Time + StartTime time.Time + // HashLog records every input that contributed to the primary target's + // cache hash, in the order they were encountered. It is populated only for + // the outermost (primary) target; recursive dependency loaders share the + // same slice via the shared *Stats pointer. + HashLog []HashInput + Duration time.Duration TargetsHashed int TargetCacheHits int TargetsVisited int - Duration time.Duration } type loader struct { - visited map[string]struct{} - hasher *hasher.Hasher hashCache map[string][]byte - stats *Stats globalImports map[string]domain.ImportTrackerVal varCollection *variables.Collection features *features.Features overridingVars *variables.Scope + visited map[string]struct{} + stats *Stats + hasher *hasher.Hasher target domain.Target builtinArgs variables.DefaultArgs - conslog conslogging.ConsoleLogger - baseProcessed bool - ci bool - primaryTarget bool + // logTarget is the canonical name of the outermost target whose hash log + // we are recording. Set on the primary loader; propagated to sub-loaders so + // they annotate entries with their own target name for clarity. + logTarget string + conslog conslogging.ConsoleLogger + baseProcessed bool + ci bool + primaryTarget bool } func newLoader(opt HashOpt) *loader { h := hasher.New() h.HashJSONMarshalled(opt.BuiltinArgs) // Other important values are set by load(). - return &loader{ + l := &loader{ conslog: opt.Console, target: opt.Target, visited: map[string]struct{}{}, @@ -76,7 +96,31 @@ func newLoader(opt HashOpt) *loader { hashCache: map[string][]byte{}, stats: &Stats{StartTime: time.Now()}, primaryTarget: true, + logTarget: opt.Target.StringCanonical(), + } + // Log the built-in args (platform, earthly version, etc.) that were just + // hashed above so they appear in the hash log. + l.logInput("builtin args", fmt.Sprintf("%+v", opt.BuiltinArgs)) + + return l +} + +// logInput appends a HashInput to the shared Stats.HashLog. It is safe to call +// from any loader in the dependency chain because all loaders share the same +// *Stats pointer. +func (l *loader) logInput(label, detail string) { + if l.stats == nil { + return + } + + entry := HashInput{Label: label, Detail: detail} + if l.logTarget != "" && !l.primaryTarget { + // Prefix with the dependency target name so readers can tell which + // dependency contributed the entry. + entry.Detail = fmt.Sprintf("%s (dep: %s)", detail, l.logTarget) } + + l.stats.HashLog = append(l.stats.HashLog, entry) } func (l *loader) handleFrom(ctx context.Context, cmd spec.Command) error { @@ -302,6 +346,8 @@ func (l *loader) handleCopySrc(ctx context.Context, cmd spec.Command, src string return wrapError(err, cmd.SourceLocation, "failed to hash file %s", path) } + + l.logInput("COPY file", file) } return nil @@ -417,6 +463,10 @@ func (l *loader) handleCommand(ctx context.Context, cmd spec.Command) error { // Some commands require more processing. switch cmd.Name { case command.From: + // Log the base image or target; handleFrom recurses into targets and + // logs them as "dep target". + l.logInput("FROM", strings.Join(cmd.Args, " ")) + return l.handleFrom(ctx, cmd) case command.Build: return l.handleBuild(ctx, cmd) @@ -429,12 +479,18 @@ func (l *loader) handleCommand(ctx context.Context, cmd spec.Command) error { case command.Set: return l.handleSet(cmd) case command.FromDockerfile: + l.logInput("FROM DOCKERFILE", strings.Join(cmd.Args, " ")) + return l.handleFromDockerfile(ctx, cmd) case command.Import: + l.logInput("IMPORT", strings.Join(cmd.Args, " ")) + return l.handleImport(cmd, false) default: // By default, no special handling is required. The raw command has been // hashed above and all argument values have been hashed independently. + l.logInput(cmd.Name, strings.Join(cmd.Args, " ")) + return nil } } @@ -500,6 +556,7 @@ func (l *loader) handleArg(cmd spec.Command, isBase bool) error { } l.hasher.HashString(fmt.Sprintf("ARG %s=%s", key, expanded)) + l.logInput("ARG", fmt.Sprintf("%s=%s", key, expanded)) if opts.Global { declOpts = append(declOpts, variables.AsGlobal()) @@ -536,6 +593,7 @@ func (l *loader) handleLet(cmd spec.Command) error { } l.hasher.HashString(fmt.Sprintf("LET %s=%s", key, val)) + l.logInput("LET", fmt.Sprintf("%s=%s", key, val)) _, _, err = l.varCollection.DeclareVar(key, variables.WithValue(val)) if err != nil { @@ -568,6 +626,7 @@ func (l *loader) handleSet(cmd spec.Command) error { } l.hasher.HashString(fmt.Sprintf("SET %s=%s", key, val)) + l.logInput("SET", fmt.Sprintf("%s=%s", key, val)) err = l.varCollection.UpdateVar(key, val, nil) if err != nil { @@ -600,6 +659,7 @@ func (l *loader) handleWithDocker(ctx context.Context, cmd spec.Command) error { } l.hashCommand(cmd) + l.logInput("WITH DOCKER", strings.Join(cmd.Args, " ")) opts := commandflag.WithDockerOpts{} @@ -747,6 +807,7 @@ func evalCondition(c []string) (bool, bool) { func (l *loader) handleIf(ctx context.Context, ifStmt spec.IfStatement) error { l.hashIfStatement(ifStmt) + l.logInput("IF", strings.Join(ifStmt.Expression, " ")) err := l.handleIfEval(ctx, ifStmt) if err != nil { @@ -810,6 +871,7 @@ func (l *loader) handleIfDefault(ctx context.Context, ifStmt spec.IfStatement) e for _, elseIf := range ifStmt.ElseIf { l.hashElseIf(elseIf) + l.logInput("ELSE IF", strings.Join(elseIf.Expression, " ")) err = l.loadBlock(ctx, elseIf.Body) if err != nil { @@ -829,6 +891,7 @@ func (l *loader) handleIfDefault(ctx context.Context, ifStmt spec.IfStatement) e func (l *loader) handleFor(ctx context.Context, forStmt spec.ForStatement) error { l.hashForStatement(forStmt) + l.logInput("FOR", strings.Join(forStmt.Args, " ")) opts := commandflag.NewForOpts() @@ -849,6 +912,7 @@ func (l *loader) handleFor(ctx context.Context, forStmt spec.ForStatement) error for _, val := range vals { l.hasher.HashString(fmt.Sprintf("FOR %s=%s", name, val)) + l.logInput("FOR iteration", fmt.Sprintf("%s=%s", name, val)) l.varCollection.SetArg(name, val) err := l.loadBlock(ctx, forStmt.Body) @@ -887,11 +951,14 @@ func flattenForArgs(args []string, seps string) []string { func (l *loader) handleWait(ctx context.Context, waitStmt spec.WaitStatement) error { l.hashWaitStatement(waitStmt) + l.logInput("WAIT", fmt.Sprintf("%v", waitStmt.Args)) + return l.handleStatements(ctx, waitStmt.Body) } func (l *loader) handleTry(ctx context.Context, tryStmt spec.TryStatement) error { l.hashTryStatement() + l.logInput("TRY", "") err := l.handleStatements(ctx, tryStmt.TryBody) if err != nil { @@ -991,6 +1058,7 @@ func (l *loader) forTarget(target domain.Target, args []string, passArgs bool) ( hashCache: l.hashCache, stats: l.stats, primaryTarget: false, + logTarget: target.StringCanonical(), } if target.IsLocalInternal() { @@ -1028,6 +1096,8 @@ func (l *loader) loadTargetFromString( if target.IsRemote() { if supportedRemoteTarget(target) { l.hasher.HashString(target.StringCanonical()) + l.logInput("remote target", target.StringCanonical()) + return nil } @@ -1056,6 +1126,7 @@ func (l *loader) loadTargetFromString( } l.hasher.HashBytes(hash) + l.logInput("dep target", fmt.Sprintf("%s (hash: %x)", target.StringCanonical(), hash)) return nil } @@ -1115,12 +1186,14 @@ func (l *loader) load(ctx context.Context) ([]byte, error) { if l.overridingVars != nil { for _, val := range l.overridingVars.BuildArgs() { l.hasher.HashString("VAR " + val) + l.logInput("build arg", val) } } ef := buildCtx.Earthfile if ef.Version != nil { l.hashVersion(*ef.Version) + l.logInput("VERSION", fmt.Sprintf("%v", ef.Version.Args)) } // Ensure all "base" target commands are processed once. diff --git a/inputgraph/testdata/cache-miss-reason/Earthfile b/inputgraph/testdata/cache-miss-reason/Earthfile new file mode 100644 index 0000000000..592d4ed60d --- /dev/null +++ b/inputgraph/testdata/cache-miss-reason/Earthfile @@ -0,0 +1,25 @@ +VERSION 0.8 + +FROM alpine + +# simple-arg: a target with ARG and RUN +simple-arg: + ARG MESSAGE=hello + RUN echo "$MESSAGE" + +# with-let: a target using LET and SET +with-let: + LET x = initial + SET x = updated + RUN echo "$x" + +# with-dep: a target that depends on another local target +with-dep: + BUILD +simple-arg + RUN echo "done" + +# multi-arg: a target with multiple ARGs +multi-arg: + ARG FIRST=one + ARG SECOND=two + RUN echo "$FIRST $SECOND" From 485296e7f13a640b6dff6cc5d1e66ded16e25d30 Mon Sep 17 00:00:00 2001 From: Daniel Schlegel Date: Wed, 27 May 2026 20:58:38 +0200 Subject: [PATCH 2/6] feat: surface BuildKit cache misses as '*cache miss*' log lines When BuildKit executes a vertex that was not found in its content- addressed cache (vertex.Cached == false), write a '*cache miss*' line to the command output -- symmetrical with the existing '*cached*' annotation on hits. This requires no new flags. Every RUN, COPY, and other BuildKit operation that actually executes (rather than being replayed from cache) will now show '*cache miss*' in its output line, making it immediately obvious which steps caused a rebuild and why the build took longer than expected. Internal vertices (BuildKit-internal plumbing) are excluded to avoid noise. Also exports logbus.Stdout / logbus.Stderr as named constants so the solvermon package can reference the stream numbers without duplicating magic literals. --- .gitignore | 1 + logbus/command.go | 9 +++++++-- logbus/solvermon/solvermon.go | 5 +++++ logbus/solvermon/vertexmon.go | 19 ++++++++++--------- 4 files changed, 23 insertions(+), 11 deletions(-) diff --git a/.gitignore b/.gitignore index 9e73346886..5f51ceea64 100644 --- a/.gitignore +++ b/.gitignore @@ -11,3 +11,4 @@ .tmp-earth-out* .DS_Store **/node_modules +dataflow.md diff --git a/logbus/command.go b/logbus/command.go index 194d143aa6..69e4836676 100644 --- a/logbus/command.go +++ b/logbus/command.go @@ -14,8 +14,13 @@ import ( ) const ( - stdout = 1 - stderr = 2 + // Stdout is the stream number for stdout. + Stdout = 1 + // Stderr is the stream number for stderr. + Stderr = 2 + + stdout = Stdout + stderr = Stderr tailErrorBufferSizeBytes = 80 * 1024 // About as much as 1024 lines of 80 chars each. ) diff --git a/logbus/solvermon/solvermon.go b/logbus/solvermon/solvermon.go index d6feee6104..2a27663fb5 100644 --- a/logbus/solvermon/solvermon.go +++ b/logbus/solvermon/solvermon.go @@ -152,6 +152,11 @@ func (sm *SolverMonitor) handleBuildkitStatus(status *client.SolveStatus) error if vertex.Started != nil { vm.cp.SetStart(*vertex.Started) + + if !vertex.Cached && !vm.cacheMissLogged && !vm.meta.Internal { + vm.cacheMissLogged = true + _, _ = vm.cp.Write([]byte("*cache miss*\n"), *vertex.Started, logbus.Stderr) + } } if vertex.Error != "" { diff --git a/logbus/solvermon/vertexmon.go b/logbus/solvermon/vertexmon.go index 3afc25c623..d1e2c5b69e 100644 --- a/logbus/solvermon/vertexmon.go +++ b/logbus/solvermon/vertexmon.go @@ -25,15 +25,16 @@ const ( ) type vertexMonitor struct { - vertex *client.Vertex - meta *vertexmeta.VertexMeta - cp *logbus.Command - ssp *statsstreamparser.Parser - operation string - errorStr string - fatalErrorType logstream.FailureType - isFatalError bool // If set, this is the root cause of the entire build failure. - isCanceled bool + vertex *client.Vertex + meta *vertexmeta.VertexMeta + cp *logbus.Command + ssp *statsstreamparser.Parser + operation string + errorStr string + fatalErrorType logstream.FailureType + isFatalError bool // If set, this is the root cause of the entire build failure. + isCanceled bool + cacheMissLogged bool // Whether the cache miss log line has already been written. } var reErrExitCode = regexp.MustCompile(`(?:process ".*" did not complete successfully|error calling LocalhostExec): exit code: (?P[0-9]+)$`) //nolint:lll From acff21a42dc5ed699f22d74b0fde8106311e73bf Mon Sep 17 00:00:00 2001 From: Daniel Schlegel Date: Wed, 27 May 2026 21:22:52 +0200 Subject: [PATCH 3/6] feat: smart BuildKit cache miss detection with regression reason Replace the naive unconditional '*cache miss*' annotation with a per-vertex state tracker that only reports a miss when a vertex was previously cached but is no longer. How it works: - After each successful build, the full per-vertex cache state (digest, operation name, input digests, was-cached) is persisted to the BoltDB skip-DB under a new 'vertex-state' bucket, keyed by the canonical target name. - On the next build, before monitoring starts, the previous state is loaded into a digest -> VertexRecord map. - When a vertex executes (cache miss), we check the map: * Not found -> new operation (first run or graph changed) -> silent * Found + was previously a miss -> still a miss -> silent * Found + was previously cached -> REGRESSION, emit annotation: '*cache miss* (previously cached; input changed: )' The changed input is identified by walking vertex.Inputs and finding the first predecessor whose digest either does not appear in the previous state or was itself a miss last time. Requirements: - Requires --auto-skip-db-path (or EARTHLY_AUTO_SKIP_DB_PATH) to activate; no flags needed beyond providing a DB path. - Works independently of --auto-skip (target-level skipping). - Internal BuildKit vertices are excluded from reporting. Changes: - util/buildkitskipper/vertexstate.go: new VertexRecord type, VertexStateStore interface, localVertexStateStore (BoltDB impl) - util/buildkitskipper/local.go: create vertex-state bucket, embed store, expose via VertexStateStore() method - cmd/earthly/bk/buildkitskipper_create.go: add VertexStateStore() to BuildkitSkipper interface - logbus/solvermon/solvermon.go: state loading, collection, smart miss detection, SaveState method, Configure method - logbus/setup/setup.go: updated New() call signature - builder/solver.go: call SaveState after successful build - builder/builder.go: VertexStateStore field in Opt - cmd/earthly/subcmd/build_cmd.go: wire store into SolverMonitor --- builder/builder.go | 2 + builder/solver.go | 5 + cmd/earthly/bk/buildkitskipper_create.go | 1 + cmd/earthly/subcmd/build_cmd.go | 8 ++ logbus/setup/setup.go | 2 +- logbus/solvermon/solvermon.go | 138 +++++++++++++++++++++-- util/buildkitskipper/local.go | 16 ++- util/buildkitskipper/vertexstate.go | 74 ++++++++++++ 8 files changed, 233 insertions(+), 13 deletions(-) create mode 100644 util/buildkitskipper/vertexstate.go diff --git a/builder/builder.go b/builder/builder.go index 638d036a73..8538300da0 100644 --- a/builder/builder.go +++ b/builder/builder.go @@ -23,6 +23,7 @@ import ( "github.com/EarthBuild/earthbuild/logbus/solvermon" "github.com/EarthBuild/earthbuild/regproxy" "github.com/EarthBuild/earthbuild/states" + "github.com/EarthBuild/earthbuild/util/buildkitskipper" "github.com/EarthBuild/earthbuild/util/containerutil" "github.com/EarthBuild/earthbuild/util/dockerutil" "github.com/EarthBuild/earthbuild/util/gatewaycrafter" @@ -68,6 +69,7 @@ type Opt struct { LocalRegistryAddr string GitLFSInclude string BuildkitSkipper bk.BuildkitSkipper + VertexStateStore buildkitskipper.VertexStateStore Parallelism semutil.Semaphore ContainerFrontend containerutil.ContainerFrontend CleanCollection *cleanup.Collection diff --git a/builder/solver.go b/builder/solver.go index db0a7738d1..5cf17772e2 100644 --- a/builder/solver.go +++ b/builder/solver.go @@ -98,6 +98,11 @@ func (s *solver) buildMainMulti( return err } + saveErr := s.logbusSM.SaveState(ctx) + if saveErr != nil { + console.Warnf("failed to save vertex state: %v", saveErr) + } + return nil } diff --git a/cmd/earthly/bk/buildkitskipper_create.go b/cmd/earthly/bk/buildkitskipper_create.go index 4b055372da..5f09cac8fa 100644 --- a/cmd/earthly/bk/buildkitskipper_create.go +++ b/cmd/earthly/bk/buildkitskipper_create.go @@ -12,6 +12,7 @@ import ( type BuildkitSkipper interface { Add(ctx context.Context, target string, key []byte) error Exists(ctx context.Context, key []byte) (bool, error) + VertexStateStore() buildkitskipper.VertexStateStore } // NewBuildkitSkipper returns a local buildkitskipper when localSkipDB is specified. diff --git a/cmd/earthly/subcmd/build_cmd.go b/cmd/earthly/subcmd/build_cmd.go index f3ba277b80..b9b9ead93b 100644 --- a/cmd/earthly/subcmd/build_cmd.go +++ b/cmd/earthly/subcmd/build_cmd.go @@ -26,6 +26,7 @@ import ( "github.com/EarthBuild/earthbuild/domain" "github.com/EarthBuild/earthbuild/inputgraph" "github.com/EarthBuild/earthbuild/states" + "github.com/EarthBuild/earthbuild/util/buildkitskipper" "github.com/EarthBuild/earthbuild/util/cliutil" "github.com/EarthBuild/earthbuild/util/containerutil" "github.com/EarthBuild/earthbuild/util/flagutil" @@ -545,6 +546,12 @@ func (b *Build) ActionBuildImp(ctx context.Context, cmd *cli.Command, flagArgs, logbusSM := b.cli.LogbusSetup().SolverMonitor + var vertexStateStore buildkitskipper.VertexStateStore + if skipDB != nil { + vertexStateStore = skipDB.VertexStateStore() + logbusSM.Configure(ctx, vertexStateStore, target.StringCanonical()) + } + builderOpts := builder.Opt{ BkClient: bkClient, LogBusSolverMonitor: logbusSM, @@ -582,6 +589,7 @@ func (b *Build) ActionBuildImp(ctx context.Context, cmd *cli.Command, flagArgs, GitLogLevel: b.gitLogLevel(), DisableRemoteRegistryProxy: b.cli.Flags().DisableRemoteRegistryProxy, BuildkitSkipper: skipDB, + VertexStateStore: vertexStateStore, NoAutoSkip: b.cli.Flags().NoAutoSkip, } diff --git a/logbus/setup/setup.go b/logbus/setup/setup.go index e8e801684d..eca929cc33 100644 --- a/logbus/setup/setup.go +++ b/logbus/setup/setup.go @@ -56,7 +56,7 @@ func New( forceColor, noColor, disableOngoingUpdates, execStatsTracker, isGitHubActions) bs.Bus.AddRawSubscriber(bs.Formatter) bs.Bus.AddFormattedSubscriber(bs.ConsoleWriter) - bs.SolverMonitor = solvermon.New(bs.Bus) + bs.SolverMonitor = solvermon.New(ctx, bs.Bus, nil, "") if busDebugFile != "" { f, err := os.OpenFile(busDebugFile, os.O_WRONLY|os.O_CREATE|os.O_TRUNC, 0o644) // #nosec G302, G304 diff --git a/logbus/solvermon/solvermon.go b/logbus/solvermon/solvermon.go index 2a27663fb5..6aca20d0ed 100644 --- a/logbus/solvermon/solvermon.go +++ b/logbus/solvermon/solvermon.go @@ -8,6 +8,7 @@ import ( "github.com/EarthBuild/earthbuild/logbus" "github.com/EarthBuild/earthbuild/logstream" + "github.com/EarthBuild/earthbuild/util/buildkitskipper" "github.com/EarthBuild/earthbuild/util/statsstreamparser" "github.com/EarthBuild/earthbuild/util/stringutil" "github.com/EarthBuild/earthbuild/util/vertexmeta" @@ -19,19 +20,71 @@ import ( // SolverMonitor is a buildkit solver monitor. type SolverMonitor struct { - b *logbus.Bus - digests map[digest.Digest]string // digest -> cmdID - vertices map[string]*vertexMonitor // cmdID -> vertexMonitor - mu sync.Mutex + b *logbus.Bus + digests map[digest.Digest]string // digest -> cmdID + vertices map[string]*vertexMonitor // cmdID -> vertexMonitor + store buildkitskipper.VertexStateStore + targetName string + prevState map[string]buildkitskipper.VertexRecord // digest -> VertexRecord from last run + collected []buildkitskipper.VertexRecord + mu sync.Mutex } // New creates a new SolverMonitor. -func New(b *logbus.Bus) *SolverMonitor { - return &SolverMonitor{ - b: b, - digests: make(map[digest.Digest]string), - vertices: make(map[string]*vertexMonitor), +// store and target are optional; pass nil and "" to disable vertex-state tracking. +func New(ctx context.Context, b *logbus.Bus, store buildkitskipper.VertexStateStore, target string) *SolverMonitor { + sm := &SolverMonitor{ + b: b, + digests: make(map[digest.Digest]string), + vertices: make(map[string]*vertexMonitor), + store: store, + targetName: target, + prevState: make(map[string]buildkitskipper.VertexRecord), } + + if store != nil && target != "" { + records, err := store.LoadState(ctx, target) + if err == nil { + for _, r := range records { + sm.prevState[r.Digest] = r + } + } + } + + return sm +} + +// Configure sets the vertex state store and target for this monitor, and loads +// the previous run's state. It is safe to call only before MonitorProgress. +func (sm *SolverMonitor) Configure(ctx context.Context, store buildkitskipper.VertexStateStore, target string) { + if store == nil || target == "" { + return + } + + sm.store = store + sm.targetName = target + + records, err := store.LoadState(ctx, target) + if err == nil { + for _, r := range records { + sm.prevState[r.Digest] = r + } + } +} + +// SaveState persists collected vertex records to the store for the current target. +// It is a no-op when no store or target was configured. +func (sm *SolverMonitor) SaveState(ctx context.Context) error { + if sm.store == nil || sm.targetName == "" { + return nil + } + + sm.mu.Lock() + records := make([]buildkitskipper.VertexRecord, len(sm.collected)) + copy(records, sm.collected) + sm.mu.Unlock() + + return sm.store.SaveState(ctx, sm.targetName, records) } // MonitorProgress processes a channel of buildkit solve statuses. @@ -71,6 +124,16 @@ func (sm *SolverMonitor) MonitorProgress(ctx context.Context, ch chan *client.So } } +// digestStrings converts a slice of digest.Digest to a slice of strings. +func digestStrings(ds []digest.Digest) []string { + out := make([]string, len(ds)) + for i, d := range ds { + out[i] = d.String() + } + + return out +} + func (sm *SolverMonitor) handleBuildkitStatus(status *client.SolveStatus) error { sm.mu.Lock() defer sm.mu.Unlock() @@ -155,7 +218,11 @@ func (sm *SolverMonitor) handleBuildkitStatus(status *client.SolveStatus) error if !vertex.Cached && !vm.cacheMissLogged && !vm.meta.Internal { vm.cacheMissLogged = true - _, _ = vm.cp.Write([]byte("*cache miss*\n"), *vertex.Started, logbus.Stderr) + + cacheMissMsg := sm.buildCacheMissMessage(vertex) + if cacheMissMsg != "" { + _, _ = vm.cp.Write([]byte(cacheMissMsg+"\n"), *vertex.Started, logbus.Stderr) + } } } @@ -167,6 +234,14 @@ func (sm *SolverMonitor) handleBuildkitStatus(status *client.SolveStatus) error continue } + // Collect the vertex record once the vertex is complete. + sm.collected = append(sm.collected, buildkitskipper.VertexRecord{ + Digest: vertex.Digest.String(), + Inputs: digestStrings(vertex.Inputs), + Operation: vm.operation, + WasCached: vertex.Cached, + }) + var status logstream.RunStatus switch { @@ -230,3 +305,46 @@ func (sm *SolverMonitor) handleBuildkitStatus(status *client.SolveStatus) error return nil } + +// buildCacheMissMessage decides whether to emit a cache-miss annotation and, +// if so, returns the message string. It returns "" when the miss should be +// silent (first run, or was already a miss last time). +func (sm *SolverMonitor) buildCacheMissMessage(vertex *client.Vertex) string { + digestStr := vertex.Digest.String() + prev, found := sm.prevState[digestStr] + + if !found { + // New operation (first run or graph changed) — don't log. + return "" + } + + if !prev.WasCached { + // Was already a miss last time — don't log. + return "" + } + + // Previously cached but now a miss: find which input changed. + changedInput := sm.findChangedInput(vertex.Inputs) + + return "*cache miss* (previously cached; input changed: " + changedInput + ")" +} + +// findChangedInput scans the given input digests and returns the Operation of +// the first input that either (a) does not appear in prevState or (b) was not +// cached last time. Returns "unknown" when no specific input can be identified. +func (sm *SolverMonitor) findChangedInput(inputs []digest.Digest) string { + for _, inp := range inputs { + inpStr := inp.String() + prev, ok := sm.prevState[inpStr] + + if !ok || !prev.WasCached { + if ok && prev.Operation != "" { + return prev.Operation + } + + return "unknown" + } + } + + return "unknown" +} diff --git a/util/buildkitskipper/local.go b/util/buildkitskipper/local.go index cf4ab51363..7f135d321b 100644 --- a/util/buildkitskipper/local.go +++ b/util/buildkitskipper/local.go @@ -25,6 +25,11 @@ func NewLocal(path string) (*LocalBuildkitSkipper, error) { return fmt.Errorf("could not create builds bucket: %w", err) } + _, err = tx.CreateBucketIfNotExists(vertexStateBucket) + if err != nil { + return fmt.Errorf("could not create vertex-state bucket: %w", err) + } + return nil }) if err != nil { @@ -32,13 +37,20 @@ func NewLocal(path string) (*LocalBuildkitSkipper, error) { } return &LocalBuildkitSkipper{ - db: db, + db: db, + vertexStateStore: &localVertexStateStore{db: db}, }, nil } // LocalBuildkitSkipper uses BoltDB to store & retrieve auto-skip hashes. type LocalBuildkitSkipper struct { - db *bolt.DB + db *bolt.DB + vertexStateStore *localVertexStateStore +} + +// VertexStateStore returns the VertexStateStore for persisting per-vertex cache state. +func (l *LocalBuildkitSkipper) VertexStateStore() VertexStateStore { + return l.vertexStateStore } // Add a new hash value (org & target are ignored in this implementation). diff --git a/util/buildkitskipper/vertexstate.go b/util/buildkitskipper/vertexstate.go new file mode 100644 index 0000000000..1370cae307 --- /dev/null +++ b/util/buildkitskipper/vertexstate.go @@ -0,0 +1,74 @@ +package buildkitskipper + +import ( + "context" + "encoding/json" + "fmt" + + bolt "go.etcd.io/bbolt" +) + +var vertexStateBucket = []byte("vertex-state") + +// VertexRecord captures the cache state of one BuildKit vertex from a build run. +type VertexRecord struct { + // Digest is the stable SHA256 identity of this LLB operation. + Digest string + // Operation is the human-readable command string (e.g. "RUN apt-get install curl"). + Operation string + // Inputs holds the digests of predecessor vertices, in order. + Inputs []string + // WasCached is true if BuildKit served this vertex from cache. + WasCached bool +} + +// VertexStateStore persists and retrieves the per-vertex cache state for a target across runs. +type VertexStateStore interface { + // SaveState persists the vertex records for a target after a successful build. + SaveState(ctx context.Context, target string, records []VertexRecord) error + // LoadState retrieves the vertex records from the previous build for a target. + // Returns nil, nil if no prior state exists. + LoadState(ctx context.Context, target string) ([]VertexRecord, error) +} + +// localVertexStateStore is a BoltDB-backed implementation of VertexStateStore. +type localVertexStateStore struct { + db *bolt.DB +} + +// SaveState persists the vertex records for a target after a successful build. +func (s *localVertexStateStore) SaveState(_ context.Context, target string, records []VertexRecord) error { + data, err := json.Marshal(records) + if err != nil { + return fmt.Errorf("marshal vertex records: %w", err) + } + + return s.db.Update(func(tx *bolt.Tx) error { + err := tx.Bucket(vertexStateBucket).Put([]byte(target), data) + if err != nil { + return fmt.Errorf("save vertex state for %s: %w", target, err) + } + + return nil + }) +} + +// LoadState retrieves the vertex records from the previous build for a target. +// Returns nil, nil if no prior state exists. +func (s *localVertexStateStore) LoadState(_ context.Context, target string) ([]VertexRecord, error) { + var records []VertexRecord + + err := s.db.View(func(tx *bolt.Tx) error { + data := tx.Bucket(vertexStateBucket).Get([]byte(target)) + if data == nil { + return nil + } + + return json.Unmarshal(data, &records) + }) + if err != nil { + return nil, fmt.Errorf("load vertex state for %s: %w", target, err) + } + + return records, nil +} From 12d6f9e1a8656a4725eeb847163739398f85e550 Mon Sep 17 00:00:00 2001 From: Daniel Schlegel Date: Wed, 27 May 2026 21:46:22 +0200 Subject: [PATCH 4/6] fix: only annotate earth-managed vertices; add tests; fix EARTHLY refs - Filter cache-miss annotations to vertices with a non-empty CommandID (set only by earth's converter). This excludes BuildKit-internal vertices such as exporters ('exporting outputs'), cache import/export, and context-transfer vertices that always execute and carry no meaningful miss reason. - Fix stray 'earthly' reference in a comment (should be 'earth'). - Add solvermon_cachemiss_test.go covering: * buildCacheMissMessage: no history (silent), previously-miss (silent), previously-cached with no inputs (unknown reason), with changed input (operation named), with newly-added input (unknown), with all inputs still cached (unknown / command itself changed) * handleBuildkitStatus: non-earth vertices (exporter) are never annotated even when seeded as previously-cached * handleBuildkitStatus: earth-managed vertex (with CommandID) IS annotated when it was previously cached * VertexRecord collection on vertex completion * VertexStateStore SaveState/LoadState round-trip via BoltDB * VertexStateStore LoadState returns nil for unknown target --- inputgraph/loader.go | 2 +- logbus/solvermon/solvermon.go | 6 +- logbus/solvermon/solvermon_cachemiss_test.go | 366 +++++++++++++++++++ 3 files changed, 372 insertions(+), 2 deletions(-) create mode 100644 logbus/solvermon/solvermon_cachemiss_test.go diff --git a/inputgraph/loader.go b/inputgraph/loader.go index 9cadc488f7..396aa9a431 100644 --- a/inputgraph/loader.go +++ b/inputgraph/loader.go @@ -98,7 +98,7 @@ func newLoader(opt HashOpt) *loader { primaryTarget: true, logTarget: opt.Target.StringCanonical(), } - // Log the built-in args (platform, earthly version, etc.) that were just + // Log the built-in args (platform, earth version, etc.) that were just // hashed above so they appear in the hash log. l.logInput("builtin args", fmt.Sprintf("%+v", opt.BuiltinArgs)) diff --git a/logbus/solvermon/solvermon.go b/logbus/solvermon/solvermon.go index 6aca20d0ed..4e652a7396 100644 --- a/logbus/solvermon/solvermon.go +++ b/logbus/solvermon/solvermon.go @@ -216,7 +216,11 @@ func (sm *SolverMonitor) handleBuildkitStatus(status *client.SolveStatus) error if vertex.Started != nil { vm.cp.SetStart(*vertex.Started) - if !vertex.Cached && !vm.cacheMissLogged && !vm.meta.Internal { + // Only annotate vertices that earth's converter created ahead of + // time (identified by a non-empty CommandID). This excludes + // BuildKit-internal vertices (exporters, cache, context transfer) + // that are always re-executed and have no meaningful miss reason. + if !vertex.Cached && !vm.cacheMissLogged && meta.CommandID != "" { vm.cacheMissLogged = true cacheMissMsg := sm.buildCacheMissMessage(vertex) diff --git a/logbus/solvermon/solvermon_cachemiss_test.go b/logbus/solvermon/solvermon_cachemiss_test.go new file mode 100644 index 0000000000..b2354628bc --- /dev/null +++ b/logbus/solvermon/solvermon_cachemiss_test.go @@ -0,0 +1,366 @@ +package solvermon + +import ( + "context" + "encoding/base64" + "encoding/json" + "testing" + "time" + + "github.com/EarthBuild/earthbuild/domain" + "github.com/EarthBuild/earthbuild/logbus" + "github.com/EarthBuild/earthbuild/util/buildkitskipper" + "github.com/EarthBuild/earthbuild/util/vertexmeta" + "github.com/moby/buildkit/client" + "github.com/opencontainers/go-digest" + "github.com/stretchr/testify/require" +) + +// vertexMetaPrefix encodes a VertexMeta as a BuildKit vertex name prefix so +// that ParseFromVertexPrefix can parse it back. +func vertexMetaPrefix(vm *vertexmeta.VertexMeta, operation string) string { + dt, err := json.Marshal(vm) + if err != nil { + panic(err) + } + + return "[" + base64.StdEncoding.EncodeToString(dt) + "] " + operation +} + +// sha returns a deterministic digest for a given string label. +func sha(label string) digest.Digest { + return digest.FromString(label) +} + +// makeMonitorWithState builds a SolverMonitor whose prevState is seeded from +// the given records, without touching the filesystem. +func makeMonitorWithState(records []buildkitskipper.VertexRecord) *SolverMonitor { + sm := &SolverMonitor{ + prevState: make(map[string]buildkitskipper.VertexRecord), + } + + for _, r := range records { + sm.prevState[r.Digest] = r + } + + return sm +} + +// --------------------------------------------------------------------------- +// buildCacheMissMessage +// --------------------------------------------------------------------------- + +func TestBuildCacheMissMessage_NoHistory(t *testing.T) { + t.Parallel() + + // Vertex never seen before → silent (first run) + sm := makeMonitorWithState(nil) + v := &client.Vertex{Digest: sha("new-op"), Inputs: nil} + require.Empty(t, sm.buildCacheMissMessage(v)) +} + +func TestBuildCacheMissMessage_PreviouslyMiss(t *testing.T) { + t.Parallel() + + // Vertex existed last run but was already a miss → silent + d := sha("op-a") + sm := makeMonitorWithState([]buildkitskipper.VertexRecord{ + {Digest: d.String(), Operation: "RUN echo hello", WasCached: false}, + }) + v := &client.Vertex{Digest: d, Inputs: nil} + require.Empty(t, sm.buildCacheMissMessage(v)) +} + +func TestBuildCacheMissMessage_PreviouslyCached_NoInputs(t *testing.T) { + t.Parallel() + + // Vertex was cached before, no inputs → report miss with "unknown" reason + d := sha("op-b") + sm := makeMonitorWithState([]buildkitskipper.VertexRecord{ + {Digest: d.String(), Operation: "RUN apt-get update", WasCached: true}, + }) + v := &client.Vertex{Digest: d, Inputs: nil} + msg := sm.buildCacheMissMessage(v) + require.Contains(t, msg, "*cache miss*") + require.Contains(t, msg, "previously cached") + require.Contains(t, msg, "unknown") +} + +func TestBuildCacheMissMessage_PreviouslyCached_InputChanged(t *testing.T) { + t.Parallel() + + // Parent op was a miss last run → that's the changed input + parentDigest := sha("parent-op") + childDigest := sha("child-op") + + sm := makeMonitorWithState([]buildkitskipper.VertexRecord{ + {Digest: parentDigest.String(), Operation: "COPY ./src /src", WasCached: false}, + {Digest: childDigest.String(), Operation: "RUN go build", WasCached: true}, + }) + + v := &client.Vertex{ + Digest: childDigest, + Inputs: []digest.Digest{parentDigest}, + } + msg := sm.buildCacheMissMessage(v) + require.Contains(t, msg, "*cache miss*") + require.Contains(t, msg, "previously cached") + require.Contains(t, msg, "COPY ./src /src") +} + +func TestBuildCacheMissMessage_PreviouslyCached_InputNewlyAdded(t *testing.T) { + t.Parallel() + + // One input never seen before (newly added to graph) + newInputDigest := sha("new-input") + childDigest := sha("child-op2") + + sm := makeMonitorWithState([]buildkitskipper.VertexRecord{ + {Digest: childDigest.String(), Operation: "RUN make", WasCached: true}, + // newInputDigest is absent from prevState + }) + + v := &client.Vertex{ + Digest: childDigest, + Inputs: []digest.Digest{newInputDigest}, + } + msg := sm.buildCacheMissMessage(v) + require.Contains(t, msg, "*cache miss*") + require.Contains(t, msg, "unknown") +} + +func TestBuildCacheMissMessage_AllInputsPreviouslyCached(t *testing.T) { + t.Parallel() + + // All inputs were cached → miss reason is "unknown" (command text itself changed) + inputDigest := sha("stable-input") + childDigest := sha("child-op3") + + sm := makeMonitorWithState([]buildkitskipper.VertexRecord{ + {Digest: inputDigest.String(), Operation: "FROM alpine", WasCached: true}, + {Digest: childDigest.String(), Operation: "RUN echo old", WasCached: true}, + }) + + v := &client.Vertex{ + Digest: childDigest, + Inputs: []digest.Digest{inputDigest}, + } + msg := sm.buildCacheMissMessage(v) + require.Contains(t, msg, "*cache miss*") + require.Contains(t, msg, "unknown") +} + +// --------------------------------------------------------------------------- +// handleBuildkitStatus — filtering: only earth-managed vertices get annotated +// --------------------------------------------------------------------------- + +// exportingOutputsVertex is the BuildKit vertex name used by the exporter, +// which has no VertexMeta prefix and must never receive cache-miss annotations. +const exportingOutputsVertex = "exporting outputs" + +// newTestBus creates a minimal logbus.Bus for testing. +func newTestBus(t *testing.T) *logbus.Bus { + t.Helper() + + return logbus.New() +} + +func TestHandleBuildkitStatus_SkipsNonEarthVertices(t *testing.T) { + t.Parallel() + + // Vertices without a CommandID (exporter, context, cache vertices) must + // never produce a cache-miss annotation even when they were "seen before". + b := newTestBus(t) + sm := &SolverMonitor{ + b: b, + digests: make(map[digest.Digest]string), + vertices: make(map[string]*vertexMonitor), + prevState: make(map[string]buildkitskipper.VertexRecord), + } + + exporterDigest := sha("exporting-outputs") + + // Seed prevState as if this digest was previously cached + sm.prevState[exporterDigest.String()] = buildkitskipper.VertexRecord{ + Digest: exporterDigest.String(), + Operation: exportingOutputsVertex, + WasCached: true, + } + + now := time.Now() + + status := &client.SolveStatus{ + Vertexes: []*client.Vertex{ + { + Name: exportingOutputsVertex, + Digest: exporterDigest, + Started: &now, + Cached: false, + }, + }, + } + + err := sm.handleBuildkitStatus(status) + require.NoError(t, err) + + // The vertex monitor must NOT have cacheMissLogged set + for _, vm := range sm.vertices { + require.False(t, vm.cacheMissLogged, + "exporter vertex should not have cache miss logged") + } +} + +func TestHandleBuildkitStatus_AnnotatesEarthVertex(t *testing.T) { + t.Parallel() + + b := newTestBus(t) + + // Pre-create the logbus command as the converter would. + run := b.Run() + + cmdID := "target-1/cmd-0" + targetID := "target-1" + + _, err := run.NewTarget(targetID, domain.Target{}, nil, "", "") + require.NoError(t, err) + + _, err = run.NewCommand(cmdID, "RUN echo hello", targetID, "+my-target", "", false, false, false, nil, "", "", "") + require.NoError(t, err) + + sm := &SolverMonitor{ + b: b, + digests: make(map[digest.Digest]string), + vertices: make(map[string]*vertexMonitor), + prevState: make(map[string]buildkitskipper.VertexRecord), + } + + opDigest := sha("run-echo-hello") + + // Seed: this vertex was previously cached + sm.prevState[opDigest.String()] = buildkitskipper.VertexRecord{ + Digest: opDigest.String(), + Operation: "RUN echo hello", + WasCached: true, + } + + now := time.Now() + + // Build a vertex name with a proper VertexMeta (as the converter embeds) + vm := &vertexmeta.VertexMeta{ + CommandID: cmdID, + TargetID: targetID, + TargetName: "+my-target", + } + vertexName := vertexMetaPrefix(vm, "RUN echo hello") + + status := &client.SolveStatus{ + Vertexes: []*client.Vertex{ + { + Name: vertexName, + Digest: opDigest, + Started: &now, + Cached: false, + }, + }, + } + + err = sm.handleBuildkitStatus(status) + require.NoError(t, err) + + // The vertex monitor must have cacheMissLogged set + for _, mon := range sm.vertices { + if mon.meta.CommandID == cmdID { + require.True(t, mon.cacheMissLogged, + "earth-managed vertex should have cache miss logged") + + return + } + } + + t.Fatal("expected to find the earth-managed vertex monitor") +} + +// --------------------------------------------------------------------------- +// VertexRecord collection +// --------------------------------------------------------------------------- + +func TestHandleBuildkitStatus_CollectsRecordsOnCompletion(t *testing.T) { + t.Parallel() + + b := newTestBus(t) + sm := &SolverMonitor{ + b: b, + digests: make(map[digest.Digest]string), + vertices: make(map[string]*vertexMonitor), + prevState: make(map[string]buildkitskipper.VertexRecord), + } + + d := sha("op-collect") + now := time.Now() + completed := now.Add(time.Second) + + status := &client.SolveStatus{ + Vertexes: []*client.Vertex{ + { + Name: exportingOutputsVertex, + Digest: d, + Started: &now, + Completed: &completed, + Cached: true, + }, + }, + } + + err := sm.handleBuildkitStatus(status) + require.NoError(t, err) + require.Len(t, sm.collected, 1) + require.Equal(t, d.String(), sm.collected[0].Digest) + require.True(t, sm.collected[0].WasCached) +} + +// --------------------------------------------------------------------------- +// VertexStateStore: SaveState / LoadState round-trip +// --------------------------------------------------------------------------- + +func TestVertexStateStore_RoundTrip(t *testing.T) { + t.Parallel() + + dir := t.TempDir() + + store, err := buildkitskipper.NewLocal(dir + "/test.db") + require.NoError(t, err) + + vss := store.VertexStateStore() + ctx := context.Background() + + records := []buildkitskipper.VertexRecord{ + {Digest: sha("a").String(), Operation: "FROM alpine", Inputs: nil, WasCached: true}, + {Digest: sha("b").String(), Operation: "RUN apt-get update", Inputs: []string{sha("a").String()}, WasCached: false}, + } + + err = vss.SaveState(ctx, "./+my-target", records) + require.NoError(t, err) + + loaded, err := vss.LoadState(ctx, "./+my-target") + require.NoError(t, err) + require.Len(t, loaded, 2) + require.Equal(t, records[0].Digest, loaded[0].Digest) + require.Equal(t, records[0].Operation, loaded[0].Operation) + require.True(t, loaded[0].WasCached) + require.Equal(t, records[1].Operation, loaded[1].Operation) + require.False(t, loaded[1].WasCached) + require.Equal(t, records[1].Inputs, loaded[1].Inputs) +} + +func TestVertexStateStore_MissingTarget(t *testing.T) { + t.Parallel() + + dir := t.TempDir() + + store, err := buildkitskipper.NewLocal(dir + "/test.db") + require.NoError(t, err) + + loaded, err := store.VertexStateStore().LoadState(context.Background(), "./+nonexistent") + require.NoError(t, err) + require.Nil(t, loaded) +} From a1756141972ee62b8555611c598517d05223f793 Mon Sep 17 00:00:00 2001 From: Daniel Schlegel Date: Wed, 27 May 2026 21:50:14 +0200 Subject: [PATCH 5/6] docs: document cache miss reason feature Add 'Cache miss reasons' section to caching-in-earthfiles.md covering: - BuildKit layer cache miss annotations (*cache miss* inline output), how to activate via --auto-skip-db-path, and how the changed input is identified - Auto-skip input log (--verbose on a miss prints every hashed input) Add 'Local auto-skip database' subsection to managing-cache.md documenting --auto-skip-db-path / EARTH_AUTO_SKIP_DB_PATH, linking to the cache miss annotation feature, and explaining how to reset it. --- docs/caching/caching-in-earthfiles.md | 38 +++++++++++++++++++++++++++ docs/caching/managing-cache.md | 12 ++++++++- 2 files changed, 49 insertions(+), 1 deletion(-) diff --git a/docs/caching/caching-in-earthfiles.md b/docs/caching/caching-in-earthfiles.md index 2f03b8f5c2..64f0eee32b 100644 --- a/docs/caching/caching-in-earthfiles.md +++ b/docs/caching/caching-in-earthfiles.md @@ -214,3 +214,41 @@ If you have already optimized your cache by maximizing its size, declaring argum ### Debugging tips If you are experiencing caching issues and have ruled out the above common situations, we would love to hear from you. Please open an issue in the [Earthly GitHub repository](https://github.com/earthbuild/earthbuild). + +### Cache miss reasons + +Earth provides two levels of cache miss visibility, one for each caching layer. + +#### BuildKit layer cache misses + +When a `RUN`, `COPY`, or other BuildKit operation executes instead of being served from cache, Earth annotates its output with: + +``` +*cache miss* (previously cached; input changed: COPY ./src /app/src) +``` + +This annotation only appears when the operation **was cached on a previous run** but is no longer — i.e. a regression, not a first-ever execution. First runs and operations that were already a miss last time are silent. + +To activate this feature, provide a local state database via the `--auto-skip-db-path` flag (or `EARTH_AUTO_SKIP_DB_PATH` env var). Earth records the cache state of every operation after each successful build and compares it on the next run: + +```bash +earth --auto-skip-db-path ~/.earth/skip.db +my-target +``` + +The changed input shown in the annotation is identified by walking the operation's input chain and finding the first predecessor that was itself a miss. If no specific predecessor can be identified, the reason is reported as `unknown`. + +#### Auto-skip input log + +For targets using `--auto-skip`, Earth can explain which hashed inputs contributed to the target's cache key. When a cache miss occurs at the auto-skip level, running with `--verbose` prints the full ordered list of inputs: + +``` +auto-skip | cache miss for ./+my-target — hashed inputs: +auto-skip | builtin args {EarthVersion:dev ...} +auto-skip | VERSION [0.8] +auto-skip | FROM alpine +auto-skip | ARG MESSAGE=hello +auto-skip | RUN echo "$MESSAGE" +auto-skip | dep target ./+base (hash: 3f2a8b...) +``` + +Every input that contributes to the hash is listed — `ARG` values, `RUN` commands, `COPY` file contents, dependency target hashes, build arg overrides, and more. This makes it straightforward to understand exactly what would need to change for the target to be skipped on the next run. diff --git a/docs/caching/managing-cache.md b/docs/caching/managing-cache.md index 6c76d10b2e..b2f91a61c0 100644 --- a/docs/caching/managing-cache.md +++ b/docs/caching/managing-cache.md @@ -65,7 +65,7 @@ To cause a satellite to restart with a fresh cache, you can use the command `ear ## Auto-skip cache -The auto-skip cache is a cache that is used to skip large parts of a build in certain situations. It is used by the `earthly --auto-skip` and `BUILD --auto-skip` commands. +The auto-skip cache is a cache that is used to skip large parts of a build in certain situations. It is used by the `earth --auto-skip` and `BUILD --auto-skip` commands. Unlike the layer cache and the cache mounts, the auto-skip cache is global and is stored in a cloud database. @@ -74,3 +74,13 @@ To clear the entire auto-skip cache for your Earthly org, you can use the comman To clear the auto-skip cache for an entire repository, you can use the command `earthly prune-auto-skip --path github.com/foo/bar --deep`. To clear the auto-skip cache for a specific target, you can use the command `earthly prune-auto-skip --path github.com/foo/bar --target +my-target`. + +### Local auto-skip database + +For local development, Earth can maintain a lightweight on-disk skip database instead of relying on the cloud. Pass a file path via `--auto-skip-db-path` (or the `EARTH_AUTO_SKIP_DB_PATH` environment variable): + +```bash +earth --auto-skip-db-path ~/.earth/skip.db +my-target +``` + +This database also powers the [BuildKit cache miss annotations](./caching-in-earthfiles.md#buildkit-layer-cache-misses) feature, which identifies which operation caused a previously-cached layer to become a miss. The database is created automatically on first use. To reset it, simply delete the file. From 69dff834c6be24897599d90bbe68b2e7d7334f3c Mon Sep 17 00:00:00 2001 From: Daniel Schlegel Date: Thu, 28 May 2026 08:32:47 +0200 Subject: [PATCH 6/6] feat: hash log diff for Earthfile-level cache miss reasons - Add HashLogStore (BoltDB-backed) to persist per-target hash input records across builds - Add DiffHashLog to compare prev/current hash logs and produce human-readable +/-/~ diff lines - Enrich VertexRecord and VertexMeta with ActiveArgs, BaseImageRef, and CopiedPaths so vertex-level diffs carry richer context - Compute hash log diff unconditionally in build_cmd (no --auto-skip required) and surface via SolverMonitor.SetHashLogDiff - Default skip-DB path to ~/.earth/vertex-state.db when no explicit --local-skip-db flag is set --- Earthfile | 3 + cmd/earthly/bk/buildkitskipper_create.go | 1 + cmd/earthly/subcmd/build_cmd.go | 74 +++++++- docs/caching/caching-in-earthfiles.md | 2 +- docs/caching/managing-cache.md | 2 +- earthfile2llb/converter.go | 48 ++++- inputgraph/loader.go | 16 +- logbus/solvermon/solvermon.go | 175 ++++++++++++++++--- logbus/solvermon/solvermon_cachemiss_test.go | 128 ++++++++++---- util/buildkitskipper/hashdiff.go | 114 ++++++++++++ util/buildkitskipper/hashdiff_test.go | 135 ++++++++++++++ util/buildkitskipper/hashlog.go | 74 ++++++++ util/buildkitskipper/local.go | 12 ++ util/buildkitskipper/vertexstate.go | 15 +- util/vertexmeta/vertexmeta.go | 15 +- 15 files changed, 723 insertions(+), 91 deletions(-) create mode 100644 util/buildkitskipper/hashdiff.go create mode 100644 util/buildkitskipper/hashdiff_test.go create mode 100644 util/buildkitskipper/hashlog.go diff --git a/Earthfile b/Earthfile index bc80dd8f24..f555cfe3c2 100644 --- a/Earthfile +++ b/Earthfile @@ -121,6 +121,9 @@ lint-scripts-auth-test: # lint-scripts runs the shellcheck package to detect potential errors in shell scripts lint-scripts: + ARG hello="jjhhjj" + RUN echo "vvvv" + BUILD +lint-scripts-auth-test BUILD +lint-scripts-misc diff --git a/cmd/earthly/bk/buildkitskipper_create.go b/cmd/earthly/bk/buildkitskipper_create.go index 5f09cac8fa..7360f80e35 100644 --- a/cmd/earthly/bk/buildkitskipper_create.go +++ b/cmd/earthly/bk/buildkitskipper_create.go @@ -13,6 +13,7 @@ type BuildkitSkipper interface { Add(ctx context.Context, target string, key []byte) error Exists(ctx context.Context, key []byte) (bool, error) VertexStateStore() buildkitskipper.VertexStateStore + HashLogStore() buildkitskipper.HashLogStore } // NewBuildkitSkipper returns a local buildkitskipper when localSkipDB is specified. diff --git a/cmd/earthly/subcmd/build_cmd.go b/cmd/earthly/subcmd/build_cmd.go index b9b9ead93b..8d2f416da3 100644 --- a/cmd/earthly/subcmd/build_cmd.go +++ b/cmd/earthly/subcmd/build_cmd.go @@ -334,7 +334,17 @@ func (b *Build) ActionBuildImp(ctx context.Context, cmd *cli.Command, flagArgs, return err } - skipDB, err := bk.NewBuildkitSkipper(b.cli.Flags().LocalSkipDB) + skipDBPath := b.cli.Flags().LocalSkipDB + if skipDBPath == "" { + // Default to ~/.earth/vertex-state.db so cache miss reasons are always + // recorded and surfaced without requiring an explicit flag. + earthDir, dirErr := cliutil.GetOrCreateEarthDir(b.cli.Flags().InstallationName) + if dirErr == nil { + skipDBPath = filepath.Join(earthDir, "vertex-state.db") + } + } + + skipDB, err := bk.NewBuildkitSkipper(skipDBPath) if err != nil { b.cli.Console().WithPrefix(autoSkipPrefix).Warnf("Failed to initialize auto-skip database: %v", err) } @@ -552,6 +562,10 @@ func (b *Build) ActionBuildImp(ctx context.Context, cmd *cli.Command, flagArgs, logbusSM.Configure(ctx, vertexStateStore, target.StringCanonical()) } + // Compute the Earthfile hash log unconditionally and diff against the + // previous run. This powers cache miss reasons without requiring --auto-skip. + saveHashLogFn := b.computeAndSetHashLogDiff(ctx, skipDB, target, overridingVars, logbusSM) + builderOpts := builder.Opt{ BkClient: bkClient, LogBusSolverMonitor: logbusSM, @@ -644,6 +658,10 @@ func (b *Build) ActionBuildImp(ctx context.Context, cmd *cli.Command, flagArgs, addHashFn() } + if saveHashLogFn != nil { + saveHashLogFn() + } + return nil } @@ -863,6 +881,60 @@ func (b *Build) platformResolver( return platr, nil } +// computeAndSetHashLogDiff hashes the target's Earthfile inputs, diffs them +// against the stored log from the previous run, and calls SetHashLogDiff on +// the solver monitor so cache miss annotations can show what changed. +// Returns a save function that must be called after a successful build. +func (b *Build) computeAndSetHashLogDiff( + ctx context.Context, + skipDB bk.BuildkitSkipper, + target domain.Target, + overridingVars *variables.Scope, + sm interface{ SetHashLogDiff([]string) }, +) func() { + if skipDB == nil || target.IsRemote() { + return nil + } + + _, stats, err := inputgraph.HashTarget(ctx, inputgraph.HashOpt{ + Target: target, + Console: b.cli.Console(), + CI: b.cli.Flags().CI, + BuiltinArgs: variables.DefaultArgs{EarthVersion: b.cli.Version(), EarthBuildSha: b.cli.GitSHA()}, + OverridingVars: overridingVars, + }) + if err != nil { + // Non-fatal: hash log diff is best-effort. + return nil + } + + if len(stats.HashLog) == 0 { + return nil + } + + // Convert HashLog to HashInputRecords. + current := make([]buildkitskipper.HashInputRecord, len(stats.HashLog)) + for i, e := range stats.HashLog { + current[i] = buildkitskipper.HashInputRecord{Label: e.Label, Detail: e.Detail} + } + + // Load previous log and compute diff. + store := skipDB.HashLogStore() + key := target.StringCanonical() + + prev, err := store.LoadHashLog(ctx, key) + if err == nil && len(prev) > 0 { + diff := buildkitskipper.DiffHashLog(prev, current) + if !diff.IsEmpty() { + sm.SetHashLogDiff(diff.Lines()) + } + } + + return func() { + _ = store.SaveHashLog(ctx, key, current) + } +} + func (b *Build) initAutoSkip( ctx context.Context, skipDB bk.BuildkitSkipper, target domain.Target, overridingVars *variables.Scope, ) (func(), bool, error) { diff --git a/docs/caching/caching-in-earthfiles.md b/docs/caching/caching-in-earthfiles.md index 64f0eee32b..647af618aa 100644 --- a/docs/caching/caching-in-earthfiles.md +++ b/docs/caching/caching-in-earthfiles.md @@ -229,7 +229,7 @@ When a `RUN`, `COPY`, or other BuildKit operation executes instead of being serv This annotation only appears when the operation **was cached on a previous run** but is no longer — i.e. a regression, not a first-ever execution. First runs and operations that were already a miss last time are silent. -To activate this feature, provide a local state database via the `--auto-skip-db-path` flag (or `EARTH_AUTO_SKIP_DB_PATH` env var). Earth records the cache state of every operation after each successful build and compares it on the next run: +To activate this feature, provide a local state database via the `--auto-skip-db-path` flag (or `EARTHLY_AUTO_SKIP_DB_PATH` env var). Earth records the cache state of every operation after each successful build and compares it on the next run: ```bash earth --auto-skip-db-path ~/.earth/skip.db +my-target diff --git a/docs/caching/managing-cache.md b/docs/caching/managing-cache.md index b2f91a61c0..ad2a4d9886 100644 --- a/docs/caching/managing-cache.md +++ b/docs/caching/managing-cache.md @@ -77,7 +77,7 @@ To clear the auto-skip cache for a specific target, you can use the command `ear ### Local auto-skip database -For local development, Earth can maintain a lightweight on-disk skip database instead of relying on the cloud. Pass a file path via `--auto-skip-db-path` (or the `EARTH_AUTO_SKIP_DB_PATH` environment variable): +For local development, Earth can maintain a lightweight on-disk skip database instead of relying on the cloud. Pass a file path via `--auto-skip-db-path` (or the `EARTHLY_AUTO_SKIP_DB_PATH` environment variable): ```bash earth --auto-skip-db-path ~/.earth/skip.db +my-target diff --git a/earthfile2llb/converter.go b/earthfile2llb/converter.go index e300753cbc..3977e406e8 100644 --- a/earthfile2llb/converter.go +++ b/earthfile2llb/converter.go @@ -613,7 +613,7 @@ func (c *Converter) CopyArtifactLocal( return errors.Wrapf(err, "parse artifact name %s", artifactName) } - prefix, cmdID, err := c.newVertexMeta(ctx, false, false, false, nil) + prefix, cmdID, err := c.newVertexMetaWithCopiedPaths(ctx, false, false, false, nil, []string{artifact.String()}) if err != nil { return err } @@ -687,7 +687,7 @@ func (c *Converter) CopyArtifact( return errors.Wrapf(err, "parse artifact name %s", artifactName) } - prefix, cmdID, err := c.newVertexMeta(ctx, false, false, false, nil) + prefix, cmdID, err := c.newVertexMetaWithCopiedPaths(ctx, false, false, false, nil, []string{artifact.String()}) if err != nil { return err } @@ -755,7 +755,7 @@ func (c *Converter) CopyClassical( c.nonSaveCommand() - prefix, _, err := c.newVertexMeta(ctx, false, false, false, nil) + prefix, _, err := c.newVertexMetaWithCopiedPaths(ctx, false, false, false, nil, srcs) if err != nil { return err } @@ -3247,6 +3247,26 @@ func (c *Converter) newVertexMeta( } } + // Collect all active (non-builtin) args for cache-miss diagnostics. + // Builtins (prefixed with EARTH_ or EARTHLY_) are excluded to keep the + // vertex name compact and focused on user-controlled values. + activeArgs := make(map[string]string) + + for _, arg := range c.varCollection.SortedVariables(variables.WithActive()) { + if strings.HasPrefix(arg, "EARTH_") || strings.HasPrefix(arg, "EARTHLY_") { + continue + } + + v, ok := c.varCollection.Get(arg, variables.WithActive()) + if ok { + activeArgs[arg] = v + } + } + + if len(activeArgs) == 0 { + activeArgs = nil + } + platform := c.platr.Materialize(c.platr.Current()) platformStr := platform.String() isNativePlatform := c.platr.PlatformEquals(platform, platutil.NativePlatform) @@ -3299,8 +3319,30 @@ func (c *Converter) newVertexMeta( Secrets: secrets, Internal: internal, Runner: c.opt.Runner, + ActiveArgs: activeArgs, + } + + return vm.ToVertexPrefix(), cmdID, nil +} + +// newVertexMetaWithCopiedPaths is like newVertexMeta but also records the +// source paths of a COPY operation for cache-miss diagnostics. +func (c *Converter) newVertexMetaWithCopiedPaths( + ctx context.Context, local, interactive, internal bool, secrets []string, copiedPaths []string, +) (string, string, error) { + prefix, cmdID, err := c.newVertexMeta(ctx, local, interactive, internal, secrets) + if err != nil { + return "", "", err } + if len(copiedPaths) == 0 { + return prefix, cmdID, nil + } + + // Re-parse the encoded prefix, add CopiedPaths, re-encode. + vm, _ := vertexmeta.ParseFromVertexPrefix(prefix + " _") + vm.CopiedPaths = copiedPaths + return vm.ToVertexPrefix(), cmdID, nil } diff --git a/inputgraph/loader.go b/inputgraph/loader.go index 396aa9a431..c0ae2b5669 100644 --- a/inputgraph/loader.go +++ b/inputgraph/loader.go @@ -107,20 +107,14 @@ func newLoader(opt HashOpt) *loader { // logInput appends a HashInput to the shared Stats.HashLog. It is safe to call // from any loader in the dependency chain because all loaders share the same -// *Stats pointer. +// *Stats pointer. Only entries from the primary (top-level) target are logged; +// sub-target entries are captured via their "dep target" entry instead. func (l *loader) logInput(label, detail string) { - if l.stats == nil { + if l.stats == nil || !l.primaryTarget { return } - entry := HashInput{Label: label, Detail: detail} - if l.logTarget != "" && !l.primaryTarget { - // Prefix with the dependency target name so readers can tell which - // dependency contributed the entry. - entry.Detail = fmt.Sprintf("%s (dep: %s)", detail, l.logTarget) - } - - l.stats.HashLog = append(l.stats.HashLog, entry) + l.stats.HashLog = append(l.stats.HashLog, HashInput{Label: label, Detail: detail}) } func (l *loader) handleFrom(ctx context.Context, cmd spec.Command) error { @@ -1126,7 +1120,7 @@ func (l *loader) loadTargetFromString( } l.hasher.HashBytes(hash) - l.logInput("dep target", fmt.Sprintf("%s (hash: %x)", target.StringCanonical(), hash)) + l.logInput("dep target", fmt.Sprintf("+%s (hash: %x)", target.Target, hash)) return nil } diff --git a/logbus/solvermon/solvermon.go b/logbus/solvermon/solvermon.go index 4e652a7396..c9a9cc22c0 100644 --- a/logbus/solvermon/solvermon.go +++ b/logbus/solvermon/solvermon.go @@ -3,6 +3,7 @@ package solvermon import ( "context" + "strings" "sync" "time" @@ -27,7 +28,12 @@ type SolverMonitor struct { targetName string prevState map[string]buildkitskipper.VertexRecord // digest -> VertexRecord from last run collected []buildkitskipper.VertexRecord - mu sync.Mutex + // hashLogDiff contains human-readable lines describing what changed in the + // Earthfile inputs since the last run. Set via SetHashLogDiff before the + // build starts; shown on the first *cache miss* when no vertex-level reason + // is found. Cleared after first use to avoid repeating on every miss. + hashLogDiff []string + mu sync.Mutex } // New creates a new SolverMonitor. @@ -72,6 +78,15 @@ func (sm *SolverMonitor) Configure(ctx context.Context, store buildkitskipper.Ve } } +// SetHashLogDiff sets the Earthfile-level diff lines to show when a cache miss +// has no vertex-level reason. Safe to call before MonitorProgress starts. +func (sm *SolverMonitor) SetHashLogDiff(lines []string) { + sm.mu.Lock() + defer sm.mu.Unlock() + + sm.hashLogDiff = lines +} + // SaveState persists collected vertex records to the store for the current target. // It is a no-op when no store or target was configured. func (sm *SolverMonitor) SaveState(ctx context.Context) error { @@ -216,17 +231,16 @@ func (sm *SolverMonitor) handleBuildkitStatus(status *client.SolveStatus) error if vertex.Started != nil { vm.cp.SetStart(*vertex.Started) - // Only annotate vertices that earth's converter created ahead of - // time (identified by a non-empty CommandID). This excludes - // BuildKit-internal vertices (exporters, cache, context transfer) - // that are always re-executed and have no meaningful miss reason. - if !vertex.Cached && !vm.cacheMissLogged && meta.CommandID != "" { + // Only annotate RUN and COPY operations created by earth's converter + // (identified by a non-empty CommandID). FROM / image-pull vertices + // are always re-executed on a cold daemon and carry no actionable + // miss information. + if !vertex.Cached && !vm.cacheMissLogged && + meta.CommandID != "" && isAnnotatableOp(vm.operation) { vm.cacheMissLogged = true - cacheMissMsg := sm.buildCacheMissMessage(vertex) - if cacheMissMsg != "" { - _, _ = vm.cp.Write([]byte(cacheMissMsg+"\n"), *vertex.Started, logbus.Stderr) - } + cacheMissMsg := "*cache miss*" + sm.buildCacheMissReason(vertex, meta) + _, _ = vm.cp.Write([]byte(cacheMissMsg+"\n"), *vertex.Started, logbus.Stderr) } } @@ -240,10 +254,13 @@ func (sm *SolverMonitor) handleBuildkitStatus(status *client.SolveStatus) error // Collect the vertex record once the vertex is complete. sm.collected = append(sm.collected, buildkitskipper.VertexRecord{ - Digest: vertex.Digest.String(), - Inputs: digestStrings(vertex.Inputs), - Operation: vm.operation, - WasCached: vertex.Cached, + Digest: vertex.Digest.String(), + Inputs: digestStrings(vertex.Inputs), + Operation: vm.operation, + WasCached: vertex.Cached, + ActiveArgs: vm.meta.ActiveArgs, + CopiedPaths: vm.meta.CopiedPaths, + BaseImageRef: vm.meta.BaseImageRef, }) var status logstream.RunStatus @@ -310,27 +327,135 @@ func (sm *SolverMonitor) handleBuildkitStatus(status *client.SolveStatus) error return nil } -// buildCacheMissMessage decides whether to emit a cache-miss annotation and, -// if so, returns the message string. It returns "" when the miss should be -// silent (first run, or was already a miss last time). -func (sm *SolverMonitor) buildCacheMissMessage(vertex *client.Vertex) string { +// cacheMissReasonUnknown is returned when a cache miss regression is detected +// but no specific input change can be identified. +const cacheMissReasonUnknown = "unknown" + +// buildCacheMissReason returns an optional suffix to append to the base +// "*cache miss*" annotation. It returns "" when no prior state is available +// (first run or no DB configured). When the vertex was previously cached it +// returns a human-readable explanation of what changed. +func (sm *SolverMonitor) buildCacheMissReason(vertex *client.Vertex, meta *vertexmeta.VertexMeta) string { digestStr := vertex.Digest.String() prev, found := sm.prevState[digestStr] if !found { - // New operation (first run or graph changed) — don't log. + // Vertex digest changed (command/inputs changed) or first run. + // Show the Earthfile diff once on the first miss, then clear it. + if len(sm.hashLogDiff) > 0 { + reason := " (Earthfile changed:\n" + strings.Join(sm.hashLogDiff, "\n") + ")" + sm.hashLogDiff = nil + + return reason + } + return "" } if !prev.WasCached { - // Was already a miss last time — don't log. + // Was already a miss last time — no regression to report. return "" } - // Previously cached but now a miss: find which input changed. - changedInput := sm.findChangedInput(vertex.Inputs) + // Previously cached but now a miss. Try to explain why, in priority order. + + // 1. ARG value changed. + if reason := diffArgs(prev.ActiveArgs, meta.ActiveArgs); reason != "" { + return " (previously cached; " + reason + ")" + } + + // 2. COPY source paths changed. + if reason := diffCopiedPaths(prev.CopiedPaths, meta.CopiedPaths); reason != "" { + return " (previously cached; " + reason + ")" + } + + // 3. Base image reference changed. + if prev.BaseImageRef != "" && meta.BaseImageRef != "" && prev.BaseImageRef != meta.BaseImageRef { + return " (previously cached; base image changed: " + prev.BaseImageRef + " → " + meta.BaseImageRef + ")" + } + + // 4. Command text changed (same digest, different operation string — shouldn't + // happen for structural ops, but handle it defensively). + if prev.Operation != "" && prev.Operation != sm.prevState[digestStr].Operation { + return " (previously cached; command changed)" + } + + // 5. Fall back to input-chain analysis. + if changedInput := sm.findChangedInput(vertex.Inputs); changedInput != cacheMissReasonUnknown { + return " (previously cached; upstream changed: " + changedInput + ")" + } + + // 6. Fall back to Earthfile-level diff if available. + if len(sm.hashLogDiff) > 0 { + return " (previously cached; Earthfile changed:\n" + strings.Join(sm.hashLogDiff, "\n") + ")" + } + + return " (previously cached; reason " + cacheMissReasonUnknown + ")" +} + +// diffArgs returns a human-readable description of the first arg that changed +// between prev and current. Returns "" if no relevant change is found. +func diffArgs(prev, current map[string]string) string { + for k, curVal := range current { + prevVal, existed := prev[k] + if !existed { + return "new arg: " + k + "=" + curVal + } + + if prevVal != curVal { + return "arg changed: " + k + "=" + prevVal + " → " + curVal + } + } + + for k, prevVal := range prev { + if _, exists := current[k]; !exists { + return "arg removed: " + k + "=" + prevVal + } + } + + return "" +} + +// diffCopiedPaths returns a human-readable description if the set of copied +// paths changed between runs. Returns "" if unchanged. +func diffCopiedPaths(prev, current []string) string { + if len(prev) == 0 && len(current) == 0 { + return "" + } + + prevSet := make(map[string]struct{}, len(prev)) + for _, p := range prev { + prevSet[p] = struct{}{} + } + + for _, p := range current { + if _, ok := prevSet[p]; !ok { + return "file added to COPY: " + p + } + } + + currSet := make(map[string]struct{}, len(current)) + for _, p := range current { + currSet[p] = struct{}{} + } + + for _, p := range prev { + if _, ok := currSet[p]; !ok { + return "file removed from COPY: " + p + } + } + + return "" +} - return "*cache miss* (previously cached; input changed: " + changedInput + ")" +// isAnnotatableOp returns true for operations where a cache miss is meaningful +// and actionable — specifically RUN and COPY commands authored by the user. +// FROM and image-pull operations are excluded because they depend on registry +// state and are always non-cached on a cold daemon. +func isAnnotatableOp(operation string) bool { + return strings.HasPrefix(operation, "RUN ") || + strings.HasPrefix(operation, "COPY ") || + strings.HasPrefix(operation, "GIT CLONE ") } // findChangedInput scans the given input digests and returns the Operation of @@ -346,9 +471,9 @@ func (sm *SolverMonitor) findChangedInput(inputs []digest.Digest) string { return prev.Operation } - return "unknown" + return cacheMissReasonUnknown } } - return "unknown" + return cacheMissReasonUnknown } diff --git a/logbus/solvermon/solvermon_cachemiss_test.go b/logbus/solvermon/solvermon_cachemiss_test.go index b2354628bc..1997a39a09 100644 --- a/logbus/solvermon/solvermon_cachemiss_test.go +++ b/logbus/solvermon/solvermon_cachemiss_test.go @@ -53,43 +53,59 @@ func makeMonitorWithState(records []buildkitskipper.VertexRecord) *SolverMonitor func TestBuildCacheMissMessage_NoHistory(t *testing.T) { t.Parallel() - // Vertex never seen before → silent (first run) sm := makeMonitorWithState(nil) v := &client.Vertex{Digest: sha("new-op"), Inputs: nil} - require.Empty(t, sm.buildCacheMissMessage(v)) + require.Empty(t, sm.buildCacheMissReason(v, &vertexmeta.VertexMeta{})) } func TestBuildCacheMissMessage_PreviouslyMiss(t *testing.T) { t.Parallel() - // Vertex existed last run but was already a miss → silent d := sha("op-a") sm := makeMonitorWithState([]buildkitskipper.VertexRecord{ {Digest: d.String(), Operation: "RUN echo hello", WasCached: false}, }) v := &client.Vertex{Digest: d, Inputs: nil} - require.Empty(t, sm.buildCacheMissMessage(v)) + require.Empty(t, sm.buildCacheMissReason(v, &vertexmeta.VertexMeta{})) } func TestBuildCacheMissMessage_PreviouslyCached_NoInputs(t *testing.T) { t.Parallel() - // Vertex was cached before, no inputs → report miss with "unknown" reason d := sha("op-b") sm := makeMonitorWithState([]buildkitskipper.VertexRecord{ {Digest: d.String(), Operation: "RUN apt-get update", WasCached: true}, }) v := &client.Vertex{Digest: d, Inputs: nil} - msg := sm.buildCacheMissMessage(v) - require.Contains(t, msg, "*cache miss*") + msg := sm.buildCacheMissReason(v, &vertexmeta.VertexMeta{}) require.Contains(t, msg, "previously cached") - require.Contains(t, msg, "unknown") +} + +func TestBuildCacheMissMessage_PreviouslyCached_ArgChanged(t *testing.T) { + t.Parallel() + + d := sha("op-arg") + sm := makeMonitorWithState([]buildkitskipper.VertexRecord{ + { + Digest: d.String(), + Operation: "RUN go build", + WasCached: true, + ActiveArgs: map[string]string{"GO_VERSION": "1.21"}, + }, + }) + v := &client.Vertex{Digest: d, Inputs: nil} + meta := &vertexmeta.VertexMeta{ActiveArgs: map[string]string{"GO_VERSION": "1.22"}} + msg := sm.buildCacheMissReason(v, meta) + require.Contains(t, msg, "previously cached") + require.Contains(t, msg, "arg changed") + require.Contains(t, msg, "GO_VERSION") + require.Contains(t, msg, "1.21") + require.Contains(t, msg, "1.22") } func TestBuildCacheMissMessage_PreviouslyCached_InputChanged(t *testing.T) { t.Parallel() - // Parent op was a miss last run → that's the changed input parentDigest := sha("parent-op") childDigest := sha("child-op") @@ -98,12 +114,8 @@ func TestBuildCacheMissMessage_PreviouslyCached_InputChanged(t *testing.T) { {Digest: childDigest.String(), Operation: "RUN go build", WasCached: true}, }) - v := &client.Vertex{ - Digest: childDigest, - Inputs: []digest.Digest{parentDigest}, - } - msg := sm.buildCacheMissMessage(v) - require.Contains(t, msg, "*cache miss*") + v := &client.Vertex{Digest: childDigest, Inputs: []digest.Digest{parentDigest}} + msg := sm.buildCacheMissReason(v, &vertexmeta.VertexMeta{}) require.Contains(t, msg, "previously cached") require.Contains(t, msg, "COPY ./src /src") } @@ -111,28 +123,19 @@ func TestBuildCacheMissMessage_PreviouslyCached_InputChanged(t *testing.T) { func TestBuildCacheMissMessage_PreviouslyCached_InputNewlyAdded(t *testing.T) { t.Parallel() - // One input never seen before (newly added to graph) - newInputDigest := sha("new-input") childDigest := sha("child-op2") - sm := makeMonitorWithState([]buildkitskipper.VertexRecord{ {Digest: childDigest.String(), Operation: "RUN make", WasCached: true}, - // newInputDigest is absent from prevState }) - v := &client.Vertex{ - Digest: childDigest, - Inputs: []digest.Digest{newInputDigest}, - } - msg := sm.buildCacheMissMessage(v) - require.Contains(t, msg, "*cache miss*") - require.Contains(t, msg, "unknown") + v := &client.Vertex{Digest: childDigest, Inputs: []digest.Digest{sha("new-input")}} + msg := sm.buildCacheMissReason(v, &vertexmeta.VertexMeta{}) + require.Contains(t, msg, "previously cached") } func TestBuildCacheMissMessage_AllInputsPreviouslyCached(t *testing.T) { t.Parallel() - // All inputs were cached → miss reason is "unknown" (command text itself changed) inputDigest := sha("stable-input") childDigest := sha("child-op3") @@ -141,13 +144,9 @@ func TestBuildCacheMissMessage_AllInputsPreviouslyCached(t *testing.T) { {Digest: childDigest.String(), Operation: "RUN echo old", WasCached: true}, }) - v := &client.Vertex{ - Digest: childDigest, - Inputs: []digest.Digest{inputDigest}, - } - msg := sm.buildCacheMissMessage(v) - require.Contains(t, msg, "*cache miss*") - require.Contains(t, msg, "unknown") + v := &client.Vertex{Digest: childDigest, Inputs: []digest.Digest{inputDigest}} + msg := sm.buildCacheMissReason(v, &vertexmeta.VertexMeta{}) + require.Contains(t, msg, "previously cached") } // --------------------------------------------------------------------------- @@ -236,7 +235,7 @@ func TestHandleBuildkitStatus_AnnotatesEarthVertex(t *testing.T) { opDigest := sha("run-echo-hello") - // Seed: this vertex was previously cached + // Seed: this vertex was previously cached — verifies the regression suffix fires. sm.prevState[opDigest.String()] = buildkitskipper.VertexRecord{ Digest: opDigest.String(), Operation: "RUN echo hello", @@ -280,6 +279,65 @@ func TestHandleBuildkitStatus_AnnotatesEarthVertex(t *testing.T) { t.Fatal("expected to find the earth-managed vertex monitor") } +func TestHandleBuildkitStatus_AnnotatesEarthVertex_NoDB(t *testing.T) { + t.Parallel() + + // Verifies that cache miss is annotated even without any prior DB state + // (first run, no --auto-skip-db-path). + b := newTestBus(t) + run := b.Run() + + cmdID := "target-2/cmd-0" + targetID := "target-2" + + _, err := run.NewTarget(targetID, domain.Target{}, nil, "", "") + require.NoError(t, err) + + _, err = run.NewCommand(cmdID, "RUN echo world", targetID, "+my-target", "", false, false, false, nil, "", "", "") + require.NoError(t, err) + + sm := &SolverMonitor{ + b: b, + digests: make(map[digest.Digest]string), + vertices: make(map[string]*vertexMonitor), + prevState: make(map[string]buildkitskipper.VertexRecord), // empty — no DB + } + + opDigest := sha("run-echo-world") + now := time.Now() + + vm := &vertexmeta.VertexMeta{ + CommandID: cmdID, + TargetID: targetID, + TargetName: "+my-target", + } + + status := &client.SolveStatus{ + Vertexes: []*client.Vertex{ + { + Name: vertexMetaPrefix(vm, "RUN echo world"), + Digest: opDigest, + Started: &now, + Cached: false, + }, + }, + } + + err = sm.handleBuildkitStatus(status) + require.NoError(t, err) + + for _, mon := range sm.vertices { + if mon.meta.CommandID == cmdID { + require.True(t, mon.cacheMissLogged, + "earth-managed vertex must be annotated even without prior DB state") + + return + } + } + + t.Fatal("expected to find the earth-managed vertex monitor") +} + // --------------------------------------------------------------------------- // VertexRecord collection // --------------------------------------------------------------------------- diff --git a/util/buildkitskipper/hashdiff.go b/util/buildkitskipper/hashdiff.go new file mode 100644 index 0000000000..1cf3428403 --- /dev/null +++ b/util/buildkitskipper/hashdiff.go @@ -0,0 +1,114 @@ +package buildkitskipper + +import "fmt" + +// HashLogDiff describes what changed in a target's inputs between two runs. +type HashLogDiff struct { + // Added contains inputs present in the current run but not the previous one. + Added []HashInputRecord + // Removed contains inputs present in the previous run but not the current one. + Removed []HashInputRecord + // Changed contains inputs whose Detail value changed for the same Label+position. + Changed []HashInputChange +} + +// HashInputChange describes a single input whose value changed between runs. +type HashInputChange struct { + Label string + Before string + After string +} + +// IsEmpty returns true when there are no differences. +func (d HashLogDiff) IsEmpty() bool { + return len(d.Added) == 0 && len(d.Removed) == 0 && len(d.Changed) == 0 +} + +// Lines returns a human-readable slice of diff lines, one per change. +func (d HashLogDiff) Lines() []string { + lines := make([]string, 0, len(d.Added)+len(d.Removed)+len(d.Changed)) + + for _, c := range d.Changed { + lines = append(lines, fmt.Sprintf("~ %-16s %s → %s", c.Label, c.Before, c.After)) + } + + for _, r := range d.Removed { + lines = append(lines, fmt.Sprintf("- %-16s %s", r.Label, r.Detail)) + } + + for _, a := range d.Added { + lines = append(lines, fmt.Sprintf("+ %-16s %s", a.Label, a.Detail)) + } + + return lines +} + +// DiffHashLog computes the difference between prev and current hash logs. +// It matches entries positionally within the same Label group: entries with the +// same label are compared in order, and value changes within that group are +// reported as Changed rather than Add+Remove pairs. +func DiffHashLog(prev, current []HashInputRecord) HashLogDiff { + var diff HashLogDiff + + // Group entries by label, preserving order within each group. + prevByLabel := groupByLabel(prev) + currByLabel := groupByLabel(current) + + // Collect all labels seen in either run, in the order they first appear. + seen := make(map[string]struct{}) + labels := make([]string, 0, len(prevByLabel)+len(currByLabel)) + + for _, r := range prev { + if _, ok := seen[r.Label]; !ok { + seen[r.Label] = struct{}{} + labels = append(labels, r.Label) + } + } + + for _, r := range current { + if _, ok := seen[r.Label]; !ok { + seen[r.Label] = struct{}{} + labels = append(labels, r.Label) + } + } + + for _, label := range labels { + prevGroup := prevByLabel[label] + currGroup := currByLabel[label] + + // Pair entries positionally within the group. + minLen := min(len(prevGroup), len(currGroup)) + + for i := range minLen { + if prevGroup[i].Detail != currGroup[i].Detail { + diff.Changed = append(diff.Changed, HashInputChange{ + Label: label, + Before: prevGroup[i].Detail, + After: currGroup[i].Detail, + }) + } + } + + // Extra entries in prev = removed. + for i := minLen; i < len(prevGroup); i++ { + diff.Removed = append(diff.Removed, prevGroup[i]) + } + + // Extra entries in curr = added. + for i := minLen; i < len(currGroup); i++ { + diff.Added = append(diff.Added, currGroup[i]) + } + } + + return diff +} + +func groupByLabel(records []HashInputRecord) map[string][]HashInputRecord { + m := make(map[string][]HashInputRecord) + + for _, r := range records { + m[r.Label] = append(m[r.Label], r) + } + + return m +} diff --git a/util/buildkitskipper/hashdiff_test.go b/util/buildkitskipper/hashdiff_test.go new file mode 100644 index 0000000000..e0b87fa8ed --- /dev/null +++ b/util/buildkitskipper/hashdiff_test.go @@ -0,0 +1,135 @@ +package buildkitskipper_test + +import ( + "testing" + + "github.com/EarthBuild/earthbuild/util/buildkitskipper" + "github.com/stretchr/testify/require" +) + +const ( + labelARG = "ARG" + labelRUN = "RUN" + detailFoo = "FOO=bar" +) + +func TestDiffHashLog_NoDiff(t *testing.T) { + t.Parallel() + + prev := []buildkitskipper.HashInputRecord{ + {Label: labelARG, Detail: "GO_VERSION=1.21"}, + {Label: labelRUN, Detail: "go build ./..."}, + } + diff := buildkitskipper.DiffHashLog(prev, prev) + require.True(t, diff.IsEmpty()) + require.Empty(t, diff.Lines()) +} + +func TestDiffHashLog_ChangedValue(t *testing.T) { + t.Parallel() + + prev := []buildkitskipper.HashInputRecord{ + {Label: labelARG, Detail: "GO_VERSION=1.21"}, + } + curr := []buildkitskipper.HashInputRecord{ + {Label: labelARG, Detail: "GO_VERSION=1.22"}, + } + diff := buildkitskipper.DiffHashLog(prev, curr) + require.False(t, diff.IsEmpty()) + require.Len(t, diff.Changed, 1) + require.Equal(t, labelARG, diff.Changed[0].Label) + require.Equal(t, "GO_VERSION=1.21", diff.Changed[0].Before) + require.Equal(t, "GO_VERSION=1.22", diff.Changed[0].After) + + lines := diff.Lines() + require.Len(t, lines, 1) + require.Contains(t, lines[0], "~") + require.Contains(t, lines[0], "GO_VERSION=1.21") + require.Contains(t, lines[0], "GO_VERSION=1.22") +} + +func TestDiffHashLog_AddedEntry(t *testing.T) { + t.Parallel() + + prev := []buildkitskipper.HashInputRecord{ + {Label: labelARG, Detail: detailFoo}, + } + curr := []buildkitskipper.HashInputRecord{ + {Label: labelARG, Detail: detailFoo}, + {Label: labelRUN, Detail: "echo hello"}, + } + diff := buildkitskipper.DiffHashLog(prev, curr) + require.False(t, diff.IsEmpty()) + require.Len(t, diff.Added, 1) + require.Equal(t, labelRUN, diff.Added[0].Label) + require.Equal(t, "echo hello", diff.Added[0].Detail) + + lines := diff.Lines() + require.Len(t, lines, 1) + require.Contains(t, lines[0], "+") + require.Contains(t, lines[0], "echo hello") +} + +func TestDiffHashLog_RemovedEntry(t *testing.T) { + t.Parallel() + + prev := []buildkitskipper.HashInputRecord{ + {Label: labelARG, Detail: detailFoo}, + {Label: labelRUN, Detail: "echo old"}, + } + curr := []buildkitskipper.HashInputRecord{ + {Label: labelARG, Detail: detailFoo}, + } + diff := buildkitskipper.DiffHashLog(prev, curr) + require.False(t, diff.IsEmpty()) + require.Len(t, diff.Removed, 1) + require.Equal(t, labelRUN, diff.Removed[0].Label) + + lines := diff.Lines() + require.Len(t, lines, 1) + require.Contains(t, lines[0], "-") + require.Contains(t, lines[0], "echo old") +} + +func TestDiffHashLog_MultipleChanges(t *testing.T) { + t.Parallel() + + prev := []buildkitskipper.HashInputRecord{ + {Label: labelARG, Detail: "A=1"}, + {Label: labelARG, Detail: "B=2"}, + {Label: labelRUN, Detail: "echo old"}, + } + curr := []buildkitskipper.HashInputRecord{ + {Label: labelARG, Detail: "A=1"}, + {Label: labelARG, Detail: "B=99"}, + {Label: labelRUN, Detail: "echo new"}, + {Label: labelRUN, Detail: "echo added"}, + } + diff := buildkitskipper.DiffHashLog(prev, curr) + require.False(t, diff.IsEmpty()) + require.Len(t, diff.Changed, 2) + require.Empty(t, diff.Removed) + require.Len(t, diff.Added, 1) +} + +func TestDiffHashLog_EmptyPrev(t *testing.T) { + t.Parallel() + + curr := []buildkitskipper.HashInputRecord{ + {Label: labelARG, Detail: detailFoo}, + } + diff := buildkitskipper.DiffHashLog(nil, curr) + require.False(t, diff.IsEmpty()) + require.Len(t, diff.Added, 1) +} + +func TestDiffHashLog_EmptyCurr(t *testing.T) { + t.Parallel() + + prev := []buildkitskipper.HashInputRecord{ + {Label: labelARG, Detail: detailFoo}, + } + diff := buildkitskipper.DiffHashLog(prev, nil) + require.False(t, diff.IsEmpty()) + require.Len(t, diff.Removed, 1) +} diff --git a/util/buildkitskipper/hashlog.go b/util/buildkitskipper/hashlog.go new file mode 100644 index 0000000000..b6f3c27ece --- /dev/null +++ b/util/buildkitskipper/hashlog.go @@ -0,0 +1,74 @@ +package buildkitskipper + +import ( + "context" + "encoding/json" + "fmt" + + bolt "go.etcd.io/bbolt" +) + +var hashLogBucket = []byte("hash-log") + +// HashInputRecord is a single labelled input that contributed to a target's +// cache hash. It mirrors inputgraph.HashInput but is defined here to avoid a +// circular import (inputgraph imports buildkitskipper/hasher). +type HashInputRecord struct { + // Label is a human-readable name for the kind of input (e.g. "ARG", "RUN", + // "COPY file", "FROM target"). + Label string + // Detail is additional context such as the expanded value or file path. + Detail string +} + +// HashLogStore persists and retrieves the ordered list of hash inputs for a +// target across runs, enabling Earthfile-level cache miss diffs. +type HashLogStore interface { + // SaveHashLog persists the hash log for a target after a successful build. + SaveHashLog(ctx context.Context, target string, log []HashInputRecord) error + // LoadHashLog retrieves the hash log from the previous build for a target. + // Returns nil, nil if no prior log exists. + LoadHashLog(ctx context.Context, target string) ([]HashInputRecord, error) +} + +// localHashLogStore is a BoltDB-backed implementation of HashLogStore. +type localHashLogStore struct { + db *bolt.DB +} + +// SaveHashLog persists the hash log for a target. +func (s *localHashLogStore) SaveHashLog(_ context.Context, target string, log []HashInputRecord) error { + data, err := json.Marshal(log) + if err != nil { + return fmt.Errorf("marshal hash log: %w", err) + } + + return s.db.Update(func(tx *bolt.Tx) error { + err := tx.Bucket(hashLogBucket).Put([]byte(target), data) + if err != nil { + return fmt.Errorf("save hash log for %s: %w", target, err) + } + + return nil + }) +} + +// LoadHashLog retrieves the hash log from the previous build. +// Returns nil, nil if no prior log exists. +func (s *localHashLogStore) LoadHashLog(_ context.Context, target string) ([]HashInputRecord, error) { + var records []HashInputRecord + + err := s.db.View(func(tx *bolt.Tx) error { + data := tx.Bucket(hashLogBucket).Get([]byte(target)) + if data == nil { + return nil + } + + return json.Unmarshal(data, &records) + }) + if err != nil { + return nil, fmt.Errorf("load hash log for %s: %w", target, err) + } + + return records, nil +} diff --git a/util/buildkitskipper/local.go b/util/buildkitskipper/local.go index 7f135d321b..09e9989052 100644 --- a/util/buildkitskipper/local.go +++ b/util/buildkitskipper/local.go @@ -30,6 +30,11 @@ func NewLocal(path string) (*LocalBuildkitSkipper, error) { return fmt.Errorf("could not create vertex-state bucket: %w", err) } + _, err = tx.CreateBucketIfNotExists(hashLogBucket) + if err != nil { + return fmt.Errorf("could not create hash-log bucket: %w", err) + } + return nil }) if err != nil { @@ -39,6 +44,7 @@ func NewLocal(path string) (*LocalBuildkitSkipper, error) { return &LocalBuildkitSkipper{ db: db, vertexStateStore: &localVertexStateStore{db: db}, + hashLogStore: &localHashLogStore{db: db}, }, nil } @@ -46,6 +52,7 @@ func NewLocal(path string) (*LocalBuildkitSkipper, error) { type LocalBuildkitSkipper struct { db *bolt.DB vertexStateStore *localVertexStateStore + hashLogStore *localHashLogStore } // VertexStateStore returns the VertexStateStore for persisting per-vertex cache state. @@ -53,6 +60,11 @@ func (l *LocalBuildkitSkipper) VertexStateStore() VertexStateStore { return l.vertexStateStore } +// HashLogStore returns the HashLogStore for persisting Earthfile hash logs. +func (l *LocalBuildkitSkipper) HashLogStore() HashLogStore { + return l.hashLogStore +} + // Add a new hash value (org & target are ignored in this implementation). func (l *LocalBuildkitSkipper) Add(_ context.Context, _ string, data []byte) error { if len(data) != sha1.Size { diff --git a/util/buildkitskipper/vertexstate.go b/util/buildkitskipper/vertexstate.go index 1370cae307..ccfb2b8f8a 100644 --- a/util/buildkitskipper/vertexstate.go +++ b/util/buildkitskipper/vertexstate.go @@ -12,14 +12,13 @@ var vertexStateBucket = []byte("vertex-state") // VertexRecord captures the cache state of one BuildKit vertex from a build run. type VertexRecord struct { - // Digest is the stable SHA256 identity of this LLB operation. - Digest string - // Operation is the human-readable command string (e.g. "RUN apt-get install curl"). - Operation string - // Inputs holds the digests of predecessor vertices, in order. - Inputs []string - // WasCached is true if BuildKit served this vertex from cache. - WasCached bool + ActiveArgs map[string]string `json:"activeArgs,omitempty"` + Digest string + Operation string + BaseImageRef string `json:"baseImageRef,omitempty"` + Inputs []string + CopiedPaths []string `json:"copiedPaths,omitempty"` + WasCached bool } // VertexStateStore persists and retrieves the per-vertex cache state for a target across runs. diff --git a/util/vertexmeta/vertexmeta.go b/util/vertexmeta/vertexmeta.go index 04923c697b..252d33575a 100644 --- a/util/vertexmeta/vertexmeta.go +++ b/util/vertexmeta/vertexmeta.go @@ -20,20 +20,23 @@ const targetInternal = "internal" type VertexMeta struct { SourceLocation *spec.SourceLocation `json:"sl,omitempty"` OverridingArgs map[string]string `json:"args,omitempty"` - CommandID string `json:"cid,omitempty"` - RepoGitURL string `json:"rgu,omitempty"` - RepoGitHash string `json:"rgh,omitempty"` + ActiveArgs map[string]string `json:"aargs,omitempty"` + Platform string `json:"plt,omitempty"` + RepoFileRelToRepo string `json:"rfr,omitempty"` TargetID string `json:"tid,omitempty"` TargetName string `json:"tnm,omitempty"` CanonicalTargetName string `json:"ctnm,omitempty"` - Platform string `json:"plt,omitempty"` + RepoGitURL string `json:"rgu,omitempty"` Runner string `json:"runner,omitempty"` - RepoFileRelToRepo string `json:"rfr,omitempty"` + RepoGitHash string `json:"rgh,omitempty"` + BaseImageRef string `json:"bimg,omitempty"` + CommandID string `json:"cid,omitempty"` + CopiedPaths []string `json:"cpaths,omitempty"` Secrets []string `json:"secrets,omitempty"` - Interactive bool `json:"itrctv,omitempty"` Local bool `json:"lcl,omitempty"` Internal bool `json:"itrnl,omitempty"` NonDefaultPlatform bool `json:"defplt,omitempty"` + Interactive bool `json:"itrctv,omitempty"` } var vertexRegexp = regexp.MustCompile(`(?s)^\[([^\]]*)\] (.*)$`)