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)