Merge pull request #9666 from hashicorp/jbardin/debug

preliminary debug output

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

@@ -300,12 +300,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 {

command/plan.go

@@ -72,6 +72,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

dot/graph.go

@@ -132,6 +132,19 @@ func (g *Graph) String() string {
 	return w.String()
 }
 
+// Returns the DOT representation of this Graph.
+func (g *Graph) Bytes() []byte {
+	w := newGraphWriter()
+
+	g.drawHeader(w)
+	w.Indent()
+	g.drawBody(w)
+	w.Unindent()
+	g.drawFooter(w)
+
+	return w.Bytes()
+}
+
 func (g *Graph) drawHeader(w *graphWriter) {
 	if g.Directed {
 		w.Printf("digraph {\n")

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

@@ -232,7 +232,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 {
@@ -352,7 +352,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
@@ -449,7 +449,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{
@@ -549,7 +549,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
@@ -595,7 +595,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
@@ -657,10 +657,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()
@@ -686,6 +688,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
 }
@@ -716,9 +723,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)
@@ -737,13 +749,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

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/debug_test.go

@@ -0,0 +1,179 @@
+package terraform
+
+import (
+	"archive/tar"
+	"bytes"
+	"compress/gzip"
+	"io"
+	"io/ioutil"
+	"regexp"
+	"strings"
+	"testing"
+)
+
+// debugInfo should be safe when nil
+func TestDebugInfo_nil(t *testing.T) {
+	var d *debugInfo
+
+	d.SetPhase("none")
+	d.WriteGraph(nil)
+	d.WriteFile("none", nil)
+	d.Close()
+}
+
+func TestDebugInfo_basicFile(t *testing.T) {
+	var w bytes.Buffer
+	debug, err := newDebugInfo("test-debug-info", &w)
+	if err != nil {
+		t.Fatal(err)
+	}
+	debug.SetPhase("test")
+
+	fileData := map[string][]byte{
+		"file1": []byte("file 1 data"),
+		"file2": []byte("file 2 data"),
+		"file3": []byte("file 3 data"),
+	}
+
+	for f, d := range fileData {
+		err = debug.WriteFile(f, d)
+		if err != nil {
+			t.Fatal(err)
+		}
+	}
+
+	err = debug.Close()
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	gz, err := gzip.NewReader(&w)
+	if err != nil {
+		t.Fatal(err)
+	}
+	tr := tar.NewReader(gz)
+
+	for {
+		hdr, err := tr.Next()
+		if err == io.EOF {
+			break
+		}
+		if err != nil {
+			t.Fatal(err)
+		}
+
+		// get the filename part of the archived file
+		name := regexp.MustCompile(`\w+$`).FindString(hdr.Name)
+		data := fileData[name]
+
+		delete(fileData, name)
+
+		tarData, err := ioutil.ReadAll(tr)
+		if err != nil {
+			t.Fatal(err)
+		}
+		if !bytes.Equal(data, tarData) {
+			t.Fatalf("got '%s' for file '%s'", tarData, name)
+		}
+	}
+
+	for k := range fileData {
+		t.Fatalf("didn't find file %s", k)
+	}
+}
+
+// Test that we get logs and graphs from a walk. We're not looking for anything
+// specific, since the output is going to change in the near future.
+func TestDebug_plan(t *testing.T) {
+	var out bytes.Buffer
+	d, err := newDebugInfo("test-debug-info", &out)
+	if err != nil {
+		t.Fatal(err)
+	}
+	// set the global debug value
+	dbug = d
+
+	// run a basic plan
+	m := testModule(t, "plan-good")
+	p := testProvider("aws")
+	p.DiffFn = testDiffFn
+	ctx := testContext2(t, &ContextOpts{
+		Module: m,
+		Providers: map[string]ResourceProviderFactory{
+			"aws": testProviderFuncFixed(p),
+		},
+	})
+
+	_, err = ctx.Plan()
+	if err != nil {
+		t.Fatalf("err: %s", err)
+	}
+
+	err = CloseDebugInfo()
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	gz, err := gzip.NewReader(&out)
+	if err != nil {
+		t.Fatal(err)
+	}
+	tr := tar.NewReader(gz)
+
+	files := 0
+	graphs := 0
+	for {
+		hdr, err := tr.Next()
+		if err == io.EOF {
+			break
+		}
+		if err != nil {
+			t.Fatal(err)
+		}
+
+		// record any file that contains data
+		if hdr.Size > 0 {
+			files++
+
+			// and any dot graph with data
+			if strings.HasSuffix(hdr.Name, ".dot") {
+				graphs++
+			}
+		}
+	}
+
+	if files == 0 {
+		t.Fatal("no files with data found")
+	}
+
+	if graphs == 0 {
+		t.Fatal("no no-empty graphs found")
+	}
+}
+
+// verify that no hooks panic on nil input
+func TestDebugHook_nilArgs(t *testing.T) {
+	// make sure debug isn't nil, so the hooks try to execute
+	var w bytes.Buffer
+	var err error
+	dbug, err = newDebugInfo("test-debug-info", &w)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	var h DebugHook
+	h.PostApply(nil, nil, nil)
+	h.PostDiff(nil, nil)
+	h.PostImportState(nil, nil)
+	h.PostProvision(nil, "")
+	h.PostProvisionResource(nil, nil)
+	h.PostRefresh(nil, nil)
+	h.PostStateUpdate(nil)
+	h.PreApply(nil, nil, nil)
+	h.PreDiff(nil, nil)
+	h.PreImportState(nil, "")
+	h.PreProvision(nil, "")
+	h.PreProvisionResource(nil, nil)
+	h.PreRefresh(nil, nil)
+	h.ProvisionOutput(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,30 @@ 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:]
+		}
+
+		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
 		}
 
 		log.Printf(
 			"[TRACE] Graph after step %T:\n\n%s",
 			step, g.StringWithNodeTypes())
+
+		dg, _ := NewDebugGraph(debugName, g, nil)
+		dbug.WriteGraph(dg)
+
+		if err != nil {
+			return g, err
+		}
 	}
 
 	// Validate the graph structure
@@ -97,6 +118,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,289 @@
+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
+
+	ord 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()
+
+	// record the ordinal value for each node
+	ord := dg.ord
+	dg.ord++
+
+	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 (
-	"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
 }

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

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