Merge pull request #11944 from hashicorp/f-state-slow

show message if state lock acquisition/release is slow

backend/local/backend_apply.go

@@ -8,7 +8,7 @@ import (
 	"github.com/hashicorp/errwrap"
 	"github.com/hashicorp/go-multierror"
 	"github.com/hashicorp/terraform/backend"
-	"github.com/hashicorp/terraform/state"
+	clistate "github.com/hashicorp/terraform/command/state"
 	"github.com/hashicorp/terraform/terraform"
 )
 
@@ -35,22 +35,14 @@ func (b *Local) opApply(
 		return
 	}
 
-	// context acquired the state, and therefor the lock.
-	// Unlock it when the operation is complete
-	defer func() {
-		if s, ok := opState.(state.Locker); op.LockState && ok {
-			if err := s.Unlock(); err != nil {
-				runningOp.Err = multierror.Append(runningOp.Err,
-					errwrap.Wrapf("Error unlocking state:\n\n"+
-						"{{err}}\n\n"+
-						"The Terraform operation completed but there was an error unlocking the state.\n"+
-						"This may require unlocking the state manually with the `terraform unlock` command\n",
-						err,
-					),
-				)
+	// If we're locking state, unlock when we're done
+	if op.LockState {
+		defer func() {
+			if err := clistate.Unlock(opState, b.CLI, b.Colorize()); err != nil {
+				runningOp.Err = multierror.Append(runningOp.Err, err)
 			}
-		}
-	}()
+		}()
+	}
 
 	// Setup the state
 	runningOp.State = tfCtx.State()

backend/local/backend_local.go

@@ -8,6 +8,7 @@ import (
 	"github.com/hashicorp/errwrap"
 	"github.com/hashicorp/go-multierror"
 	"github.com/hashicorp/terraform/backend"
+	clistate "github.com/hashicorp/terraform/command/state"
 	"github.com/hashicorp/terraform/state"
 	"github.com/hashicorp/terraform/terraform"
 )
@@ -28,8 +29,9 @@ func (b *Local) context(op *backend.Operation) (*terraform.Context, state.State,
 		return nil, nil, errwrap.Wrapf("Error loading state: {{err}}", err)
 	}
 
-	if s, ok := s.(state.Locker); op.LockState && ok {
-		if err := s.Lock(op.Type.String()); err != nil {
+	if op.LockState {
+		err := clistate.Lock(s, op.Type.String(), b.CLI, b.Colorize())
+		if err != nil {
 			return nil, nil, errwrap.Wrapf("Error locking state: {{err}}", err)
 		}
 	}

backend/local/backend_plan.go

@@ -8,10 +8,11 @@ import (
 	"strings"
 
 	"github.com/hashicorp/errwrap"
+	"github.com/hashicorp/go-multierror"
 	"github.com/hashicorp/terraform/backend"
 	"github.com/hashicorp/terraform/command/format"
+	clistate "github.com/hashicorp/terraform/command/state"
 	"github.com/hashicorp/terraform/config/module"
-	"github.com/hashicorp/terraform/state"
 	"github.com/hashicorp/terraform/terraform"
 )
 
@@ -58,15 +59,14 @@ func (b *Local) opPlan(
 		return
 	}
 
-	// context acquired the state, and therefor the lock.
-	// Unlock it when the operation is complete
-	defer func() {
-		if s, ok := opState.(state.Locker); op.LockState && ok {
-			if err := s.Unlock(); err != nil {
-				log.Printf("[ERROR]: %s", err)
+	// If we're locking state, unlock when we're done
+	if op.LockState {
+		defer func() {
+			if err := clistate.Unlock(opState, b.CLI, b.Colorize()); err != nil {
+				runningOp.Err = multierror.Append(runningOp.Err, err)
 			}
-		}
-	}()
+		}()
+	}
 
 	// Setup the state
 	runningOp.State = tfCtx.State()

backend/local/backend_refresh.go

@@ -3,12 +3,12 @@ package local
 import (
 	"context"
 	"fmt"
-	"log"
 	"os"
 
 	"github.com/hashicorp/errwrap"
+	"github.com/hashicorp/go-multierror"
 	"github.com/hashicorp/terraform/backend"
-	"github.com/hashicorp/terraform/state"
+	clistate "github.com/hashicorp/terraform/command/state"
 )
 
 func (b *Local) opRefresh(
@@ -48,15 +48,14 @@ func (b *Local) opRefresh(
 		return
 	}
 
-	// context acquired the state, and therefor the lock.
-	// Unlock it when the operation is complete
-	defer func() {
-		if s, ok := opState.(state.Locker); op.LockState && ok {
-			if err := s.Unlock(); err != nil {
-				log.Printf("[ERROR]: %s", err)
+	// If we're locking state, unlock when we're done
+	if op.LockState {
+		defer func() {
+			if err := clistate.Unlock(opState, b.CLI, b.Colorize()); err != nil {
+				runningOp.Err = multierror.Append(runningOp.Err, err)
 			}
-		}
-	}()
+		}()
+	}
 
 	// Set our state
 	runningOp.State = opState.State()

command/meta_backend.go

@@ -16,6 +16,7 @@ import (
 	"github.com/hashicorp/go-multierror"
 	"github.com/hashicorp/hcl"
 	"github.com/hashicorp/terraform/backend"
+	clistate "github.com/hashicorp/terraform/command/state"
 	"github.com/hashicorp/terraform/config"
 	"github.com/hashicorp/terraform/state"
 	"github.com/hashicorp/terraform/terraform"
@@ -531,11 +532,12 @@ func (m *Meta) backendFromPlan(opts *BackendOpts) (backend.Backend, error) {
 		return nil, fmt.Errorf("Error reading state: %s", err)
 	}
 
-	unlock, err := lockState(realMgr, "backend from plan")
+	// Lock the state if we can
+	err = clistate.Lock(realMgr, "backend from plan", m.Ui, m.Colorize())
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("Error locking state: %s", err)
 	}
-	defer unlock()
+	defer clistate.Unlock(realMgr, m.Ui, m.Colorize())
 
 	if err := realMgr.RefreshState(); err != nil {
 		return nil, fmt.Errorf("Error reading state: %s", err)
@@ -983,11 +985,12 @@ func (m *Meta) backend_C_r_s(
 		}
 	}
 
-	unlock, err := lockState(sMgr, "backend_C_r_s")
+	// Lock the state if we can
+	err = clistate.Lock(sMgr, "backend from config", m.Ui, m.Colorize())
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("Error locking state: %s", err)
 	}
-	defer unlock()
+	defer clistate.Unlock(sMgr, m.Ui, m.Colorize())
 
 	// Store the metadata in our saved state location
 	s := sMgr.State()
@@ -1087,11 +1090,12 @@ func (m *Meta) backend_C_r_S_changed(
 		}
 	}
 
-	unlock, err := lockState(sMgr, "backend_C_r_S_changed")
+	// Lock the state if we can
+	err = clistate.Lock(sMgr, "backend from config", m.Ui, m.Colorize())
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("Error locking state: %s", err)
 	}
-	defer unlock()
+	defer clistate.Unlock(sMgr, m.Ui, m.Colorize())
 
 	// Update the backend state
 	s = sMgr.State()
@@ -1244,11 +1248,12 @@ func (m *Meta) backend_C_R_S_unchanged(
 		}
 	}
 
-	unlock, err := lockState(sMgr, "backend_C_R_S_unchanged")
+	// Lock the state if we can
+	err = clistate.Lock(sMgr, "backend from config", m.Ui, m.Colorize())
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("Error locking state: %s", err)
 	}
-	defer unlock()
+	defer clistate.Unlock(sMgr, m.Ui, m.Colorize())
 
 	// Unset the remote state
 	s = sMgr.State()
@@ -1399,21 +1404,6 @@ func init() {
 	backendlegacy.Init(Backends)
 }
 
-// simple wrapper to check for a state.Locker and always provide an unlock
-// function to defer.
-func lockState(s state.State, info string) (func() error, error) {
-	l, ok := s.(state.Locker)
-	if !ok {
-		return func() error { return nil }, nil
-	}
-
-	if err := l.Lock(info); err != nil {
-		return nil, err
-	}
-
-	return l.Unlock, nil
-}
-
 // errBackendInitRequired is the final error message shown when reinit
 // is required for some reason. The error message includes the reason.
 var errBackendInitRequired = errors.New(

command/meta_backend_migrate.go

@@ -7,6 +7,7 @@ import (
 	"path/filepath"
 	"strings"
 
+	clistate "github.com/hashicorp/terraform/command/state"
 	"github.com/hashicorp/terraform/state"
 	"github.com/hashicorp/terraform/terraform"
 )
@@ -23,17 +24,17 @@ import (
 //
 // This will attempt to lock both states for the migration.
 func (m *Meta) backendMigrateState(opts *backendMigrateOpts) error {
-	unlockOne, err := lockState(opts.One, "migrate from")
+	err := clistate.Lock(opts.One, "migration source state", m.Ui, m.Colorize())
 	if err != nil {
-		return err
+		return fmt.Errorf("Error locking source state: %s", err)
 	}
-	defer unlockOne()
+	defer clistate.Unlock(opts.One, m.Ui, m.Colorize())
 
-	unlockTwo, err := lockState(opts.Two, "migrate to")
+	err = clistate.Lock(opts.Two, "migration destination state", m.Ui, m.Colorize())
 	if err != nil {
-		return err
+		return fmt.Errorf("Error locking destination state: %s", err)
 	}
-	defer unlockTwo()
+	defer clistate.Unlock(opts.Two, m.Ui, m.Colorize())
 
 	one := opts.One.State()
 	two := opts.Two.State()

command/state/state.go

@@ -0,0 +1,96 @@
+// Package state exposes common helpers for working with state from the CLI.
+//
+// This is a separate package so that backends can use this for consistent
+// messaging without creating a circular reference to the command package.
+package message
+
+import (
+	"fmt"
+	"strings"
+	"time"
+
+	"github.com/hashicorp/errwrap"
+	"github.com/hashicorp/terraform/helper/slowmessage"
+	"github.com/hashicorp/terraform/state"
+	"github.com/mitchellh/cli"
+	"github.com/mitchellh/colorstring"
+)
+
+const (
+	LockThreshold    = 400 * time.Millisecond
+	LockMessage      = "Acquiring state lock. This may take a few moments..."
+	LockErrorMessage = `Error acquiring the state lock: {{err}}
+
+Terraform acquires a state lock to protect the state from being written
+by multiple users at the same time. Please resolve the issue above and try
+again. For most commands, you can disable locking with the "-lock=false"
+flag, but this is not recommended.`
+
+	UnlockMessage      = "Releasing state lock. This may take a few moments..."
+	UnlockErrorMessage = `
+[reset][bold][red]Error releasing the state lock![reset][red]
+
+Error message: %s
+
+Terraform acquires a lock when accessing your state to prevent others
+running Terraform to potentially modify the state at the same time. An
+error occurred while releasing this lock. This could mean that the lock
+did or did not release properly. If the lock didn't release properly,
+Terraform may not be able to run future commands since it'll appear as if
+the lock is held.
+
+In this scenario, please call the "force-unlock" command to unlock the
+state manually. This is a very dangerous operation since if it is done
+erroneously it could result in two people modifying state at the same time.
+Only call this command if you're certain that the unlock above failed and
+that no one else is holding a lock.
+`
+)
+
+// Lock locks the given state and outputs to the user if locking
+// is taking longer than the threshold.
+func Lock(s state.State, info string, ui cli.Ui, color *colorstring.Colorize) error {
+	sl, ok := s.(state.Locker)
+	if !ok {
+		return nil
+	}
+
+	err := slowmessage.Do(LockThreshold, func() error {
+		return sl.Lock(info)
+	}, func() {
+		if ui != nil {
+			ui.Output(color.Color(LockMessage))
+		}
+	})
+
+	if err != nil {
+		err = errwrap.Wrapf(strings.TrimSpace(LockErrorMessage), err)
+	}
+
+	return err
+}
+
+// Unlock unlocks the given state and outputs to the user if the
+// unlock fails what can be done.
+func Unlock(s state.State, ui cli.Ui, color *colorstring.Colorize) error {
+	sl, ok := s.(state.Locker)
+	if !ok {
+		return nil
+	}
+
+	err := slowmessage.Do(LockThreshold, sl.Unlock, func() {
+		if ui != nil {
+			ui.Output(color.Color(UnlockMessage))
+		}
+	})
+
+	if err != nil {
+		ui.Output(color.Color(fmt.Sprintf(
+			"\n"+strings.TrimSpace(UnlockErrorMessage)+"\n", err)))
+
+		err = fmt.Errorf(
+			"Error releasing the state lock. Please see the longer error message above.")
+	}
+
+	return err
+}

command/taint.go

@@ -5,7 +5,7 @@ import (
 	"log"
 	"strings"
 
-	"github.com/hashicorp/terraform/state"
+	clistate "github.com/hashicorp/terraform/command/state"
 	"github.com/hashicorp/terraform/terraform"
 )
 
@@ -72,13 +72,14 @@ func (c *TaintCommand) Run(args []string) int {
 		return 1
 	}
 
-	if s, ok := st.(state.Locker); c.Meta.stateLock && ok {
-		if err := s.Lock("taint"); err != nil {
-			c.Ui.Error(fmt.Sprintf("Failed to lock state: %s", err))
+	if c.Meta.stateLock {
+		err := clistate.Lock(st, "taint", c.Ui, c.Colorize())
+		if err != nil {
+			c.Ui.Error(fmt.Sprintf("Error locking state: %s", err))
 			return 1
 		}
 
-		defer s.Unlock()
+		defer clistate.Unlock(st, c.Ui, c.Colorize())
 	}
 
 	// Get the actual state structure

command/unlock.go

@@ -124,7 +124,7 @@ func (c *UnlockCommand) Synopsis() string {
 }
 
 const outputUnlockSuccess = `
-[reset][bold][red]Terraform state has been successfully unlocked![reset][red]
+[reset][bold][green]Terraform state has been successfully unlocked![reset][green]
 
 The state has been unlocked, and Terraform commands should now be able to
 obtain a new lock on the remote state.

command/untaint.go

@@ -5,7 +5,7 @@ import (
 	"log"
 	"strings"
 
-	"github.com/hashicorp/terraform/state"
+	clistate "github.com/hashicorp/terraform/command/state"
 )
 
 // UntaintCommand is a cli.Command implementation that manually untaints
@@ -60,13 +60,14 @@ func (c *UntaintCommand) Run(args []string) int {
 		return 1
 	}
 
-	if s, ok := st.(state.Locker); c.Meta.stateLock && ok {
-		if err := s.Lock("untaint"); err != nil {
-			c.Ui.Error(fmt.Sprintf("Failed to lock state: %s", err))
+	if c.Meta.stateLock {
+		err := clistate.Lock(st, "untaint", c.Ui, c.Colorize())
+		if err != nil {
+			c.Ui.Error(fmt.Sprintf("Error locking state: %s", err))
 			return 1
 		}
 
-		defer s.Unlock()
+		defer clistate.Unlock(st, c.Ui, c.Colorize())
 	}
 
 	// Get the actual state structure

helper/slowmessage/slowmessage.go

@@ -0,0 +1,34 @@
+package slowmessage
+
+import (
+	"time"
+)
+
+// SlowFunc is the function that could be slow. Usually, you'll have to
+// wrap an existing function in a lambda to make it match this type signature.
+type SlowFunc func() error
+
+// CallbackFunc is the function that is triggered when the threshold is reached.
+type CallbackFunc func()
+
+// Do calls sf. If threshold time has passed, cb is called. Note that this
+// call will be made concurrently to sf still running.
+func Do(threshold time.Duration, sf SlowFunc, cb CallbackFunc) error {
+	// Call the slow function
+	errCh := make(chan error, 1)
+	go func() {
+		errCh <- sf()
+	}()
+
+	// Wait for it to complete or the threshold to pass
+	select {
+	case err := <-errCh:
+		return err
+	case <-time.After(threshold):
+		// Threshold reached, call the callback
+		cb()
+	}
+
+	// Wait an indefinite amount of time for it to finally complete
+	return <-errCh
+}

helper/slowmessage/slowmessage_test.go

@@ -0,0 +1,82 @@
+package slowmessage
+
+import (
+	"errors"
+	"testing"
+	"time"
+)
+
+func TestDo(t *testing.T) {
+	var sfErr error
+	cbCalled := false
+	sfCalled := false
+	sfSleep := 0 * time.Second
+
+	reset := func() {
+		cbCalled = false
+		sfCalled = false
+		sfErr = nil
+	}
+	sf := func() error {
+		sfCalled = true
+		time.Sleep(sfSleep)
+		return sfErr
+	}
+	cb := func() { cbCalled = true }
+
+	// SF is not slow
+	reset()
+	if err := Do(10*time.Millisecond, sf, cb); err != nil {
+		t.Fatalf("err: %s", err)
+	}
+
+	if !sfCalled {
+		t.Fatal("should call")
+	}
+	if cbCalled {
+		t.Fatal("should not call")
+	}
+
+	// SF is not slow (with error)
+	reset()
+	sfErr = errors.New("error")
+	if err := Do(10*time.Millisecond, sf, cb); err == nil {
+		t.Fatalf("err: %s", err)
+	}
+
+	if !sfCalled {
+		t.Fatal("should call")
+	}
+	if cbCalled {
+		t.Fatal("should not call")
+	}
+
+	// SF is slow
+	reset()
+	sfSleep = 50 * time.Millisecond
+	if err := Do(10*time.Millisecond, sf, cb); err != nil {
+		t.Fatalf("err: %s", err)
+	}
+
+	if !sfCalled {
+		t.Fatal("should call")
+	}
+	if !cbCalled {
+		t.Fatal("should call")
+	}
+
+	// SF is slow (with error)
+	reset()
+	sfErr = errors.New("error")
+	sfSleep = 50 * time.Millisecond
+	if err := Do(10*time.Millisecond, sf, cb); err == nil {
+		t.Fatalf("err: %s", err)
+	}
+
+	if !sfCalled {
+		t.Fatal("should call")
+	}
+	if !cbCalled {
+		t.Fatal("should call")
+	}
+}