Merge pull request #10133 from hashicorp/jbardin/debug

DebugVisitInfo

dag/dag.go

@@ -167,7 +167,7 @@ func (g *AcyclicGraph) Cycles() [][]Vertex {
 // This will walk nodes in parallel if it can. Because the walk is done
 // in parallel, the error returned will be a multierror.
 func (g *AcyclicGraph) Walk(cb WalkFunc) error {
-	defer g.debug.BeginOperation("Walk", "").End("")
+	defer g.debug.BeginOperation(typeWalk, "").End("")
 
 	// Cache the vertices since we use it multiple times
 	vertices := g.Vertices()
@@ -278,7 +278,7 @@ type vertexAtDepth struct {
 // the vertices in start. This is not exported now but it would make sense
 // to export this publicly at some point.
 func (g *AcyclicGraph) DepthFirstWalk(start []Vertex, f DepthWalkFunc) error {
-	defer g.debug.BeginOperation("DepthFirstWalk", "").End("")
+	defer g.debug.BeginOperation(typeDepthFirstWalk, "").End("")
 
 	seen := make(map[Vertex]struct{})
 	frontier := make([]*vertexAtDepth, len(start))
@@ -322,7 +322,7 @@ func (g *AcyclicGraph) DepthFirstWalk(start []Vertex, f DepthWalkFunc) error {
 // reverseDepthFirstWalk does a depth-first walk _up_ the graph starting from
 // the vertices in start.
 func (g *AcyclicGraph) ReverseDepthFirstWalk(start []Vertex, f DepthWalkFunc) error {
-	defer g.debug.BeginOperation("ReverseDepthFirstWalk", "").End("")
+	defer g.debug.BeginOperation(typeReverseDepthFirstWalk, "").End("")
 
 	seen := make(map[Vertex]struct{})
 	frontier := make([]*vertexAtDepth, len(start))

dag/graph.go

@@ -339,24 +339,30 @@ func (g *Graph) MarshalJSON() ([]byte, error) {
 // information. After this is set, the graph will immediately encode itself to
 // the stream, and continue to record all subsequent operations.
 func (g *Graph) SetDebugWriter(w io.Writer) {
-	g.debug = &encoder{w}
+	g.debug = &encoder{w: w}
 	g.debug.Encode(newMarshalGraph("root", g))
 }
 
 // DebugVertexInfo encodes arbitrary information about a vertex in the graph
 // debug logs.
 func (g *Graph) DebugVertexInfo(v Vertex, info string) {
-	va := newVertexDebugInfo(v, info)
+	va := newVertexInfo(typeVertexInfo, v, info)
 	g.debug.Encode(va)
 }
 
 // DebugEdgeInfo encodes arbitrary information about an edge in the graph debug
 // logs.
 func (g *Graph) DebugEdgeInfo(e Edge, info string) {
-	ea := newEdgeDebugInfo(e, info)
+	ea := newEdgeInfo(typeEdgeInfo, e, info)
 	g.debug.Encode(ea)
 }
 
+// DebugVisitInfo records a visit to a Vertex during a walk operation.
+func (g *Graph) DebugVisitInfo(v Vertex, info string) {
+	vi := newVertexInfo(typeVisitInfo, v, info)
+	g.debug.Encode(vi)
+}
+
 // DebugOperation marks the start of a set of graph transformations in
 // the debug log, and returns a DebugOperationEnd func, which marks the end of
 // the operation in the log. Additional information can be added to the log via

dag/marshal.go

@@ -8,6 +8,19 @@ import (
 	"reflect"
 	"sort"
 	"strconv"
+	"sync"
+)
+
+const (
+	typeOperation             = "Operation"
+	typeTransform             = "Transform"
+	typeWalk                  = "Walk"
+	typeDepthFirstWalk        = "DepthFirstWalk"
+	typeReverseDepthFirstWalk = "ReverseDepthFirstWalk"
+	typeTransitiveReduction   = "TransitiveReduction"
+	typeEdgeInfo              = "EdgeInfo"
+	typeVertexInfo            = "VertexInfo"
+	typeVisitInfo             = "VisitInfo"
 )
 
 // the marshal* structs are for serialization of the graph data.
@@ -241,6 +254,7 @@ func (e DebugOperationEnd) End(info string) { e(info) }
 // encoder provides methods to write debug data to an io.Writer, and is a noop
 // when no writer is present
 type encoder struct {
+	sync.Mutex
 	w io.Writer
 }
 
@@ -249,6 +263,8 @@ func (e *encoder) Encode(i interface{}) {
 	if e == nil || e.w == nil {
 		return
 	}
+	e.Lock()
+	defer e.Unlock()
 
 	js, err := json.Marshal(i)
 	if err != nil {
@@ -266,7 +282,7 @@ func (e *encoder) Encode(i interface{}) {
 
 func (e *encoder) Add(v Vertex) {
 	e.Encode(marshalTransform{
-		Type:      "Transform",
+		Type:      typeTransform,
 		AddVertex: newMarshalVertex(v),
 	})
 }
@@ -274,21 +290,21 @@ func (e *encoder) Add(v Vertex) {
 // Remove records the removal of Vertex v.
 func (e *encoder) Remove(v Vertex) {
 	e.Encode(marshalTransform{
-		Type:         "Transform",
+		Type:         typeTransform,
 		RemoveVertex: newMarshalVertex(v),
 	})
 }
 
 func (e *encoder) Connect(edge Edge) {
 	e.Encode(marshalTransform{
-		Type:    "Transform",
+		Type:    typeTransform,
 		AddEdge: newMarshalEdge(edge),
 	})
 }
 
 func (e *encoder) RemoveEdge(edge Edge) {
 	e.Encode(marshalTransform{
-		Type:       "Transform",
+		Type:       typeTransform,
 		RemoveEdge: newMarshalEdge(edge),
 	})
 }
@@ -301,14 +317,14 @@ func (e *encoder) BeginOperation(op string, info string) DebugOperationEnd {
 	}
 
 	e.Encode(marshalOperation{
-		Type:  "Operation",
+		Type:  typeOperation,
 		Begin: op,
 		Info:  info,
 	})
 
 	return func(info string) {
 		e.Encode(marshalOperation{
-			Type: "Operation",
+			Type: typeOperation,
 			End:  op,
 			Info: info,
 		})
@@ -391,7 +407,7 @@ func decodeGraph(r io.Reader) (*marshalGraph, error) {
 
 		// the only Type we're concerned with here is Transform to complete the
 		// Graph
-		if s.Type != "Transform" {
+		if s.Type != typeTransform {
 			continue
 		}
 
@@ -405,31 +421,35 @@ func decodeGraph(r io.Reader) (*marshalGraph, error) {
 	return g, nil
 }
 
-// *DebugInfo structs allow encoding arbitrary information about the graph in
-// the logs.
-type vertexDebugInfo struct {
+// marshalVertexInfo allows encoding arbitrary information about the a single
+// Vertex in the logs. These are accumulated for informational display while
+// rebuilding the graph.
+type marshalVertexInfo struct {
 	Type   string
 	Vertex *marshalVertex
 	Info   string
 }
 
-func newVertexDebugInfo(v Vertex, info string) *vertexDebugInfo {
-	return &vertexDebugInfo{
-		Type:   "VertexDebugInfo",
+func newVertexInfo(infoType string, v Vertex, info string) *marshalVertexInfo {
+	return &marshalVertexInfo{
+		Type:   infoType,
 		Vertex: newMarshalVertex(v),
 		Info:   info,
 	}
 }
 
-type edgeDebugInfo struct {
+// marshalEdgeInfo allows encoding arbitrary information about the a single
+// Edge in the logs. These are accumulated for informational display while
+// rebuilding the graph.
+type marshalEdgeInfo struct {
 	Type string
 	Edge *marshalEdge
 	Info string
 }
 
-func newEdgeDebugInfo(e Edge, info string) *edgeDebugInfo {
-	return &edgeDebugInfo{
-		Type: "EdgeDebugInfo",
+func newEdgeInfo(infoType string, e Edge, info string) *marshalEdgeInfo {
+	return &marshalEdgeInfo{
+		Type: infoType,
 		Edge: newMarshalEdge(e),
 		Info: info,
 	}

dag/marshal_test.go

@@ -156,8 +156,8 @@ func TestGraphJSON_debugInfo(t *testing.T) {
 		}
 
 		switch d.Type {
-		case "VertexDebugInfo":
-			va := &vertexDebugInfo{}
+		case typeVertexInfo:
+			va := &marshalVertexInfo{}
 			err := json.Unmarshal(d.JSON, va)
 			if err != nil {
 				t.Fatal(err)
@@ -177,8 +177,8 @@ func TestGraphJSON_debugInfo(t *testing.T) {
 			default:
 				t.Fatalf("unexpected annotation: %#v", va)
 			}
-		case "EdgeDebugInfo":
-			ea := &edgeDebugInfo{}
+		case typeEdgeInfo:
+			ea := &marshalEdgeInfo{}
 			err := json.Unmarshal(d.JSON, ea)
 			if err != nil {
 				t.Fatal(err)
@@ -238,7 +238,7 @@ func TestGraphJSON_debugOperations(t *testing.T) {
 			t.Fatal(err)
 		}
 
-		if d.Type != "Operation" {
+		if d.Type != typeOperation {
 			continue
 		}
 
@@ -278,6 +278,61 @@ func TestGraphJSON_debugOperations(t *testing.T) {
 	}
 }
 
+// Verify that we can replay visiting each vertex in order
+func TestGraphJSON_debugVisits(t *testing.T) {
+	var g Graph
+	var buf bytes.Buffer
+	g.SetDebugWriter(&buf)
+
+	g.Add(1)
+	g.Add(2)
+	g.Add(3)
+	g.Add(4)
+
+	g.Connect(BasicEdge(2, 1))
+	g.Connect(BasicEdge(4, 2))
+	g.Connect(BasicEdge(3, 4))
+
+	err := (&AcyclicGraph{g}).Walk(func(v Vertex) error {
+		g.DebugVisitInfo(v, "basic walk")
+		return nil
+	})
+
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	var visited []string
+
+	dec := json.NewDecoder(bytes.NewReader(buf.Bytes()))
+	for dec.More() {
+		var d streamDecode
+
+		err := dec.Decode(&d)
+		if err != nil {
+			t.Fatal(err)
+		}
+
+		if d.Type != typeVisitInfo {
+			continue
+		}
+
+		o := &marshalVertexInfo{}
+		err = json.Unmarshal(d.JSON, o)
+		if err != nil {
+			t.Fatal(err)
+		}
+
+		visited = append(visited, o.Vertex.ID)
+	}
+
+	expected := []string{"1", "2", "4", "3"}
+
+	if strings.Join(visited, "-") != strings.Join(expected, "-") {
+		t.Fatalf("incorrect order of operations: %v", visited)
+	}
+}
+
 const testGraphJSONEmptyStr = `{
   "Type": "Graph",
   "Name": "root",

terraform/debug.go

@@ -224,40 +224,6 @@ func (d *debugInfo) flush() {
 	}
 }
 
-// WriteGraph takes a DebugGraph and writes both the DebugGraph as a dot file
-// in the debug archive, and extracts any logs that the DebugGraph collected
-// and writes them to a log file in the archive.
-func (d *debugInfo) WriteGraph(name string, g *Graph) error {
-	if d == nil || g == nil {
-		return nil
-	}
-	d.Lock()
-	defer d.Unlock()
-
-	// If we crash, the file won't be correctly closed out, but we can rebuild
-	// the archive if we have to as long as every file has been flushed and
-	// sync'ed.
-	defer d.flush()
-
-	dotPath := fmt.Sprintf("%s/graphs/%d-%s-%s.dot", d.name, d.step, d.phase, name)
-	d.step++
-
-	dotBytes := g.Dot(nil)
-	hdr := &tar.Header{
-		Name: dotPath,
-		Mode: 0644,
-		Size: int64(len(dotBytes)),
-	}
-
-	err := d.tar.WriteHeader(hdr)
-	if err != nil {
-		return err
-	}
-
-	_, err = d.tar.Write(dotBytes)
-	return err
-}
-
 // WriteFile writes data as a single file to the debug arhive.
 func (d *debugInfo) WriteFile(name string, data []byte) error {
 	if d == nil {

terraform/debug_test.go

@@ -16,7 +16,6 @@ func TestDebugInfo_nil(t *testing.T) {
 	var d *debugInfo
 
 	d.SetPhase("none")
-	d.WriteGraph("", nil)
 	d.WriteFile("none", nil)
 	d.Close()
 }
@@ -120,9 +119,7 @@ func TestDebug_plan(t *testing.T) {
 	}
 	tr := tar.NewReader(gz)
 
-	files := 0
-	graphs := 0
-	json := 0
+	graphLogs := 0
 	for {
 		hdr, err := tr.Next()
 		if err == io.EOF {
@@ -134,28 +131,13 @@ func TestDebug_plan(t *testing.T) {
 
 		// record any file that contains data
 		if hdr.Size > 0 {
-			files++
-
-			// and any dot graph with data
-			if strings.HasSuffix(hdr.Name, ".dot") {
-				graphs++
-			}
-
 			if strings.HasSuffix(hdr.Name, "graph.json") {
-				json++
+				graphLogs++
 			}
 		}
 	}
 
-	if files == 0 {
-		t.Fatal("no files with data found")
-	}
-
-	if graphs == 0 {
-		t.Fatal("no no-empty graphs found")
-	}
-
-	if json == 0 {
+	if graphLogs == 0 {
 		t.Fatal("no json graphs")
 	}
 }

terraform/graph.go

@@ -246,6 +246,7 @@ func (g *Graph) walk(walker GraphWalker) error {
 	var walkFn dag.WalkFunc
 	walkFn = func(v dag.Vertex) (rerr error) {
 		log.Printf("[DEBUG] vertex '%s.%s': walking", path, dag.VertexName(v))
+		g.DebugVisitInfo(v, g.debugName)
 
 		// If we have a panic wrap GraphWalker and a panic occurs, recover
 		// and call that. We ensure the return value is an error, however,

terraform/graph_builder.go

@@ -30,7 +30,7 @@ type BasicGraphBuilder struct {
 func (b *BasicGraphBuilder) Build(path []string) (*Graph, error) {
 	g := &Graph{Path: path}
 
-	debugName := "build-graph.json"
+	debugName := "graph.json"
 	if b.Name != "" {
 		debugName = b.Name + "-" + debugName
 	}
@@ -58,19 +58,10 @@ func (b *BasicGraphBuilder) Build(path []string) (*Graph, error) {
 		}
 		debugOp.End(errMsg)
 
-		// always log the graph state to see what transformations may have happened
-		debugName := "build-" + stepName
-		if b.Name != "" {
-			debugName = b.Name + "-" + debugName
-		}
-
 		log.Printf(
 			"[TRACE] Graph after step %T:\n\n%s",
 			step, g.StringWithNodeTypes())
 
-		// TODO: replace entirely with the json logs
-		dbug.WriteGraph(debugName, g)
-
 		if err != nil {
 			return g, err
 		}
@@ -134,7 +125,7 @@ func (b *BuiltinGraphBuilder) Build(path []string) (*Graph, error) {
 	basic := &BasicGraphBuilder{
 		Steps:    b.Steps(path),
 		Validate: b.Validate,
-		Name:     "builtin",
+		Name:     "BuiltinGraphBuilder",
 	}
 
 	return basic.Build(path)

terraform/graph_builder_apply.go

@@ -40,7 +40,7 @@ func (b *ApplyGraphBuilder) Build(path []string) (*Graph, error) {
 	return (&BasicGraphBuilder{
 		Steps:    b.Steps(),
 		Validate: true,
-		Name:     "apply",
+		Name:     "ApplyGraphBuilder",
 	}).Build(path)
 }
 

terraform/graph_builder_destroy_plan.go

@@ -26,7 +26,7 @@ func (b *DestroyPlanGraphBuilder) Build(path []string) (*Graph, error) {
 	return (&BasicGraphBuilder{
 		Steps:    b.Steps(),
 		Validate: true,
-		Name:     "destroy",
+		Name:     "DestroyPlanGraphBuilder",
 	}).Build(path)
 }
 

terraform/graph_builder_import.go

@@ -23,6 +23,7 @@ func (b *ImportGraphBuilder) Build(path []string) (*Graph, error) {
 	return (&BasicGraphBuilder{
 		Steps:    b.Steps(),
 		Validate: true,
+		Name:     "ImportGraphBuilder",
 	}).Build(path)
 }
 

terraform/graph_builder_plan.go

@@ -38,7 +38,7 @@ func (b *PlanGraphBuilder) Build(path []string) (*Graph, error) {
 	return (&BasicGraphBuilder{
 		Steps:    b.Steps(),
 		Validate: true,
-		Name:     "plan",
+		Name:     "PlanGraphBuilder",
 	}).Build(path)
 }
 

terraform/graph_config_node_resource.go

@@ -191,7 +191,11 @@ func (n *GraphNodeConfigResource) DynamicExpand(ctx EvalContext) (*Graph, error)
 	steps = append(steps, &RootTransformer{})
 
 	// Build the graph
-	b := &BasicGraphBuilder{Steps: steps, Validate: true}
+	b := &BasicGraphBuilder{
+		Steps:    steps,
+		Validate: true,
+		Name:     "GraphNodeConfigResource",
+	}
 	return b.Build(ctx.Path())
 }
 

terraform/node_resource_destroy.go

@@ -74,7 +74,10 @@ func (n *NodeDestroyResource) DynamicExpand(ctx EvalContext) (*Graph, error) {
 	steps = append(steps, &RootTransformer{})
 
 	// Build the graph
-	b := &BasicGraphBuilder{Steps: steps}
+	b := &BasicGraphBuilder{
+		Steps: steps,
+		Name:  "NodeResourceDestroy",
+	}
 	return b.Build(ctx.Path())
 }
 

terraform/node_resource_plan.go

@@ -101,6 +101,10 @@ func (n *NodePlannableResource) DynamicExpand(ctx EvalContext) (*Graph, error) {
 	}
 
 	// Build the graph
-	b := &BasicGraphBuilder{Steps: steps, Validate: true}
+	b := &BasicGraphBuilder{
+		Steps:    steps,
+		Validate: true,
+		Name:     "NodePlannableResource",
+	}
 	return b.Build(ctx.Path())
 }

terraform/transform_destroy_cbd.go

@@ -142,6 +142,7 @@ func (t *CBDEdgeTransformer) depMap(
 			&AttachStateTransformer{State: t.State},
 			&ReferenceTransformer{},
 		},
+		Name: "CBDEdgeTransformer",
 	}).Build(nil)
 	if err != nil {
 		return nil, err