From c5940f24385f0b08ee3b1b040593aa5aa1f04288 Mon Sep 17 00:00:00 2001 From: Martin Atkins Date: Thu, 11 Oct 2018 16:36:09 -0700 Subject: [PATCH] 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 | 1 + backend/local/backend_local.go | 10 ++++++++++ terraform/context.go | 5 +++++ 3 files changed, 16 insertions(+) diff --git a/backend/local/backend_apply.go b/backend/local/backend_apply.go index 1b479c752..66c437971 100644 --- a/backend/local/backend_apply.go +++ b/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() diff --git a/backend/local/backend_local.go b/backend/local/backend_local.go index e972098e1..0e9ec77f3 100644 --- a/backend/local/backend_local.go +++ b/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) } diff --git a/terraform/context.go b/terraform/context.go index ff3679aa1..b6e6b73ac 100644 --- a/terraform/context.go +++ b/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,