Merge pull request #10104 from hashicorp/jbardin/debug

DebugOperation

dag/dag.go

@@ -103,7 +103,7 @@ func (g *AcyclicGraph) TransitiveReduction() {
 	// v such that the edge (u,v) exists (v is a direct descendant of u).
 	//
 	// For each v-prime reachable from v, remove the edge (u, v-prime).
-	defer g.debug.BeginReduction().End()
+	defer g.debug.BeginOperation("TransitiveReduction", "").End("")
 
 	for _, u := range g.Vertices() {
 		uTargets := g.DownEdges(u)
@@ -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.BeginWalk().End()
+	defer g.debug.BeginOperation("Walk", "").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.BeginDepthFirstWalk().End()
+	defer g.debug.BeginOperation("DepthFirstWalk", "").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.BeginReverseDepthFirstWalk().End()
+	defer g.debug.BeginOperation("ReverseDepthFirstWalk", "").End("")
 
 	seen := make(map[Vertex]struct{})
 	frontier := make([]*vertexAtDepth, len(start))

dag/graph.go

@@ -139,7 +139,7 @@ func (g *Graph) Replace(original, replacement Vertex) bool {
 		return false
 	}
 
-	defer g.debug.BeginReplace().End()
+	defer g.debug.BeginOperation("Replace", "").End("")
 
 	// If they're the same, then don't do anything
 	if original == replacement {
@@ -357,6 +357,21 @@ func (g *Graph) DebugEdgeInfo(e Edge, info string) {
 	g.debug.Encode(ea)
 }
 
+// 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
+// the info parameter.
+//
+// The returned func's End method allows this method to be called from a single
+// defer statement:
+//     defer g.DebugOperationBegin("OpName", "operating").End("")
+//
+// The returned function must be called to properly close the logical operation
+// in the logs.
+func (g *Graph) DebugOperation(operation string, info string) DebugOperationEnd {
+	return g.debug.BeginOperation(operation, info)
+}
+
 // VertexName returns the name of a vertex.
 func VertexName(raw Vertex) string {
 	switch v := raw.(type) {

dag/marshal.go

@@ -230,10 +230,13 @@ func marshalSubgrapher(v Vertex) (*Graph, bool) {
 	return nil, false
 }
 
-// ender provides a way to call any End* method expression via an End method
-type ender func()
+// The DebugOperationEnd func type provides a way to call an End function via a
+// method call, allowing for the chaining of methods in a defer statement.
+type DebugOperationEnd func(string)
 
-func (e ender) End() { e() }
+// End calls function e with the info parameter, marking the end of this
+// operation in the logs.
+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
@@ -290,89 +293,26 @@ func (e *encoder) RemoveEdge(edge Edge) {
 	})
 }
 
-// BeginReplace marks the start of a replace operation, and returns the encoder
-// to chain the EndReplace call.
-func (e *encoder) BeginReplace() ender {
+// BeginOperation marks the start of set of graph transformations, and returns
+// an EndDebugOperation func to be called once the opration is complete.
+func (e *encoder) BeginOperation(op string, info string) DebugOperationEnd {
+	if e == nil {
+		return func(string) {}
+	}
+
 	e.Encode(marshalOperation{
 		Type:  "Operation",
-		Begin: newString("Replace"),
+		Begin: op,
+		Info:  info,
 	})
-	return e.EndReplace
-}
 
-func (e *encoder) EndReplace() {
-	e.Encode(marshalOperation{
-		Type: "Operation",
-		End:  newString("Replace"),
-	})
-}
-
-// BeginReduction marks the start of a replace operation, and returns the encoder
-// to chain the EndReduction call.
-func (e *encoder) BeginReduction() ender {
-	e.Encode(marshalOperation{
-		Type:  "Operation",
-		Begin: newString("Reduction"),
-	})
-	return e.EndReduction
-}
-
-func (e *encoder) EndReduction() {
-	e.Encode(marshalOperation{
-		Type: "Operation",
-		End:  newString("Reduction"),
-	})
-}
-
-// BeginDepthFirstWalk marks the start of a replace operation, and returns the
-// encoder to chain the EndDepthFirstWalk call.
-func (e *encoder) BeginDepthFirstWalk() ender {
-	e.Encode(marshalOperation{
-		Type:  "Operation",
-		Begin: newString("DepthFirstWalk"),
-	})
-	return e.EndDepthFirstWalk
-}
-
-func (e *encoder) EndDepthFirstWalk() {
-	e.Encode(marshalOperation{
-		Type: "Operation",
-		End:  newString("DepthFirstWalk"),
-	})
-}
-
-// BeginReverseDepthFirstWalk marks the start of a replace operation, and
-// returns the encoder to chain the EndReverseDepthFirstWalk call.
-func (e *encoder) BeginReverseDepthFirstWalk() ender {
-	e.Encode(marshalOperation{
-		Type:  "Operation",
-		Begin: newString("ReverseDepthFirstWalk"),
-	})
-	return e.EndReverseDepthFirstWalk
-}
-
-func (e *encoder) EndReverseDepthFirstWalk() {
-	e.Encode(marshalOperation{
-		Type: "Operation",
-		End:  newString("ReverseDepthFirstWalk"),
-	})
-}
-
-// BeginWalk marks the start of a replace operation, and returns the encoder
-// to chain the EndWalk call.
-func (e *encoder) BeginWalk() ender {
-	e.Encode(marshalOperation{
-		Type:  "Operation",
-		Begin: newString("Walk"),
-	})
-	return e.EndWalk
-}
-
-func (e *encoder) EndWalk() {
-	e.Encode(marshalOperation{
-		Type: "Operation",
-		End:  newString("Walk"),
-	})
+	return func(info string) {
+		e.Encode(marshalOperation{
+			Type: "Operation",
+			End:  op,
+			Info: info,
+		})
+	}
 }
 
 // structure for recording graph transformations
@@ -424,15 +364,11 @@ func (s *streamDecode) UnmarshalJSON(d []byte) error {
 // graph state.
 type marshalOperation struct {
 	Type  string
-	Begin *string `json:",omitempty"`
-	End   *string `json:",omitempty"`
-	Info  *string `json:".omitempty"`
+	Begin string `json:",omitempty"`
+	End   string `json:",omitempty"`
+	Info  string `json:",omitempty"`
 }
 
-func newBool(b bool) *bool { return &b }
-
-func newString(s string) *string { return &s }
-
 // decodeGraph decodes a marshalGraph from an encoded graph stream.
 func decodeGraph(r io.Reader) (*marshalGraph, error) {
 	dec := json.NewDecoder(r)

dag/marshal_test.go

@@ -207,6 +207,77 @@ func TestGraphJSON_debugInfo(t *testing.T) {
 	}
 }
 
+// Verify that debug operations appear in the debug output
+func TestGraphJSON_debugOperations(t *testing.T) {
+	var g Graph
+	var buf bytes.Buffer
+	g.SetDebugWriter(&buf)
+
+	debugOp := g.DebugOperation("AddOne", "adding node 1")
+	g.Add(1)
+	debugOp.End("done adding node 1")
+
+	// use an immediate closure to test defers
+	func() {
+		defer g.DebugOperation("AddTwo", "adding nodes 2 and 3").End("done adding 2 and 3")
+		g.Add(2)
+		defer g.DebugOperation("NestedAddThree", "second defer").End("done adding node 3")
+		g.Add(3)
+	}()
+
+	g.Connect(BasicEdge(1, 2))
+
+	dec := json.NewDecoder(bytes.NewReader(buf.Bytes()))
+
+	var ops []string
+	for dec.More() {
+		var d streamDecode
+
+		err := dec.Decode(&d)
+		if err != nil {
+			t.Fatal(err)
+		}
+
+		if d.Type != "Operation" {
+			continue
+		}
+
+		o := &marshalOperation{}
+		err = json.Unmarshal(d.JSON, o)
+		if err != nil {
+			t.Fatal(err)
+		}
+
+		switch {
+		case o.Begin == "AddOne":
+			ops = append(ops, "BeginAddOne")
+		case o.End == "AddOne":
+			ops = append(ops, "EndAddOne")
+		case o.Begin == "AddTwo":
+			ops = append(ops, "BeginAddTwo")
+		case o.End == "AddTwo":
+			ops = append(ops, "EndAddTwo")
+		case o.Begin == "NestedAddThree":
+			ops = append(ops, "BeginAddThree")
+		case o.End == "NestedAddThree":
+			ops = append(ops, "EndAddThree")
+		}
+	}
+
+	expectedOps := []string{
+		"BeginAddOne",
+		"EndAddOne",
+		"BeginAddTwo",
+		"BeginAddThree",
+		"EndAddThree",
+		"EndAddTwo",
+	}
+
+	if strings.Join(ops, ",") != strings.Join(expectedOps, ",") {
+		t.Fatalf("incorrect order of operations: %v", ops)
+	}
+}
+
 const testGraphJSONEmptyStr = `{
   "Type": "Graph",
   "Name": "root",

terraform/graph_builder.go

@@ -49,8 +49,15 @@ func (b *BasicGraphBuilder) Build(path []string) (*Graph, error) {
 			stepName = stepName[dot+1:]
 		}
 
+		debugOp := g.DebugOperation(stepName, "")
 		err := step.Transform(g)
 
+		errMsg := ""
+		if err != nil {
+			errMsg = err.Error()
+		}
+		debugOp.End(errMsg)
+
 		// always log the graph state to see what transformations may have happened
 		debugName := "build-" + stepName
 		if b.Name != "" {