Basically overhaul tracing

errors.go

@@ -22,7 +22,7 @@ func a2vs(a atom) string {
 		return "(root)"
 	}
 
-	return fmt.Sprintf("%s at %s", a.id.errString(), a.v)
+	return fmt.Sprintf("%s@%s", a.id.errString(), a.v)
 }
 
 type traceError interface {

solver.go

@@ -322,10 +322,11 @@ func (s *solver) solve() (map[atom]map[string]struct{}, error) {
 		if awp, is := s.sel.selected(bmi.id); !is {
 			// Analysis path for when we haven't selected the project yet - need
 			// to create a version queue.
-			s.traceVisit(bmi, false)
 			queue, err := s.createVersionQueue(bmi)
 			if err != nil {
 				// Err means a failure somewhere down the line; try backtracking.
+				s.traceStartBacktrack(bmi, err, false)
+				//s.traceBacktrack(bmi, false)
 				if s.backtrack() {
 					// backtracking succeeded, move to the next unselected id
 					continue
@@ -366,10 +367,11 @@ func (s *solver) solve() (map[atom]map[string]struct{}, error) {
 				pl: bmi.pl,
 			}
 
-			s.traceVisit(bmi, true)
+			s.traceCheckPkgs(bmi)
 			err := s.check(nawp, true)
 			if err != nil {
 				// Err means a failure somewhere down the line; try backtracking.
+				s.traceStartBacktrack(bmi, err, true)
 				if s.backtrack() {
 					// backtracking succeeded, move to the next unselected id
 					continue
@@ -724,6 +726,7 @@ func (s *solver) createVersionQueue(bmi bimodalIdentifier) (*versionQueue, error
 	}
 
 	// Having assembled the queue, search it for a valid version.
+	s.traceCheckQueue(q, bmi, false, 1)
 	return q, s.findValidVersion(q, bmi.pl)
 }
 
@@ -744,6 +747,7 @@ func (s *solver) findValidVersion(q *versionQueue, pl []string) error {
 
 	for {
 		cur := q.current()
+		s.traceInfo("try %s@%s", q.id.errString(), cur)
 		err := s.check(atomWithPackages{
 			a: atom{
 				id: q.id,
@@ -842,13 +846,10 @@ func (s *solver) getLockVersionIfValid(id ProjectIdentifier) (Version, error) {
 		}
 
 		if !found {
-			s.traceInfo("%s in root lock, but current constraints disallow it", id.errString())
 			return nil, nil
 		}
 	}
 
-	s.traceInfo("using root lock's version of %s", id.errString())
-
 	return v, nil
 }
 
@@ -877,33 +878,28 @@ func (s *solver) backtrack() bool {
 			var awp atomWithPackages
 			for !proj {
 				awp, proj = s.unselectLast()
-				s.traceBacktrack(awp, !proj)
+				s.traceBacktrack(awp.bmi(), !proj)
 			}
 		}
 
 		// Grab the last versionQueue off the list of queues
 		q := s.vqs[len(s.vqs)-1]
-		// Walk back to the next project
-		var awp atomWithPackages
-		var proj bool
 
-		for !proj {
-			awp, proj = s.unselectLast()
-			if !proj {
-				// Don't want to trace this unless it's just packages, as we
-				// might be going forward
-				s.traceBacktrack(awp, !proj)
-			}
+		// Walk back to the next project
+		awp, proj := s.unselectLast()
+		if !proj {
+			panic("canary - *should* be impossible to have a pkg-only selection here")
 		}
 
 		if !q.id.eq(awp.a.id) {
-			panic("canary - version queue stack and selected project stack are out of alignment")
+			panic("canary - version queue stack and selected project stack are misaligned")
 		}
 
 		// Advance the queue past the current version, which we know is bad
 		// TODO(sdboyer) is it feasible to make available the failure reason here?
 		if q.advance(nil) == nil && !q.isExhausted() {
 			// Search for another acceptable version of this failed dep in its queue
+			s.traceCheckQueue(q, awp.bmi(), true, 0)
 			if s.findValidVersion(q, awp.pl) == nil {
 				// Found one! Put it back on the selected queue and stop
 				// backtracking
@@ -915,7 +911,8 @@ func (s *solver) backtrack() bool {
 			}
 		}
 
-		s.traceInfo("no more versions of %s, backtracking", q.id.errString())
+		s.traceBacktrack(awp.bmi(), false)
+		//s.traceInfo("no more versions of %s, backtracking", q.id.errString())
 
 		// No solution found; continue backtracking after popping the queue
 		// we just inspected off the list
@@ -1083,7 +1080,7 @@ func (s *solver) selectAtom(a atomWithPackages, pkgonly bool) {
 		}
 	}
 
-	s.traceSelect(a)
+	s.traceSelect(a, pkgonly)
 }
 
 func (s *solver) unselectLast() (atomWithPackages, bool) {

trace.go

@@ -2,6 +2,7 @@ package gps
 
 import (
 	"fmt"
+	"strconv"
 	"strings"
 )
 
@@ -10,33 +11,75 @@ const (
 	successCharSp = successChar + " "
 	failChar      = "✗"
 	failCharSp    = failChar + " "
+	backChar      = "←"
 )
 
-func (s *solver) traceVisit(bmi bimodalIdentifier, pkgonly bool) {
+func (s *solver) traceCheckPkgs(bmi bimodalIdentifier) {
 	if !s.params.Trace {
 		return
 	}
 
 	prefix := strings.Repeat("| ", len(s.vqs)+1)
-	// TODO(sdboyer) how...to list the packages in the limited space we have?
-	if pkgonly {
-		s.tl.Printf("%s\n", tracePrefix(fmt.Sprintf("? revisiting %s to add %v pkgs", bmi.id.errString(), len(bmi.pl)), prefix, prefix))
-	} else {
-		s.tl.Printf("%s\n", tracePrefix(fmt.Sprintf("? attempting %s (with %v pkgs)", bmi.id.errString(), len(bmi.pl)), prefix, prefix))
-	}
+	s.tl.Printf("%s\n", tracePrefix(fmt.Sprintf("? revisit %s to add %v pkgs", bmi.id.errString(), len(bmi.pl)), prefix, prefix))
 }
 
-func (s *solver) traceBacktrack(a atomWithPackages, pkgonly bool) {
+func (s *solver) traceCheckQueue(q *versionQueue, bmi bimodalIdentifier, cont bool, offset int) {
 	if !s.params.Trace {
 		return
 	}
 
-	prefix := strings.Repeat("| ", len(s.vqs)+1)
-	if pkgonly {
-		s.tl.Printf("%s\n", tracePrefix(fmt.Sprintf("%s backtrack: popped %v pkgs from %s", failChar, len(a.pl), a.a.id.errString()), prefix, prefix))
-	} else {
-		s.tl.Printf("%s\n", tracePrefix(fmt.Sprintf("%s backtrack: popped %s", failChar, a.a.id.errString()), prefix, prefix))
+	prefix := strings.Repeat("| ", len(s.vqs)+offset)
+	vlen := strconv.Itoa(len(q.pi))
+	if !q.allLoaded {
+		vlen = "at least " + vlen
 	}
+
+	// TODO(sdboyer) how...to list the packages in the limited space we have?
+	var verb string
+	if cont {
+		verb = "continue"
+		vlen = vlen + " more"
+	} else {
+		verb = "attempt"
+	}
+
+	s.tl.Printf("%s\n", tracePrefix(fmt.Sprintf("? %s %s with %v pkgs; %s versions to try", verb, bmi.id.errString(), len(bmi.pl), vlen), prefix, prefix))
+}
+
+// traceStartBacktrack is called with the bmi that first failed, thus initiating
+// backtracking
+func (s *solver) traceStartBacktrack(bmi bimodalIdentifier, err error, pkgonly bool) {
+	if !s.params.Trace {
+		return
+	}
+
+	var msg string
+	if pkgonly {
+		msg = fmt.Sprintf("%s could not add %v pkgs to %s; begin backtrack", backChar, len(bmi.pl), bmi.id.errString())
+	} else {
+		msg = fmt.Sprintf("%s no more versions of %s to try; begin backtrack", backChar, bmi.id.errString())
+	}
+
+	prefix := strings.Repeat("| ", len(s.sel.projects))
+	s.tl.Printf("%s\n", tracePrefix(msg, prefix, prefix))
+}
+
+// traceBacktrack is called when a package or project is poppped off during
+// backtracking
+func (s *solver) traceBacktrack(bmi bimodalIdentifier, pkgonly bool) {
+	if !s.params.Trace {
+		return
+	}
+
+	var msg string
+	if pkgonly {
+		msg = fmt.Sprintf("%s backtrack: popped %v pkgs from %s", backChar, len(bmi.pl), bmi.id.errString())
+	} else {
+		msg = fmt.Sprintf("%s backtrack: no more versions of %s to try", backChar, bmi.id.errString())
+	}
+
+	prefix := strings.Repeat("| ", len(s.sel.projects))
+	s.tl.Printf("%s\n", tracePrefix(msg, prefix, prefix))
 }
 
 // Called just once after solving has finished, whether success or not
@@ -80,14 +123,19 @@ func (s *solver) traceSelectRoot(ptree PackageTree, cdeps []completeDep) {
 }
 
 // traceSelect is called when an atom is successfully selected
-func (s *solver) traceSelect(awp atomWithPackages) {
+func (s *solver) traceSelect(awp atomWithPackages, pkgonly bool) {
 	if !s.params.Trace {
 		return
 	}
 
-	prefix := strings.Repeat("| ", len(s.vqs)+1)
-	msg := fmt.Sprintf("%s select %s at %s", successChar, awp.a.id.errString(), awp.a.v)
+	var msg string
+	if pkgonly {
+		msg = fmt.Sprintf("%s include %v more pkgs from %s", successChar, len(awp.pl), a2vs(awp.a))
+	} else {
+		msg = fmt.Sprintf("%s select %s w/%v pkgs", successChar, a2vs(awp.a), len(awp.pl))
+	}
 
+	prefix := strings.Repeat("| ", len(s.sel.projects)-1)
 	s.tl.Printf("%s\n", tracePrefix(msg, prefix, prefix))
 }
 
@@ -100,12 +148,13 @@ func (s *solver) traceInfo(args ...interface{}) {
 		panic("must pass at least one param to traceInfo")
 	}
 
-	preflen := len(s.vqs) + 1
+	preflen := len(s.sel.projects)
 	var msg string
 	switch data := args[0].(type) {
 	case string:
-		msg = tracePrefix(fmt.Sprintf(data, args[1:]), "| ", "| ")
+		msg = tracePrefix(fmt.Sprintf(data, args[1:]...), "| ", "| ")
 	case traceError:
+		preflen += 1
 		// We got a special traceError, use its custom method
 		msg = tracePrefix(data.traceString(), "| ", failCharSp)
 	case error:

types.go

@@ -170,6 +170,18 @@ type atomWithPackages struct {
 	pl []string
 }
 
+// bmi converts an atomWithPackages into a bimodalIdentifier.
+//
+// This is mostly intended for (read-only) trace use, so the package list slice
+// is not copied. It is the callers responsibility to not modify the pl slice,
+// lest that backpropagate and cause inconsistencies.
+func (awp atomWithPackages) bmi() bimodalIdentifier {
+	return bimodalIdentifier{
+		id: awp.a.id,
+		pl: awp.pl,
+	}
+}
+
 //type byImportPath []Package
 
 //func (s byImportPath) Len() int           { return len(s) }