From 797a1b339d6d2a37e99514d51e413fac446a3161 Mon Sep 17 00:00:00 2001 From: James Bardin Date: Fri, 4 Nov 2016 11:30:51 -0400 Subject: [PATCH] DebugInfo and DebugGraph Implement debugInfo and the DebugGraph DebugInfo will be a global variable through which graph debug information can we written to a compressed archive. The DebugInfo methods are all safe for concurrent use, and noop with a nil receiver. The API outside of the terraform package will be to call SetDebugInfo to create the archive, and CloseDebugInfo() to properly close the file. Each write to the archive will be flushed and sync'ed individually, so in the event of a crash or a missing call to Close, the archive can still be recovered. The DebugGraph is a representation of a terraform Graph to be written to the debug archive, currently in dot format. The DebugGraph also contains an internal buffer with Printf and Write methods to add to this buffer. The buffer will be written to an accompanying file in the debug archive along with the graph. This also adds a GraphNodeDebugger interface. Any node implementing `NodeDebug() string` can output information to annotate the debug graph node, and add the data to the log. This interface may change or be removed to provide richer options for debugging graph nodes. The new graph builders all delegate the build to the BasicGraphBuilder. Having a Name field lets us differentiate the actual builder implementation in the debug graphs. --- command/apply.go | 2 + command/meta.go | 10 +- command/plan.go | 6 + main.go | 4 + terraform/context.go | 39 +- terraform/context_import.go | 2 +- terraform/debug.go | 529 ++++++++++++++++++++++++ terraform/diff.go | 16 + terraform/graph.go | 11 +- terraform/graph_builder.go | 28 +- terraform/graph_builder_apply.go | 1 + terraform/graph_builder_destroy_plan.go | 1 + terraform/graph_debug.go | 285 +++++++++++++ terraform/graph_dot.go | 154 +------ terraform/graph_walk.go | 2 + terraform/graph_walk_context.go | 9 +- 16 files changed, 923 insertions(+), 176 deletions(-) create mode 100644 terraform/debug.go create mode 100644 terraform/graph_debug.go diff --git a/command/apply.go b/command/apply.go index 57779143e..1050507e4 100644 --- a/command/apply.go +++ b/command/apply.go @@ -96,6 +96,8 @@ func (c *ApplyCommand) Run(args []string) int { } } + terraform.SetDebugInfo(DefaultDataDir) + // Check for the new apply if experiment.Enabled(experiment.X_newApply) && !experiment.Force() { desc := "Experimental new apply graph has been enabled. This may still\n" + diff --git a/command/meta.go b/command/meta.go index 92f25db1e..ce380676c 100644 --- a/command/meta.go +++ b/command/meta.go @@ -302,12 +302,10 @@ func (m *Meta) Input() bool { // context with the settings from this Meta. func (m *Meta) contextOpts() *terraform.ContextOpts { var opts terraform.ContextOpts = *m.ContextOpts - opts.Hooks = make( - []terraform.Hook, - len(m.ContextOpts.Hooks)+len(m.extraHooks)+1) - opts.Hooks[0] = m.uiHook() - copy(opts.Hooks[1:], m.ContextOpts.Hooks) - copy(opts.Hooks[len(m.ContextOpts.Hooks)+1:], m.extraHooks) + + opts.Hooks = []terraform.Hook{m.uiHook(), &terraform.DebugHook{}} + opts.Hooks = append(opts.Hooks, m.ContextOpts.Hooks...) + opts.Hooks = append(opts.Hooks, m.extraHooks...) vs := make(map[string]interface{}) for k, v := range opts.Variables { diff --git a/command/plan.go b/command/plan.go index ffe83410a..6202362be 100644 --- a/command/plan.go +++ b/command/plan.go @@ -68,6 +68,12 @@ func (c *PlanCommand) Run(args []string) int { return 1 } + err = terraform.SetDebugInfo(DefaultDataDir) + if err != nil { + c.Ui.Error(err.Error()) + return 1 + } + if err := ctx.Input(c.InputMode()); err != nil { c.Ui.Error(fmt.Sprintf("Error configuring: %s", err)) return 1 diff --git a/main.go b/main.go index 2ccba92cc..53bef3d5c 100644 --- a/main.go +++ b/main.go @@ -11,6 +11,7 @@ import ( "github.com/hashicorp/go-plugin" "github.com/hashicorp/terraform/helper/logging" + "github.com/hashicorp/terraform/terraform" "github.com/mattn/go-colorable" "github.com/mitchellh/cli" "github.com/mitchellh/panicwrap" @@ -86,6 +87,9 @@ func realMain() int { } func wrappedMain() int { + // We always need to close the DebugInfo before we exit. + defer terraform.CloseDebugInfo() + log.SetOutput(os.Stderr) log.Printf( "[INFO] Terraform version: %s %s %s", diff --git a/terraform/context.go b/terraform/context.go index c8aac252d..2a223f9d0 100644 --- a/terraform/context.go +++ b/terraform/context.go @@ -231,7 +231,7 @@ func (c *Context) ShadowError() error { // This modifies the configuration in-place, so asking for Input twice // may result in different UI output showing different current values. func (c *Context) Input(mode InputMode) error { - v := c.acquireRun() + v := c.acquireRun("input") defer c.releaseRun(v) if mode&InputModeVar != 0 { @@ -351,7 +351,7 @@ func (c *Context) Input(mode InputMode) error { // In addition to returning the resulting state, this context is updated // with the latest state. func (c *Context) Apply() (*State, error) { - v := c.acquireRun() + v := c.acquireRun("apply") defer c.releaseRun(v) // Copy our own state @@ -448,7 +448,7 @@ func (c *Context) Apply() (*State, error) { // Plan also updates the diff of this context to be the diff generated // by the plan, so Apply can be called after. func (c *Context) Plan() (*Plan, error) { - v := c.acquireRun() + v := c.acquireRun("plan") defer c.releaseRun(v) p := &Plan{ @@ -548,7 +548,7 @@ func (c *Context) Plan() (*Plan, error) { // Even in the case an error is returned, the state will be returned and // will potentially be partially updated. func (c *Context) Refresh() (*State, error) { - v := c.acquireRun() + v := c.acquireRun("refresh") defer c.releaseRun(v) // Copy our own state @@ -594,7 +594,7 @@ func (c *Context) Stop() { // Validate validates the configuration and returns any warnings or errors. func (c *Context) Validate() ([]string, []error) { - v := c.acquireRun() + v := c.acquireRun("validate") defer c.releaseRun(v) var errs error @@ -656,10 +656,12 @@ func (c *Context) SetVariable(k string, v interface{}) { c.variables[k] = v } -func (c *Context) acquireRun() chan<- struct{} { +func (c *Context) acquireRun(phase string) chan<- struct{} { c.l.Lock() defer c.l.Unlock() + dbug.SetPhase(phase) + // Wait for no channel to exist for c.runCh != nil { c.l.Unlock() @@ -685,6 +687,11 @@ func (c *Context) releaseRun(ch chan<- struct{}) { c.l.Lock() defer c.l.Unlock() + // setting the phase to "INVALID" lets us easily detect if we have + // operations happening outside of a run, or we missed setting the proper + // phase + dbug.SetPhase("INVALID") + close(ch) c.runCh = nil } @@ -715,9 +722,14 @@ func (c *Context) walk( log.Printf("[WARN] terraform: shadow graph disabled") } - // Build the real graph walker log.Printf("[DEBUG] Starting graph walk: %s", operation.String()) - walker := &ContextGraphWalker{Context: realCtx, Operation: operation} + + dg, _ := NewDebugGraph("walk", graph, nil) + walker := &ContextGraphWalker{ + Context: realCtx, + Operation: operation, + DebugGraph: dg, + } // Walk the real graph, this will block until it completes realErr := graph.Walk(walker) @@ -736,13 +748,20 @@ func (c *Context) walk( // If we have a shadow graph, wait for that to complete. if shadowCloser != nil { + // create a debug graph for this walk + dg, err := NewDebugGraph("walk-shadow", shadow, nil) + if err != nil { + log.Printf("[ERROR] %v", err) + } + // Build the graph walker for the shadow. We also wrap this in // a panicwrap so that panics are captured. For the shadow graph, // we just want panics to be normal errors rather than to crash // Terraform. shadowWalker := GraphWalkerPanicwrap(&ContextGraphWalker{ - Context: shadowCtx, - Operation: operation, + Context: shadowCtx, + Operation: operation, + DebugGraph: dg, }) // Kick off the shadow walk. This will block on any operations diff --git a/terraform/context_import.go b/terraform/context_import.go index 8ac0e4e14..c79f7f78a 100644 --- a/terraform/context_import.go +++ b/terraform/context_import.go @@ -37,7 +37,7 @@ type ImportTarget struct { // imported. func (c *Context) Import(opts *ImportOpts) (*State, error) { // Hold a lock since we can modify our own state here - v := c.acquireRun() + v := c.acquireRun("import") defer c.releaseRun(v) // Copy our own state diff --git a/terraform/debug.go b/terraform/debug.go new file mode 100644 index 000000000..84471b34e --- /dev/null +++ b/terraform/debug.go @@ -0,0 +1,529 @@ +package terraform + +import ( + "archive/tar" + "bytes" + "compress/gzip" + "encoding/json" + "fmt" + "io" + "os" + "path/filepath" + "sync" + "time" +) + +// DebugInfo is the global handler for writing the debug archive. All methods +// are safe to call concurrently. Setting DebugInfo to nil will disable writing +// the debug archive. All methods are safe to call on the nil value. +var dbug *debugInfo + +// SetDebugInfo initializes the debug handler with a backing file in the +// provided directory. This must be called before any other terraform package +// operations or not at all. Once his is called, CloseDebugInfo should be +// called before program exit. +func SetDebugInfo(path string) error { + if os.Getenv("TF_DEBUG") == "" { + return nil + } + + di, err := newDebugInfoFile(path) + if err != nil { + return err + } + + dbug = di + return nil +} + +// CloseDebugInfo is the exported interface to Close the debug info handler. +// The debug handler needs to be closed before program exit, so we export this +// function to be deferred in the appropriate entrypoint for our executable. +func CloseDebugInfo() error { + return dbug.Close() +} + +// newDebugInfoFile initializes the global debug handler with a backing file in +// the provided directory. +func newDebugInfoFile(dir string) (*debugInfo, error) { + err := os.MkdirAll(dir, 0755) + if err != nil { + return nil, err + } + + // FIXME: not guaranteed unique, but good enough for now + name := fmt.Sprintf("debug-%s", time.Now().Format("2006-01-02-15-04-05.999999999")) + archivePath := filepath.Join(dir, name+".tar.gz") + + f, err := os.OpenFile(archivePath, os.O_RDWR|os.O_CREATE|os.O_EXCL, 0666) + if err != nil { + return nil, err + } + return newDebugInfo(name, f) +} + +// newDebugInfo initializes the global debug handler. +func newDebugInfo(name string, w io.Writer) (*debugInfo, error) { + gz := gzip.NewWriter(w) + + d := &debugInfo{ + name: name, + w: w, + gz: gz, + tar: tar.NewWriter(gz), + } + + // create the subdirs we need + topHdr := &tar.Header{ + Name: name, + Typeflag: tar.TypeDir, + Mode: 0755, + } + graphsHdr := &tar.Header{ + Name: name + "/graphs", + Typeflag: tar.TypeDir, + Mode: 0755, + } + err := d.tar.WriteHeader(topHdr) + // if the first errors, the second will too + err = d.tar.WriteHeader(graphsHdr) + if err != nil { + return nil, err + } + + return d, nil +} + +// debugInfo provides various methods for writing debug information to a +// central archive. The debugInfo struct should be initialized once before any +// output is written, and Close should be called before program exit. All +// exported methods on debugInfo will be safe for concurrent use. The exported +// methods are also all safe to call on a nil pointer, so that there is no need +// for conditional blocks before writing debug information. +// +// Each write operation done by the debugInfo will flush the gzip.Writer and +// tar.Writer, and call Sync() or Flush() on the output writer as needed. This +// ensures that as much data as possible is written to storage in the event of +// a crash. The append format of the tar file, and the stream format of the +// gzip writer allow easy recovery f the data in the event that the debugInfo +// is not closed before program exit. +type debugInfo struct { + sync.Mutex + + // archive root directory name + name string + + // current operation phase + phase string + + // step is monotonic counter for for recording the order of operations + step int + + // flag to protect Close() + closed bool + + // the debug log output is in a tar.gz format, written to the io.Writer w + w io.Writer + gz *gzip.Writer + tar *tar.Writer +} + +// Set the name of the current operational phase in the debug handler. Each file +// in the archive will contain the name of the phase in which it was created, +// i.e. "input", "apply", "plan", "refresh", "validate" +func (d *debugInfo) SetPhase(phase string) { + if d == nil { + return + } + d.Lock() + defer d.Unlock() + + d.phase = phase +} + +// Close the debugInfo, finalizing the data in storage. This closes the +// tar.Writer, the gzip.Wrtier, and if the output writer is an io.Closer, it is +// also closed. +func (d *debugInfo) Close() error { + if d == nil { + return nil + } + + d.Lock() + defer d.Unlock() + + if d.closed { + return nil + } + d.closed = true + + d.tar.Close() + d.gz.Close() + + if c, ok := d.w.(io.Closer); ok { + return c.Close() + } + return nil +} + +type syncer interface { + Sync() error +} + +type flusher interface { + Flush() error +} + +// Flush the tar.Writer and the gzip.Writer. Flush() or Sync() will be called +// on the output writer if they are available. +func (d *debugInfo) flush() { + d.tar.Flush() + d.gz.Flush() + + if f, ok := d.w.(flusher); ok { + f.Flush() + } + + if s, ok := d.w.(syncer); ok { + s.Sync() + } +} + +// 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(dg *DebugGraph) error { + if d == nil { + return nil + } + + if dg == 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() + + d.writeFile(dg.Name, dg.LogBytes()) + + dotPath := fmt.Sprintf("%s/graphs/%d-%s-%s.dot", d.name, d.step, d.phase, dg.Name) + d.step++ + + dotBytes := dg.DotBytes() + 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 { + return nil + } + + d.Lock() + defer d.Unlock() + return d.writeFile(name, data) +} + +func (d *debugInfo) writeFile(name string, data []byte) error { + defer d.flush() + path := fmt.Sprintf("%s/%d-%s-%s", d.name, d.step, d.phase, name) + d.step++ + + hdr := &tar.Header{ + Name: path, + Mode: 0644, + Size: int64(len(data)), + } + err := d.tar.WriteHeader(hdr) + if err != nil { + return err + } + + _, err = d.tar.Write(data) + return err +} + +// DebugHook implements all methods of the terraform.Hook interface, and writes +// the arguments to a file in the archive. When a suitable format for the +// argument isn't available, the argument is encoded using json.Marshal. If the +// debug handler is nil, all DebugHook methods are noop, so no time is spent in +// marshaling the data structures. +type DebugHook struct{} + +func (*DebugHook) PreApply(ii *InstanceInfo, is *InstanceState, id *InstanceDiff) (HookAction, error) { + if dbug == nil { + return HookActionContinue, nil + } + + var buf bytes.Buffer + + if ii != nil { + buf.WriteString(ii.HumanId() + "\n") + } + + if is != nil { + buf.WriteString(is.String() + "\n") + } + + idCopy, err := id.Copy() + if err != nil { + return HookActionContinue, err + } + js, err := json.MarshalIndent(idCopy, "", " ") + if err != nil { + return HookActionContinue, err + } + buf.Write(js) + + dbug.WriteFile("hook-PreApply", buf.Bytes()) + + return HookActionContinue, nil +} + +func (*DebugHook) PostApply(ii *InstanceInfo, is *InstanceState, err error) (HookAction, error) { + if dbug == nil { + return HookActionContinue, nil + } + + var buf bytes.Buffer + + if ii != nil { + buf.WriteString(ii.HumanId() + "\n") + } + + if is != nil { + buf.WriteString(is.String() + "\n") + } + + if err != nil { + buf.WriteString(err.Error()) + } + + dbug.WriteFile("hook-PostApply", buf.Bytes()) + + return HookActionContinue, nil +} + +func (*DebugHook) PreDiff(ii *InstanceInfo, is *InstanceState) (HookAction, error) { + if dbug == nil { + return HookActionContinue, nil + } + + var buf bytes.Buffer + if ii != nil { + buf.WriteString(ii.HumanId() + "\n") + } + + if is != nil { + buf.WriteString(is.String()) + buf.WriteString("\n") + } + dbug.WriteFile("hook-PreDiff", buf.Bytes()) + + return HookActionContinue, nil +} + +func (*DebugHook) PostDiff(ii *InstanceInfo, id *InstanceDiff) (HookAction, error) { + if dbug == nil { + return HookActionContinue, nil + } + + var buf bytes.Buffer + if ii != nil { + buf.WriteString(ii.HumanId() + "\n") + } + + idCopy, err := id.Copy() + if err != nil { + return HookActionContinue, err + } + js, err := json.MarshalIndent(idCopy, "", " ") + if err != nil { + return HookActionContinue, err + } + buf.Write(js) + + dbug.WriteFile("hook-PostDiff", buf.Bytes()) + + return HookActionContinue, nil +} + +func (*DebugHook) PreProvisionResource(ii *InstanceInfo, is *InstanceState) (HookAction, error) { + if dbug == nil { + return HookActionContinue, nil + } + + var buf bytes.Buffer + if ii != nil { + buf.WriteString(ii.HumanId() + "\n") + } + + if is != nil { + buf.WriteString(is.String()) + buf.WriteString("\n") + } + dbug.WriteFile("hook-PreProvisionResource", buf.Bytes()) + + return HookActionContinue, nil +} + +func (*DebugHook) PostProvisionResource(ii *InstanceInfo, is *InstanceState) (HookAction, error) { + if dbug == nil { + return HookActionContinue, nil + } + + var buf bytes.Buffer + if ii != nil { + buf.WriteString(ii.HumanId()) + buf.WriteString("\n") + } + + if is != nil { + buf.WriteString(is.String()) + buf.WriteString("\n") + } + dbug.WriteFile("hook-PostProvisionResource", buf.Bytes()) + return HookActionContinue, nil +} + +func (*DebugHook) PreProvision(ii *InstanceInfo, s string) (HookAction, error) { + if dbug == nil { + return HookActionContinue, nil + } + + var buf bytes.Buffer + if ii != nil { + buf.WriteString(ii.HumanId()) + buf.WriteString("\n") + } + buf.WriteString(s + "\n") + + dbug.WriteFile("hook-PreProvision", buf.Bytes()) + return HookActionContinue, nil +} + +func (*DebugHook) PostProvision(ii *InstanceInfo, s string) (HookAction, error) { + if dbug == nil { + return HookActionContinue, nil + } + + var buf bytes.Buffer + if ii != nil { + buf.WriteString(ii.HumanId() + "\n") + } + buf.WriteString(s + "\n") + + dbug.WriteFile("hook-PostProvision", buf.Bytes()) + return HookActionContinue, nil +} + +func (*DebugHook) ProvisionOutput(ii *InstanceInfo, s1 string, s2 string) { + if dbug == nil { + return + } + + var buf bytes.Buffer + if ii != nil { + buf.WriteString(ii.HumanId()) + buf.WriteString("\n") + } + buf.WriteString(s1 + "\n") + buf.WriteString(s2 + "\n") + + dbug.WriteFile("hook-ProvisionOutput", buf.Bytes()) +} + +func (*DebugHook) PreRefresh(ii *InstanceInfo, is *InstanceState) (HookAction, error) { + if dbug == nil { + return HookActionContinue, nil + } + + var buf bytes.Buffer + if ii != nil { + buf.WriteString(ii.HumanId() + "\n") + } + + if is != nil { + buf.WriteString(is.String()) + buf.WriteString("\n") + } + dbug.WriteFile("hook-PreRefresh", buf.Bytes()) + return HookActionContinue, nil +} + +func (*DebugHook) PostRefresh(ii *InstanceInfo, is *InstanceState) (HookAction, error) { + if dbug == nil { + return HookActionContinue, nil + } + + var buf bytes.Buffer + if ii != nil { + buf.WriteString(ii.HumanId()) + buf.WriteString("\n") + } + + if is != nil { + buf.WriteString(is.String()) + buf.WriteString("\n") + } + dbug.WriteFile("hook-PostRefresh", buf.Bytes()) + return HookActionContinue, nil +} + +func (*DebugHook) PreImportState(ii *InstanceInfo, s string) (HookAction, error) { + if dbug == nil { + return HookActionContinue, nil + } + + var buf bytes.Buffer + if ii != nil { + buf.WriteString(ii.HumanId()) + buf.WriteString("\n") + } + buf.WriteString(s + "\n") + + dbug.WriteFile("hook-PreImportState", buf.Bytes()) + return HookActionContinue, nil +} + +func (*DebugHook) PostImportState(ii *InstanceInfo, iss []*InstanceState) (HookAction, error) { + if dbug == nil { + return HookActionContinue, nil + } + + var buf bytes.Buffer + + if ii != nil { + buf.WriteString(ii.HumanId() + "\n") + } + + for _, is := range iss { + if is != nil { + buf.WriteString(is.String() + "\n") + } + } + dbug.WriteFile("hook-PostImportState", buf.Bytes()) + return HookActionContinue, nil +} + +// skip logging this for now, since it could be huge +func (*DebugHook) PostStateUpdate(*State) (HookAction, error) { + return HookActionContinue, nil +} diff --git a/terraform/diff.go b/terraform/diff.go index 5a04f4043..b3a8fe5de 100644 --- a/terraform/diff.go +++ b/terraform/diff.go @@ -331,6 +331,9 @@ type InstanceDiff struct { DestroyTainted bool } +func (d *InstanceDiff) Lock() { d.mu.Lock() } +func (d *InstanceDiff) Unlock() { d.mu.Unlock() } + // ResourceAttrDiff is the diff of a single attribute of a resource. type ResourceAttrDiff struct { Old string // Old Value @@ -375,6 +378,19 @@ func NewInstanceDiff() *InstanceDiff { return &InstanceDiff{Attributes: make(map[string]*ResourceAttrDiff)} } +func (d *InstanceDiff) Copy() (*InstanceDiff, error) { + if d == nil { + return nil, nil + } + + dCopy, err := copystructure.Config{Lock: true}.Copy(d) + if err != nil { + return nil, err + } + + return dCopy.(*InstanceDiff), nil +} + // ChangeType returns the DiffChangeType represented by the diff // for this single instance. func (d *InstanceDiff) ChangeType() DiffChangeType { diff --git a/terraform/graph.go b/terraform/graph.go index 46762de5d..5f114a5c4 100644 --- a/terraform/graph.go +++ b/terraform/graph.go @@ -197,6 +197,7 @@ func (g *Graph) Dependable(n string) dag.Vertex { // will be walked with full parallelism, so the walker should expect // to be called in concurrently. func (g *Graph) Walk(walker GraphWalker) error { + defer dbug.WriteGraph(walker.Debug()) return g.walk(walker) } @@ -253,7 +254,10 @@ func (g *Graph) walk(walker GraphWalker) error { }() walker.EnterVertex(v) - defer func() { walker.ExitVertex(v, rerr) }() + defer func() { + walker.Debug().DebugNode(v) + walker.ExitVertex(v, rerr) + }() // vertexCtx is the context that we use when evaluating. This // is normally the context of our graph but can be overridden @@ -275,6 +279,7 @@ func (g *Graph) walk(walker GraphWalker) error { // Allow the walker to change our tree if needed. Eval, // then callback with the output. log.Printf("[DEBUG] vertex '%s.%s': evaluating", path, dag.VertexName(v)) + walker.Debug().Printf("[DEBUG] vertex %T(%s.%s): evaluating\n", v, path, dag.VertexName(v)) tree = walker.EnterEvalTree(v, tree) output, err := Eval(tree, vertexCtx) if rerr = walker.ExitEvalTree(v, output, err); rerr != nil { @@ -288,6 +293,7 @@ func (g *Graph) walk(walker GraphWalker) error { "[DEBUG] vertex '%s.%s': expanding/walking dynamic subgraph", path, dag.VertexName(v)) + walker.Debug().Printf("[DEBUG] vertex %T(%s.%s): expanding\n", v, path, dag.VertexName(v)) g, err := ev.DynamicExpand(vertexCtx) if err != nil { rerr = err @@ -308,6 +314,9 @@ func (g *Graph) walk(walker GraphWalker) error { path, dag.VertexName(v)) + walker.Debug().Printf( + "[DEBUG] vertex %T(%s.%s): subgraph\n", v, path, dag.VertexName(v)) + if rerr = sn.Subgraph().walk(walker); rerr != nil { return } diff --git a/terraform/graph_builder.go b/terraform/graph_builder.go index ff3145df0..d27a524dd 100644 --- a/terraform/graph_builder.go +++ b/terraform/graph_builder.go @@ -1,7 +1,9 @@ package terraform import ( + "fmt" "log" + "strings" "github.com/hashicorp/terraform/config/module" ) @@ -21,6 +23,8 @@ type GraphBuilder interface { type BasicGraphBuilder struct { Steps []GraphTransformer Validate bool + // Optional name to add to the graph debug log + Name string } func (b *BasicGraphBuilder) Build(path []string) (*Graph, error) { @@ -30,13 +34,26 @@ func (b *BasicGraphBuilder) Build(path []string) (*Graph, error) { continue } - if err := step.Transform(g); err != nil { - return g, err + stepName := fmt.Sprintf("%T", step) + dot := strings.LastIndex(stepName, ".") + if dot >= 0 { + stepName = stepName[dot+1:] } - log.Printf( - "[TRACE] Graph after step %T:\n\n%s", - step, g.StringWithNodeTypes()) + err := step.Transform(g) + + // always log the graph state to see what transformations may have happened + debugName := "build-" + stepName + if b.Name != "" { + debugName = b.Name + "-" + debugName + } + + dg, _ := NewDebugGraph(debugName, g, nil) + dbug.WriteGraph(dg) + + if err != nil { + return g, err + } } // Validate the graph structure @@ -97,6 +114,7 @@ func (b *BuiltinGraphBuilder) Build(path []string) (*Graph, error) { basic := &BasicGraphBuilder{ Steps: b.Steps(path), Validate: b.Validate, + Name: "builtin", } return basic.Build(path) diff --git a/terraform/graph_builder_apply.go b/terraform/graph_builder_apply.go index 1d10be39a..1d88b706d 100644 --- a/terraform/graph_builder_apply.go +++ b/terraform/graph_builder_apply.go @@ -40,6 +40,7 @@ func (b *ApplyGraphBuilder) Build(path []string) (*Graph, error) { return (&BasicGraphBuilder{ Steps: b.Steps(), Validate: true, + Name: "apply", }).Build(path) } diff --git a/terraform/graph_builder_destroy_plan.go b/terraform/graph_builder_destroy_plan.go index e0cd231f3..69955f56a 100644 --- a/terraform/graph_builder_destroy_plan.go +++ b/terraform/graph_builder_destroy_plan.go @@ -26,6 +26,7 @@ func (b *DestroyPlanGraphBuilder) Build(path []string) (*Graph, error) { return (&BasicGraphBuilder{ Steps: b.Steps(), Validate: true, + Name: "destroy", }).Build(path) } diff --git a/terraform/graph_debug.go b/terraform/graph_debug.go new file mode 100644 index 000000000..d6300a258 --- /dev/null +++ b/terraform/graph_debug.go @@ -0,0 +1,285 @@ +package terraform + +import ( + "bytes" + "fmt" + "sync" + + "github.com/davecgh/go-spew/spew" + "github.com/hashicorp/terraform/dag" + "github.com/hashicorp/terraform/dot" +) + +// The NodeDebug method outputs debug information to annotate the graphs +// stored in the DebugInfo +type GraphNodeDebugger interface { + NodeDebug() string +} + +type GraphNodeDebugOrigin interface { + DotOrigin() bool +} +type DebugGraph struct { + // TODO: can we combine this and dot.Graph into a generalized graph representation? + sync.Mutex + Name string + + step int + buf bytes.Buffer + + Dot *dot.Graph + dotOpts *GraphDotOpts +} + +// DebugGraph holds a dot representation of the Terraform graph, and can be +// written out to the DebugInfo log with DebugInfo.WriteGraph. A DebugGraph can +// log data to it's internal buffer via the Printf and Write methods, which +// will be also be written out to the DebugInfo archive. +func NewDebugGraph(name string, g *Graph, opts *GraphDotOpts) (*DebugGraph, error) { + dg := &DebugGraph{ + Name: name, + dotOpts: opts, + } + + err := dg.build(g) + if err != nil { + dbug.WriteFile(dg.Name, []byte(err.Error())) + return nil, err + } + return dg, nil +} + +// Printf to the internal buffer +func (dg *DebugGraph) Printf(f string, args ...interface{}) (int, error) { + if dg == nil { + return 0, nil + } + dg.Lock() + defer dg.Unlock() + return fmt.Fprintf(&dg.buf, f, args...) +} + +// Write to the internal buffer +func (dg *DebugGraph) Write(b []byte) (int, error) { + if dg == nil { + return 0, nil + } + dg.Lock() + defer dg.Unlock() + return dg.buf.Write(b) +} + +func (dg *DebugGraph) LogBytes() []byte { + if dg == nil { + return nil + } + dg.Lock() + defer dg.Unlock() + return dg.buf.Bytes() +} + +func (dg *DebugGraph) DotBytes() []byte { + if dg == nil { + return nil + } + dg.Lock() + defer dg.Unlock() + return dg.Dot.Bytes() +} + +func (dg *DebugGraph) DebugNode(v interface{}) { + if dg == nil { + return + } + dg.Lock() + defer dg.Unlock() + + name := graphDotNodeName("root", v) + + var node *dot.Node + // TODO: recursive + for _, sg := range dg.Dot.Subgraphs { + node, _ = sg.GetNode(name) + if node != nil { + break + } + } + + // record as much of the node data structure as we can + spew.Fdump(&dg.buf, v) + + // for now, record the order of visits in the node label + if node != nil { + node.Attrs["label"] = fmt.Sprintf("%s %d", node.Attrs["label"], ord) + } + + // if the node provides debug output, insert it into the graph, and log it + if nd, ok := v.(GraphNodeDebugger); ok { + out := nd.NodeDebug() + if node != nil { + node.Attrs["comment"] = out + dg.buf.WriteString(fmt.Sprintf("NodeDebug (%s):'%s'\n", name, out)) + } + } +} + +// takes a Terraform Graph and build the internal debug graph +func (dg *DebugGraph) build(g *Graph) error { + if dg == nil { + return nil + } + dg.Lock() + defer dg.Unlock() + + dg.Dot = dot.NewGraph(map[string]string{ + "compound": "true", + "newrank": "true", + }) + dg.Dot.Directed = true + + if dg.dotOpts == nil { + dg.dotOpts = &GraphDotOpts{ + DrawCycles: true, + MaxDepth: -1, + Verbose: true, + } + } + + err := dg.buildSubgraph("root", g, 0) + if err != nil { + return err + } + + return nil +} + +func (dg *DebugGraph) buildSubgraph(modName string, g *Graph, modDepth int) error { + // Respect user-specified module depth + if dg.dotOpts.MaxDepth >= 0 && modDepth > dg.dotOpts.MaxDepth { + return nil + } + + // Begin module subgraph + var sg *dot.Subgraph + if modDepth == 0 { + sg = dg.Dot.AddSubgraph(modName) + } else { + sg = dg.Dot.AddSubgraph(modName) + sg.Cluster = true + sg.AddAttr("label", modName) + } + + origins, err := graphDotFindOrigins(g) + if err != nil { + return err + } + + drawableVertices := make(map[dag.Vertex]struct{}) + toDraw := make([]dag.Vertex, 0, len(g.Vertices())) + subgraphVertices := make(map[dag.Vertex]*Graph) + + walk := func(v dag.Vertex, depth int) error { + // We only care about nodes that yield non-empty Dot strings. + if dn, ok := v.(GraphNodeDotter); !ok { + return nil + } else if dn.DotNode("fake", dg.dotOpts) == nil { + return nil + } + + drawableVertices[v] = struct{}{} + toDraw = append(toDraw, v) + + if sn, ok := v.(GraphNodeSubgraph); ok { + subgraphVertices[v] = sn.Subgraph() + } + return nil + } + + if err := g.ReverseDepthFirstWalk(origins, walk); err != nil { + return err + } + + for _, v := range toDraw { + dn := v.(GraphNodeDotter) + nodeName := graphDotNodeName(modName, v) + sg.AddNode(dn.DotNode(nodeName, dg.dotOpts)) + + // Draw all the edges from this vertex to other nodes + targets := dag.AsVertexList(g.DownEdges(v)) + for _, t := range targets { + target := t.(dag.Vertex) + // Only want edges where both sides are drawable. + if _, ok := drawableVertices[target]; !ok { + continue + } + + if err := sg.AddEdgeBetween( + graphDotNodeName(modName, v), + graphDotNodeName(modName, target), + map[string]string{}); err != nil { + return err + } + } + } + + // Recurse into any subgraphs + for _, v := range toDraw { + subgraph, ok := subgraphVertices[v] + if !ok { + continue + } + + err := dg.buildSubgraph(dag.VertexName(v), subgraph, modDepth+1) + if err != nil { + return err + } + } + + if dg.dotOpts.DrawCycles { + colors := []string{"red", "green", "blue"} + for ci, cycle := range g.Cycles() { + for i, c := range cycle { + // Catch the last wrapping edge of the cycle + if i+1 >= len(cycle) { + i = -1 + } + edgeAttrs := map[string]string{ + "color": colors[ci%len(colors)], + "penwidth": "2.0", + } + + if err := sg.AddEdgeBetween( + graphDotNodeName(modName, c), + graphDotNodeName(modName, cycle[i+1]), + edgeAttrs); err != nil { + return err + } + + } + } + } + + return nil +} + +func graphDotNodeName(modName, v dag.Vertex) string { + return fmt.Sprintf("[%s] %s", modName, dag.VertexName(v)) +} + +func graphDotFindOrigins(g *Graph) ([]dag.Vertex, error) { + var origin []dag.Vertex + + for _, v := range g.Vertices() { + if dr, ok := v.(GraphNodeDebugOrigin); ok { + if dr.DotOrigin() { + origin = append(origin, v) + } + } + } + + if len(origin) == 0 { + return nil, fmt.Errorf("No DOT origin nodes found.\nGraph: %s", g.String()) + } + + return origin, nil +} diff --git a/terraform/graph_dot.go b/terraform/graph_dot.go index b9313fa24..c7a953796 100644 --- a/terraform/graph_dot.go +++ b/terraform/graph_dot.go @@ -1,11 +1,6 @@ package terraform -import ( - "fmt" - - "github.com/hashicorp/terraform/dag" - "github.com/hashicorp/terraform/dot" -) +import "github.com/hashicorp/terraform/dot" // GraphNodeDotter can be implemented by a node to cause it to be included // in the dot graph. The Dot method will be called which is expected to @@ -18,10 +13,6 @@ type GraphNodeDotter interface { DotNode(string, *GraphDotOpts) *dot.Node } -type GraphNodeDotOrigin interface { - DotOrigin() bool -} - // GraphDotOpts are the options for generating a dot formatted Graph. type GraphDotOpts struct { // Allows some nodes to decide to only show themselves when the user has @@ -38,148 +29,9 @@ type GraphDotOpts struct { // GraphDot returns the dot formatting of a visual representation of // the given Terraform graph. func GraphDot(g *Graph, opts *GraphDotOpts) (string, error) { - dg := dot.NewGraph(map[string]string{ - "compound": "true", - "newrank": "true", - }) - dg.Directed = true - - err := graphDotSubgraph(dg, "root", g, opts, 0) + dg, err := NewDebugGraph("root", g, opts) if err != nil { return "", err } - - return dg.String(), nil -} - -func graphDotSubgraph( - dg *dot.Graph, modName string, g *Graph, opts *GraphDotOpts, modDepth int) error { - // Respect user-specified module depth - if opts.MaxDepth >= 0 && modDepth > opts.MaxDepth { - return nil - } - - // Begin module subgraph - var sg *dot.Subgraph - if modDepth == 0 { - sg = dg.AddSubgraph(modName) - } else { - sg = dg.AddSubgraph(modName) - sg.Cluster = true - sg.AddAttr("label", modName) - } - - origins, err := graphDotFindOrigins(g) - if err != nil { - return err - } - - drawableVertices := make(map[dag.Vertex]struct{}) - toDraw := make([]dag.Vertex, 0, len(g.Vertices())) - subgraphVertices := make(map[dag.Vertex]*Graph) - - walk := func(v dag.Vertex, depth int) error { - // We only care about nodes that yield non-empty Dot strings. - if dn, ok := v.(GraphNodeDotter); !ok { - return nil - } else if dn.DotNode("fake", opts) == nil { - return nil - } - - drawableVertices[v] = struct{}{} - toDraw = append(toDraw, v) - - if sn, ok := v.(GraphNodeSubgraph); ok { - subgraphVertices[v] = sn.Subgraph() - } - return nil - } - - if err := g.ReverseDepthFirstWalk(origins, walk); err != nil { - return err - } - - for _, v := range toDraw { - dn := v.(GraphNodeDotter) - nodeName := graphDotNodeName(modName, v) - sg.AddNode(dn.DotNode(nodeName, opts)) - - // Draw all the edges from this vertex to other nodes - targets := dag.AsVertexList(g.DownEdges(v)) - for _, t := range targets { - target := t.(dag.Vertex) - // Only want edges where both sides are drawable. - if _, ok := drawableVertices[target]; !ok { - continue - } - - if err := sg.AddEdgeBetween( - graphDotNodeName(modName, v), - graphDotNodeName(modName, target), - map[string]string{}); err != nil { - return err - } - } - } - - // Recurse into any subgraphs - for _, v := range toDraw { - subgraph, ok := subgraphVertices[v] - if !ok { - continue - } - - err := graphDotSubgraph(dg, dag.VertexName(v), subgraph, opts, modDepth+1) - if err != nil { - return err - } - } - - if opts.DrawCycles { - colors := []string{"red", "green", "blue"} - for ci, cycle := range g.Cycles() { - for i, c := range cycle { - // Catch the last wrapping edge of the cycle - if i+1 >= len(cycle) { - i = -1 - } - edgeAttrs := map[string]string{ - "color": colors[ci%len(colors)], - "penwidth": "2.0", - } - - if err := sg.AddEdgeBetween( - graphDotNodeName(modName, c), - graphDotNodeName(modName, cycle[i+1]), - edgeAttrs); err != nil { - return err - } - - } - } - } - - return nil -} - -func graphDotNodeName(modName, v dag.Vertex) string { - return fmt.Sprintf("[%s] %s", modName, dag.VertexName(v)) -} - -func graphDotFindOrigins(g *Graph) ([]dag.Vertex, error) { - var origin []dag.Vertex - - for _, v := range g.Vertices() { - if dr, ok := v.(GraphNodeDotOrigin); ok { - if dr.DotOrigin() { - origin = append(origin, v) - } - } - } - - if len(origin) == 0 { - return nil, fmt.Errorf("No DOT origin nodes found.\nGraph: %s", g.String()) - } - - return origin, nil + return dg.Dot.String(), nil } diff --git a/terraform/graph_walk.go b/terraform/graph_walk.go index 34ce6f640..1e49f2162 100644 --- a/terraform/graph_walk.go +++ b/terraform/graph_walk.go @@ -13,6 +13,7 @@ type GraphWalker interface { ExitVertex(dag.Vertex, error) EnterEvalTree(dag.Vertex, EvalNode) EvalNode ExitEvalTree(dag.Vertex, interface{}, error) error + Debug() *DebugGraph } // GrpahWalkerPanicwrapper can be optionally implemented to catch panics @@ -58,3 +59,4 @@ func (NullGraphWalker) EnterEvalTree(v dag.Vertex, n EvalNode) EvalNode { return func (NullGraphWalker) ExitEvalTree(dag.Vertex, interface{}, error) error { return nil } +func (NullGraphWalker) Debug() *DebugGraph { return nil } diff --git a/terraform/graph_walk_context.go b/terraform/graph_walk_context.go index 459fcdec9..9f3051b1d 100644 --- a/terraform/graph_walk_context.go +++ b/terraform/graph_walk_context.go @@ -15,8 +15,9 @@ type ContextGraphWalker struct { NullGraphWalker // Configurable values - Context *Context - Operation walkOperation + Context *Context + Operation walkOperation + DebugGraph *DebugGraph // Outputs, do not set these. Do not read these while the graph // is being walked. @@ -144,6 +145,10 @@ func (w *ContextGraphWalker) ExitEvalTree( return nil } +func (w *ContextGraphWalker) Debug() *DebugGraph { + return w.DebugGraph +} + func (w *ContextGraphWalker) init() { w.contexts = make(map[string]*BuiltinEvalContext, 5) w.providerCache = make(map[string]ResourceProvider, 5)