track actives map usage for use in error reporting

solver/inconsistent_graph_state_error_tracker.go

@@ -0,0 +1,59 @@
+package solver
+
+// earthly-specific: this is used to collect information related to "inconsistent graph state" errors
+
+import (
+	"fmt"
+	"strings"
+	"time"
+
+	digest "github.com/opencontainers/go-digest"
+)
+
+var dgstTrackerInst = newDgstTracker()
+
+type dgstTrackerItem struct {
+	dgst   digest.Digest
+	action string
+	seen   time.Time
+}
+
+type dgstTracker struct {
+	head    int
+	records []dgstTrackerItem
+}
+
+func newDgstTracker() *dgstTracker {
+	n := 10000
+	return &dgstTracker{
+		records: make([]dgstTrackerItem, n),
+	}
+}
+
+func (d *dgstTracker) add(dgst digest.Digest, action string) {
+	d.head += 1
+	if d.head >= len(d.records) {
+		d.head = 0
+	}
+	d.records[d.head].dgst = dgst
+	d.records[d.head].action = action
+	d.records[d.head].seen = time.Now()
+}
+
+func (d *dgstTracker) String() string {
+	var sb strings.Builder
+
+	for i := d.head; i >= 0; i-- {
+		if d.records[i].seen.IsZero() {
+			break
+		}
+		sb.WriteString(fmt.Sprintf("%s %s %s; ", d.records[i].dgst, d.records[i].action, d.records[i].seen))
+	}
+	for i := len(d.records) - 1; i > d.head; i-- {
+		if d.records[i].seen.IsZero() {
+			break
+		}
+		sb.WriteString(fmt.Sprintf("%s %s %s; ", d.records[i].dgst, d.records[i].action, d.records[i].seen))
+	}
+	return sb.String()
+}

solver/jobs.go

@@ -300,8 +300,10 @@ func (jl *Solver) getEdge(e Edge) *edge {
 	jl.mu.RLock()
 	defer jl.mu.RUnlock()
 
-	st, ok := jl.actives[e.Vertex.Digest()]
+	dgst := e.Vertex.Digest()
+	st, ok := jl.actives[dgst]
 	if !ok {
+		dgstTrackerInst.add(dgst, "get-edge-not-found")
 		return nil
 	}
 	return st.getEdge(e.Index)
@@ -356,11 +358,13 @@ func (jl *Solver) loadUnlocked(v, parent Vertex, j *Job, cache map[Vertex]Vertex
 		// existing active vertex, as otherwise the original vertex will use an
 		// incorrect digest and can incorrectly delete it while it is still in use.
 		v = st.vtx
+		dgstTrackerInst.add(dgst, "loadUnlocked-found-dgstWithoutCache")
 	}
 
 	if !ok {
 		st, ok = jl.actives[dgst]
 
+		dgstTrackerInst.add(dgst, "loadUnlocked-not-found-dgstWithoutCache")
 		// !ignorecache merges with ignorecache but ignorecache doesn't merge with !ignorecache
 		if ok && !st.vtx.Options().IgnoreCache && v.Options().IgnoreCache {
 			dgst = dgstWithoutCache
@@ -394,6 +398,9 @@ func (jl *Solver) loadUnlocked(v, parent Vertex, j *Job, cache map[Vertex]Vertex
 			origDigest:   origVtx.Digest(),
 		}
 		jl.actives[dgst] = st
+		dgstTrackerInst.add(dgst, "loadUnlocked-add")
+	} else {
+		dgstTrackerInst.add(dgst, "loadUnlocked-exists")
 	}
 
 	st.mu.Lock()
@@ -409,6 +416,8 @@ func (jl *Solver) loadUnlocked(v, parent Vertex, j *Job, cache map[Vertex]Vertex
 		if _, ok := st.jobs[j]; !ok {
 			st.jobs[j] = struct{}{}
 		}
+	} else {
+		dgstTrackerInst.add(dgst, "loadUnlocked-nil-job")
 	}
 	st.mu.Unlock()
 
@@ -515,6 +524,7 @@ func (jl *Solver) deleteIfUnreferenced(k digest.Digest, st *state) {
 		}
 		st.Release()
 		delete(jl.actives, k)
+		dgstTrackerInst.add(k, "delete")
 	}
 }
 

solver/scheduler.go

@@ -365,6 +365,8 @@ type pipeFactory struct {
 func (pf *pipeFactory) NewInputRequest(ee Edge, req *edgeRequest) pipe.Receiver {
 	target := pf.s.ef.getEdge(ee)
 	if target == nil {
+		dgst := ee.Vertex.Digest()
+		bklog.G(context.TODO()).Errorf("failed to get edge dgst=%s name=%s desiredState=%s; actives history: %s", dgst, ee.Vertex.Name(), req.desiredState, dgstTrackerInst.String()) // earthly-specific
 		return pf.NewFuncRequest(func(_ context.Context) (interface{}, error) {
 			return nil, errors.Errorf("failed to get edge: inconsistent graph state")
 		})