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

@@ -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" +

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,
+	opts.Hooks = []terraform.Hook{m.uiHook(), &terraform.DebugHook{}}
-		len(m.ContextOpts.Hooks)+len(m.extraHooks)+1)
+	opts.Hooks = append(opts.Hooks, m.ContextOpts.Hooks...)
-	opts.Hooks[0] = m.uiHook()
+	opts.Hooks = append(opts.Hooks, m.extraHooks...)
-	copy(opts.Hooks[1:], m.ContextOpts.Hooks)
-	copy(opts.Hooks[len(m.ContextOpts.Hooks)+1:], m.extraHooks)
 
 	vs := make(map[string]interface{})
 	for k, v := range opts.Variables {

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

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",

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,6 +748,12 @@ 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
@@ -743,6 +761,7 @@ func (c *Context) walk(
 		shadowWalker := GraphWalkerPanicwrap(&ContextGraphWalker{
 			Context:    shadowCtx,
 			Operation:  operation,
+			DebugGraph: dg,
 		})
 
 		// Kick off the shadow walk. This will block on any operations

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

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
+}

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 {

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
 			}

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 {
+		stepName := fmt.Sprintf("%T", step)
-			return g, err
+		dot := strings.LastIndex(stepName, ".")
+		if dot >= 0 {
+			stepName = stepName[dot+1:]
 		}
 
-		log.Printf(
+		err := step.Transform(g)
-			"[TRACE] Graph after step %T:\n\n%s",
+
-			step, g.StringWithNodeTypes())
+		// 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)

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)
 }
 

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)
 }
 

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
+}

terraform/graph_dot.go

@@ -1,11 +1,6 @@
 package terraform
 
-import (
+import "github.com/hashicorp/terraform/dot"
-	"fmt"
-
-	"github.com/hashicorp/terraform/dag"
-	"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{
+	dg, err := NewDebugGraph("root", g, opts)
-		"compound": "true",
-		"newrank":  "true",
-	})
-	dg.Directed = true
-
-	err := graphDotSubgraph(dg, "root", g, opts, 0)
 	if err != nil {
 		return "", err
 	}
-
+	return dg.Dot.String(), nil
-	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
 }

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 }

terraform/graph_walk_context.go

@@ -17,6 +17,7 @@ type ContextGraphWalker struct {
 	// Configurable values
 	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)