From 6d30b601441c82ddcada63890da9daf1e18daaa6 Mon Sep 17 00:00:00 2001 From: James Bardin Date: Tue, 15 Nov 2016 10:15:52 -0500 Subject: [PATCH 1/3] Add DebugVisitInfo This encodes vertex debug information into the graph log when a vertex is visited during a walk operation. These can ordered to show how the Graph was walked. Add a mutex to the encoder so it can be used during a parallel walk. Moved string literal constants used for marshaling to pre-defined constants. Did some renaming to make the marshal* structures more consistent. --- dag/dag.go | 6 ++--- dag/graph.go | 12 ++++++--- dag/marshal.go | 54 +++++++++++++++++++++++++------------ dag/marshal_test.go | 65 +++++++++++++++++++++++++++++++++++++++++---- 4 files changed, 109 insertions(+), 28 deletions(-) diff --git a/dag/dag.go b/dag/dag.go index 3fd9e48f1..ed7d77e99 100644 --- a/dag/dag.go +++ b/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)) diff --git a/dag/graph.go b/dag/graph.go index fa33409cf..e7517a206 100644 --- a/dag/graph.go +++ b/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 diff --git a/dag/marshal.go b/dag/marshal.go index 32e1e945d..0b2f22517 100644 --- a/dag/marshal.go +++ b/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, } diff --git a/dag/marshal_test.go b/dag/marshal_test.go index 1bff410a1..14daf6424 100644 --- a/dag/marshal_test.go +++ b/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", From bb137f4bfb1f2355f9f8824c3735a5f2a4c7ed8b Mon Sep 17 00:00:00 2001 From: James Bardin Date: Tue, 15 Nov 2016 10:30:50 -0500 Subject: [PATCH 2/3] Remove the dot graphs from the debug log, and record the walk visits in the debug information. --- terraform/debug.go | 34 ---------------------------------- terraform/debug_test.go | 24 +++--------------------- terraform/graph.go | 1 + terraform/graph_builder.go | 9 --------- 4 files changed, 4 insertions(+), 64 deletions(-) diff --git a/terraform/debug.go b/terraform/debug.go index c2bd223f0..168bbd55f 100644 --- a/terraform/debug.go +++ b/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 { diff --git a/terraform/debug_test.go b/terraform/debug_test.go index 342a86b98..927632350 100644 --- a/terraform/debug_test.go +++ b/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") } } diff --git a/terraform/graph.go b/terraform/graph.go index e4ff7a710..60258490d 100644 --- a/terraform/graph.go +++ b/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, diff --git a/terraform/graph_builder.go b/terraform/graph_builder.go index 9f2d9e97f..2e5ff8e96 100644 --- a/terraform/graph_builder.go +++ b/terraform/graph_builder.go @@ -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 } From 3df3b992765ad57d30f215c3f0b864ec00105875 Mon Sep 17 00:00:00 2001 From: James Bardin Date: Tue, 15 Nov 2016 16:36:10 -0500 Subject: [PATCH 3/3] Make sure each GraphBuilder has a Name Ensure that each instance of BasucGraphBuilder gets a name corresponding to the Builder which created it. This allows us to differentiate the graphs in the logs. --- terraform/graph_builder.go | 4 ++-- terraform/graph_builder_apply.go | 2 +- terraform/graph_builder_destroy_plan.go | 2 +- terraform/graph_builder_import.go | 1 + terraform/graph_builder_plan.go | 2 +- terraform/graph_config_node_resource.go | 6 +++++- terraform/node_resource_destroy.go | 5 ++++- terraform/node_resource_plan.go | 6 +++++- terraform/transform_destroy_cbd.go | 1 + 9 files changed, 21 insertions(+), 8 deletions(-) diff --git a/terraform/graph_builder.go b/terraform/graph_builder.go index 2e5ff8e96..fb850df18 100644 --- a/terraform/graph_builder.go +++ b/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 } @@ -125,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) diff --git a/terraform/graph_builder_apply.go b/terraform/graph_builder_apply.go index 601792721..1f8794c25 100644 --- a/terraform/graph_builder_apply.go +++ b/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) } diff --git a/terraform/graph_builder_destroy_plan.go b/terraform/graph_builder_destroy_plan.go index 62f33728d..5a85f9a63 100644 --- a/terraform/graph_builder_destroy_plan.go +++ b/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) } diff --git a/terraform/graph_builder_import.go b/terraform/graph_builder_import.go index 7029a1bdf..2a877515d 100644 --- a/terraform/graph_builder_import.go +++ b/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) } diff --git a/terraform/graph_builder_plan.go b/terraform/graph_builder_plan.go index 43e709f7f..b7d6c8aa1 100644 --- a/terraform/graph_builder_plan.go +++ b/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) } diff --git a/terraform/graph_config_node_resource.go b/terraform/graph_config_node_resource.go index 70dfc2a2b..cecedb6ec 100644 --- a/terraform/graph_config_node_resource.go +++ b/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()) } diff --git a/terraform/node_resource_destroy.go b/terraform/node_resource_destroy.go index af52d1e59..b15a0eb46 100644 --- a/terraform/node_resource_destroy.go +++ b/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()) } diff --git a/terraform/node_resource_plan.go b/terraform/node_resource_plan.go index dc5f653b8..c4694d493 100644 --- a/terraform/node_resource_plan.go +++ b/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()) } diff --git a/terraform/transform_destroy_cbd.go b/terraform/transform_destroy_cbd.go index 0dde08888..4b3f45b1f 100644 --- a/terraform/transform_destroy_cbd.go +++ b/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