backend/local: Increase log verbosity for backend context construction

There are several steps here and a number of them can include reaching out
to remote servers or executing local processes, so it's helpful to have
some trace logs to better narrow down causes of errors and hangs during
this step.

backend/local/backend_apply.go

@@ -143,6 +143,7 @@ func (b *Local) opApply(
 	doneCh := make(chan struct{})
 	go func() {
 		defer close(doneCh)
+		log.Printf("[INFO] backend/local: apply calling Apply")
 		_, applyDiags = tfCtx.Apply()
 		// we always want the state, even if apply failed
 		applyState = tfCtx.State()

backend/local/backend_local.go

@@ -1,6 +1,7 @@
 package local
 
 import (
+	"log"
 	"context"
 	"fmt"
 
@@ -35,15 +36,18 @@ func (b *Local) context(op *backend.Operation) (*terraform.Context, *configload.
 	var diags tfdiags.Diagnostics
 
 	// Get the latest state.
+	log.Printf("[TRACE] backend/local: requesting state manager for workspace %q", op.Workspace)
 	s, err := b.StateMgr(op.Workspace)
 	if err != nil {
 		diags = diags.Append(errwrap.Wrapf("Error loading state: {{err}}", err))
 		return nil, nil, nil, diags
 	}
+	log.Printf("[TRACE] backend/local: requesting state lock for workspace %q", op.Workspace)
 	if err := op.StateLocker.Lock(s, op.Type.String()); err != nil {
 		diags = diags.Append(errwrap.Wrapf("Error locking state: {{err}}", err))
 		return nil, nil, nil, diags
 	}
+	log.Printf("[TRACE] backend/local: reading remote state for workspace %q", op.Workspace)
 	if err := s.RefreshState(); err != nil {
 		diags = diags.Append(errwrap.Wrapf("Error loading state: {{err}}", err))
 		return nil, nil, nil, diags
@@ -63,6 +67,7 @@ func (b *Local) context(op *backend.Operation) (*terraform.Context, *configload.
 	// Load the latest state. If we enter contextFromPlanFile below then the
 	// state snapshot in the plan file must match this, or else it'll return
 	// error diagnostics.
+	log.Printf("[TRACE] backend/local: retrieving the local state snapshot for workspace %q", op.Workspace)
 	opts.State = s.State()
 
 	var tfCtx *terraform.Context
@@ -77,17 +82,20 @@ func (b *Local) context(op *backend.Operation) (*terraform.Context, *configload.
 			m := sm.StateSnapshotMeta()
 			stateMeta = &m
 		}
+		log.Printf("[TRACE] backend/local: building context from plan file")
 		tfCtx, configSnap, ctxDiags = b.contextFromPlanFile(op.PlanFile, opts, stateMeta)
 		// Write sources into the cache of the main loader so that they are
 		// available if we need to generate diagnostic message snippets.
 		op.ConfigLoader.ImportSourcesFromSnapshot(configSnap)
 	} else {
+		log.Printf("[TRACE] backend/local: building context for current working directory")
 		tfCtx, configSnap, ctxDiags = b.contextDirect(op, opts)
 	}
 	diags = diags.Append(ctxDiags)
 	if diags.HasErrors() {
 		return nil, nil, nil, diags
 	}
+	log.Printf("[TRACE] backend/local: finished building terraform.Context")
 
 	// If we have an operation, then we automatically do the input/validate
 	// here since every option requires this.
@@ -98,6 +106,7 @@ func (b *Local) context(op *backend.Operation) (*terraform.Context, *configload.
 			mode |= terraform.InputModeVar
 			mode |= terraform.InputModeVarUnset
 
+			log.Printf("[TRACE] backend/local: requesting interactive input, if necessary")
 			inputDiags := tfCtx.Input(mode)
 			diags = diags.Append(inputDiags)
 			if inputDiags.HasErrors() {
@@ -107,6 +116,7 @@ func (b *Local) context(op *backend.Operation) (*terraform.Context, *configload.
 
 		// If validation is enabled, validate
 		if b.OpValidation {
+			log.Printf("[TRACE] backend/local: running validation operation")
 			validateDiags := tfCtx.Validate()
 			diags = diags.Append(validateDiags)
 		}

terraform/context.go

@@ -123,6 +123,7 @@ type Context struct {
 // If the returned diagnostics contains errors then the resulting context is
 // invalid and must not be used.
 func NewContext(opts *ContextOpts) (*Context, tfdiags.Diagnostics) {
+	log.Printf("[TRACE] terraform.NewContext: starting")
 	diags := CheckCoreVersionRequirements(opts.Config)
 	// If version constraints are not met then we'll bail early since otherwise
 	// we're likely to just see a bunch of other errors related to
@@ -175,6 +176,7 @@ func NewContext(opts *ContextOpts) (*Context, tfdiags.Diagnostics) {
 		if opts.ProviderSHA256s != nil && !opts.SkipProviderVerify {
 			reqd.LockExecutables(opts.ProviderSHA256s)
 		}
+		log.Printf("[TRACE] terraform.NewContext: resolving provider version selections")
 		providerFactories, err = resourceProviderFactories(opts.ProviderResolver, reqd)
 		if err != nil {
 			diags = diags.Append(err)
@@ -189,6 +191,7 @@ func NewContext(opts *ContextOpts) (*Context, tfdiags.Diagnostics) {
 		provisioners: opts.Provisioners,
 	}
 
+	log.Printf("[TRACE] terraform.NewContext: loading provider schemas")
 	schemas, err := LoadSchemas(opts.Config, opts.State, components)
 	if err != nil {
 		diags = diags.Append(err)
@@ -205,6 +208,8 @@ func NewContext(opts *ContextOpts) (*Context, tfdiags.Diagnostics) {
 		config = configs.NewEmptyConfig()
 	}
 
+	log.Printf("[TRACE] terraform.NewContext: complete")
+
 	return &Context{
 		components: components,
 		schemas:    schemas,