terraform test expect_failures does not capture output precondition failure on apply

[andrewesweet]

Terraform Version

Terraform v1.6.0-beta1
on windows_amd64

Terraform Configuration Files

main.tf

variable "foo" {
  type    = bool
  default = true
}

output "bar" {
  value = var.foo

  precondition {
    condition     = false && var.foo
    error_message = "Always fails"
  }
}

apply.tftest.hcl

run "apply" {
  command = apply

  expect_failures = [
    output.bar
  ]
}

plan.tftest.hcl

run "plan" {
  command = plan

  expect_failures = [
    output.bar
  ]
}

Debug Output

2023-09-09T23:10:36.674+0100 [INFO]  Terraform version: 1.6.0 beta1
2023-09-09T23:10:36.680+0100 [DEBUG] using github.com/hashicorp/go-tfe v1.32.1
2023-09-09T23:10:36.680+0100 [DEBUG] using github.com/hashicorp/hcl/v2 v2.18.0
2023-09-09T23:10:36.680+0100 [DEBUG] using github.com/hashicorp/terraform-svchost v0.1.1
2023-09-09T23:10:36.680+0100 [DEBUG] using github.com/zclconf/go-cty v1.14.0
2023-09-09T23:10:36.680+0100 [INFO]  Go runtime version: go1.21.0
2023-09-09T23:10:36.680+0100 [INFO]  CLI args: []string{"C:\\Users\\sweeand\\dev\\terraform\\1.6.0-beta1\\terraform.exe", "test"}
2023-09-09T23:10:36.680+0100 [TRACE] Stdout is not a terminal
2023-09-09T23:10:36.680+0100 [TRACE] Stderr is not a terminal
2023-09-09T23:10:36.680+0100 [TRACE] Stdin is a terminal
2023-09-09T23:10:36.688+0100 [DEBUG] Attempting to open CLI config file: C:\Users\sweeand\AppData\Roaming\terraform.rc
2023-09-09T23:10:36.692+0100 [INFO]  Loading CLI configuration from C:\Users\sweeand\AppData\Roaming\terraform.rc
2023-09-09T23:10:36.696+0100 [INFO]  Loading CLI configuration from C:\Users\sweeand\AppData\Roaming\terraform.d\credentials.tfrc.json
2023-09-09T23:10:36.711+0100 [DEBUG] ignoring non-existing provider search directory terraform.d/plugins
2023-09-09T23:10:36.711+0100 [DEBUG] ignoring non-existing provider search directory C:\Users\sweeand\AppData\Roaming\terraform.d\plugins
2023-09-09T23:10:36.715+0100 [DEBUG] ignoring non-existing provider search directory C:\Users\sweeand\AppData\Roaming\HashiCorp\Terraform\plugins
2023-09-09T23:10:36.715+0100 [INFO]  CLI command args: []string{"test"}
2023-09-09T23:10:36.757+0100 [DEBUG] checking for provisioner in "."
2023-09-09T23:10:36.761+0100 [DEBUG] checking for provisioner in "C:\\Users\\sweeand\\dev\\terraform\\1.6.0-beta1"
2023-09-09T23:10:36.770+0100 [DEBUG] TestSuiteRunner: found 2 files with 2 run blocks
2023-09-09T23:10:36.770+0100 [TRACE] TestFileRunner: executing test file apply.tftest.hcl
2023-09-09T23:10:36.770+0100 [TRACE] TestFileRunner: executing run block apply.tftest.hcl/apply
2023-09-09T23:10:36.770+0100 [TRACE] TestFileRunner: called validate for apply.tftest.hcl/apply
2023-09-09T23:10:36.770+0100 [TRACE] terraform.NewContext: starting
2023-09-09T23:10:36.770+0100 [TRACE] terraform.NewContext: complete
2023-09-09T23:10:36.770+0100 [TRACE] TestFileRunner: waiting for execution during apply.tftest.hcl/apply
2023-09-09T23:10:36.770+0100 [DEBUG] TestFileRunner: starting validate for apply.tftest.hcl/apply
2023-09-09T23:10:36.770+0100 [DEBUG] Building and walking validate graph
2023-09-09T23:10:36.770+0100 [TRACE] building graph for walkValidate
2023-09-09T23:10:36.770+0100 [TRACE] Executing graph transform *terraform.ConfigTransformer
2023-09-09T23:10:36.770+0100 [TRACE] ConfigTransformer: Starting for path:
2023-09-09T23:10:36.770+0100 [TRACE] Completed graph transform *terraform.ConfigTransformer (no changes)
2023-09-09T23:10:36.770+0100 [TRACE] Executing graph transform *terraform.RootVariableTransformer
2023-09-09T23:10:36.770+0100 [TRACE] Completed graph transform *terraform.RootVariableTransformer with new graph:
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.770+0100 [TRACE] Executing graph transform *terraform.ModuleVariableTransformer
2023-09-09T23:10:36.770+0100 [TRACE] Completed graph transform *terraform.ModuleVariableTransformer (no changes)
2023-09-09T23:10:36.770+0100 [TRACE] Executing graph transform *terraform.LocalTransformer
2023-09-09T23:10:36.770+0100 [TRACE] Completed graph transform *terraform.LocalTransformer (no changes)
2023-09-09T23:10:36.770+0100 [TRACE] Executing graph transform *terraform.OutputTransformer
2023-09-09T23:10:36.770+0100 [TRACE] OutputTransformer: adding bar as *terraform.nodeExpandOutput
2023-09-09T23:10:36.770+0100 [TRACE] Completed graph transform *terraform.OutputTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.770+0100 [TRACE] Executing graph transform *terraform.checkTransformer
2023-09-09T23:10:36.770+0100 [TRACE] Completed graph transform *terraform.checkTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] Executing graph transform *terraform.OrphanResourceInstanceTransformer
2023-09-09T23:10:36.771+0100 [TRACE] Completed graph transform *terraform.OrphanResourceInstanceTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] Executing graph transform *terraform.StateTransformer
2023-09-09T23:10:36.771+0100 [TRACE] StateTransformer: pointless no-op call, creating no nodes at all
2023-09-09T23:10:36.771+0100 [TRACE] Completed graph transform *terraform.StateTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] Executing graph transform *terraform.AttachStateTransformer
2023-09-09T23:10:36.771+0100 [TRACE] Completed graph transform *terraform.AttachStateTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] Executing graph transform *terraform.OrphanOutputTransformer
2023-09-09T23:10:36.771+0100 [TRACE] Completed graph transform *terraform.OrphanOutputTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] Executing graph transform *terraform.AttachResourceConfigTransformer
2023-09-09T23:10:36.771+0100 [TRACE] Completed graph transform *terraform.AttachResourceConfigTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] Executing graph transform *terraform.graphTransformerMulti
2023-09-09T23:10:36.771+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.ProviderConfigTransformer
2023-09-09T23:10:36.771+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.ProviderConfigTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.771+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.MissingProviderTransformer
2023-09-09T23:10:36.771+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.MissingProviderTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.ProviderTransformer
2023-09-09T23:10:36.771+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.ProviderTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.PruneProviderTransformer
2023-09-09T23:10:36.771+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.PruneProviderTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] Completed graph transform *terraform.graphTransformerMulti (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] Executing graph transform *terraform.RemovedModuleTransformer
2023-09-09T23:10:36.771+0100 [TRACE] Completed graph transform *terraform.RemovedModuleTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] Executing graph transform *terraform.AttachSchemaTransformer
2023-09-09T23:10:36.771+0100 [TRACE] Completed graph transform *terraform.AttachSchemaTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] Executing graph transform *terraform.ModuleExpansionTransformer
2023-09-09T23:10:36.771+0100 [TRACE] Completed graph transform *terraform.ModuleExpansionTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] Executing graph transform *terraform.ExternalReferenceTransformer
2023-09-09T23:10:36.771+0100 [TRACE] Completed graph transform *terraform.ExternalReferenceTransformer (no changes)
2023-09-09T23:10:36.771+0100 [TRACE] Executing graph transform *terraform.ReferenceTransformer
2023-09-09T23:10:36.771+0100 [DEBUG] ReferenceTransformer: "var.foo" references: []
2023-09-09T23:10:36.772+0100 [DEBUG] ReferenceTransformer: "output.bar (expand)" references: [var.foo var.foo]
2023-09-09T23:10:36.772+0100 [TRACE] Completed graph transform *terraform.ReferenceTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
    var.foo - *terraform.NodeRootVariable
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.772+0100 [TRACE] Executing graph transform *terraform.AttachDependenciesTransformer
2023-09-09T23:10:36.772+0100 [TRACE] Completed graph transform *terraform.AttachDependenciesTransformer (no changes)
2023-09-09T23:10:36.772+0100 [TRACE] Executing graph transform *terraform.attachDataResourceDependsOnTransformer
2023-09-09T23:10:36.772+0100 [TRACE] Completed graph transform *terraform.attachDataResourceDependsOnTransformer (no changes)
2023-09-09T23:10:36.772+0100 [TRACE] Executing graph transform *terraform.DestroyEdgeTransformer
2023-09-09T23:10:36.772+0100 [TRACE] Completed graph transform *terraform.DestroyEdgeTransformer (no changes)
2023-09-09T23:10:36.772+0100 [TRACE] Executing graph transform *terraform.pruneUnusedNodesTransformer
2023-09-09T23:10:36.772+0100 [TRACE] Completed graph transform *terraform.pruneUnusedNodesTransformer (no changes)
2023-09-09T23:10:36.772+0100 [TRACE] Executing graph transform *terraform.TargetsTransformer
2023-09-09T23:10:36.772+0100 [TRACE] Completed graph transform *terraform.TargetsTransformer (no changes)
2023-09-09T23:10:36.772+0100 [TRACE] Executing graph transform *terraform.ForcedCBDTransformer
2023-09-09T23:10:36.772+0100 [TRACE] Completed graph transform *terraform.ForcedCBDTransformer (no changes)
2023-09-09T23:10:36.772+0100 [TRACE] Executing graph transform *terraform.CloseProviderTransformer
2023-09-09T23:10:36.772+0100 [TRACE] Completed graph transform *terraform.CloseProviderTransformer (no changes)
2023-09-09T23:10:36.772+0100 [TRACE] Executing graph transform *terraform.CloseRootModuleTransformer
2023-09-09T23:10:36.772+0100 [TRACE] Completed graph transform *terraform.CloseRootModuleTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
    var.foo - *terraform.NodeRootVariable
  root - *terraform.nodeCloseModule
    output.bar (expand) - *terraform.nodeExpandOutput
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.772+0100 [TRACE] Executing graph transform *terraform.TransitiveReductionTransformer
2023-09-09T23:10:36.772+0100 [TRACE] Completed graph transform *terraform.TransitiveReductionTransformer (no changes)
2023-09-09T23:10:36.772+0100 [DEBUG] Starting graph walk: walkValidate
2023-09-09T23:10:36.772+0100 [TRACE] vertex "var.foo": starting visit (*terraform.NodeRootVariable)
2023-09-09T23:10:36.772+0100 [TRACE] NodeRootVariable: evaluating var.foo
2023-09-09T23:10:36.772+0100 [TRACE] prepareFinalInputVariableValue: preparing var.foo
2023-09-09T23:10:36.772+0100 [TRACE] prepareFinalInputVariableValue: var.foo has a default value
2023-09-09T23:10:36.772+0100 [TRACE] BuiltinEvalContext: Storing final value for variable var.foo
2023-09-09T23:10:36.773+0100 [TRACE] evalVariableValidations: no validation rules declared for var.foo, so skipping
2023-09-09T23:10:36.773+0100 [TRACE] vertex "var.foo": visit complete
2023-09-09T23:10:36.773+0100 [TRACE] vertex "output.bar (expand)": starting visit (*terraform.nodeExpandOutput)
2023-09-09T23:10:36.773+0100 [TRACE] vertex "output.bar (expand)": expanding dynamic subgraph
2023-09-09T23:10:36.773+0100 [TRACE] Expanding output: adding output.bar as *terraform.NodeApplyableOutput
2023-09-09T23:10:36.773+0100 [TRACE] vertex "output.bar (expand)": entering dynamic subgraph
2023-09-09T23:10:36.773+0100 [TRACE] vertex "output.bar": starting visit (*terraform.NodeApplyableOutput)
2023-09-09T23:10:36.773+0100 [TRACE] evalCheckRules: output.bar status is now StatusUnknown
2023-09-09T23:10:36.773+0100 [TRACE] setValue: Saving Create change for output.bar in changeset
2023-09-09T23:10:36.773+0100 [TRACE] setValue: Saving value for output.bar in state
2023-09-09T23:10:36.773+0100 [TRACE] vertex "output.bar": visit complete
2023-09-09T23:10:36.773+0100 [TRACE] vertex "root": starting visit (terraform.graphNodeRoot)
2023-09-09T23:10:36.773+0100 [TRACE] vertex "root": visit complete
2023-09-09T23:10:36.773+0100 [TRACE] vertex "output.bar (expand)": dynamic subgraph completed successfully
2023-09-09T23:10:36.774+0100 [TRACE] vertex "output.bar (expand)": visit complete
2023-09-09T23:10:36.774+0100 [TRACE] vertex "root": starting visit (*terraform.nodeCloseModule)
2023-09-09T23:10:36.774+0100 [TRACE] vertex "root": visit complete
2023-09-09T23:10:36.774+0100 [DEBUG] TestFileRunner: completed validate for  apply.tftest.hcl/apply
2023-09-09T23:10:36.774+0100 [TRACE] TestFileRunner: called plan for apply.tftest.hcl/apply
2023-09-09T23:10:36.774+0100 [TRACE] terraform.NewContext: starting
2023-09-09T23:10:36.774+0100 [TRACE] terraform.NewContext: complete
2023-09-09T23:10:36.774+0100 [TRACE] TestFileRunner: waiting for execution during apply.tftest.hcl/apply
2023-09-09T23:10:36.774+0100 [DEBUG] TestFileRunner: starting plan for apply.tftest.hcl/apply
2023-09-09T23:10:36.774+0100 [DEBUG] Building and walking plan graph for NormalMode
2023-09-09T23:10:36.774+0100 [TRACE] building graph for walkPlan
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.ConfigTransformer
2023-09-09T23:10:36.774+0100 [TRACE] ConfigTransformer: Starting for path:
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.ConfigTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.RootVariableTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.RootVariableTransformer with new graph:
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.ModuleVariableTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.ModuleVariableTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.LocalTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.LocalTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.OutputTransformer
2023-09-09T23:10:36.774+0100 [TRACE] OutputTransformer: adding bar as *terraform.nodeExpandOutput
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.OutputTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.checkTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.checkTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.OrphanResourceInstanceTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.OrphanResourceInstanceTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.StateTransformer
2023-09-09T23:10:36.774+0100 [TRACE] StateTransformer: creating nodes for deposed instance objects only
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.StateTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.AttachStateTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.AttachStateTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.OrphanOutputTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.OrphanOutputTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.AttachResourceConfigTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.AttachResourceConfigTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.graphTransformerMulti
2023-09-09T23:10:36.774+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.ProviderConfigTransformer
2023-09-09T23:10:36.774+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.ProviderConfigTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.774+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.MissingProviderTransformer
2023-09-09T23:10:36.774+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.MissingProviderTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.ProviderTransformer
2023-09-09T23:10:36.774+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.ProviderTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.PruneProviderTransformer
2023-09-09T23:10:36.774+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.PruneProviderTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.graphTransformerMulti (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.RemovedModuleTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.RemovedModuleTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.AttachSchemaTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.AttachSchemaTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.ModuleExpansionTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.ModuleExpansionTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.ExternalReferenceTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.ExternalReferenceTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.ReferenceTransformer
2023-09-09T23:10:36.774+0100 [DEBUG] ReferenceTransformer: "var.foo" references: []
2023-09-09T23:10:36.774+0100 [DEBUG] ReferenceTransformer: "output.bar (expand)" references: [var.foo var.foo]
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.ReferenceTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
    var.foo - *terraform.NodeRootVariable
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.AttachDependenciesTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.AttachDependenciesTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.attachDataResourceDependsOnTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.attachDataResourceDependsOnTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.DestroyEdgeTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.DestroyEdgeTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.pruneUnusedNodesTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.pruneUnusedNodesTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.TargetsTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.TargetsTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.ForcedCBDTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.ForcedCBDTransformer (no changes)
2023-09-09T23:10:36.774+0100 [TRACE] Executing graph transform *terraform.CloseProviderTransformer
2023-09-09T23:10:36.774+0100 [TRACE] Completed graph transform *terraform.CloseProviderTransformer (no changes)
2023-09-09T23:10:36.775+0100 [TRACE] Executing graph transform *terraform.CloseRootModuleTransformer
2023-09-09T23:10:36.775+0100 [TRACE] Completed graph transform *terraform.CloseRootModuleTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
    var.foo - *terraform.NodeRootVariable
  root - *terraform.nodeCloseModule
    output.bar (expand) - *terraform.nodeExpandOutput
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.775+0100 [TRACE] Executing graph transform *terraform.TransitiveReductionTransformer
2023-09-09T23:10:36.775+0100 [TRACE] Completed graph transform *terraform.TransitiveReductionTransformer (no changes)
2023-09-09T23:10:36.775+0100 [DEBUG] Starting graph walk: walkPlan
2023-09-09T23:10:36.775+0100 [TRACE] vertex "var.foo": starting visit (*terraform.NodeRootVariable)
2023-09-09T23:10:36.775+0100 [TRACE] NodeRootVariable: evaluating var.foo
2023-09-09T23:10:36.775+0100 [TRACE] prepareFinalInputVariableValue: preparing var.foo
2023-09-09T23:10:36.775+0100 [TRACE] prepareFinalInputVariableValue: var.foo has a default value
2023-09-09T23:10:36.775+0100 [TRACE] prepareFinalInputVariableValue: var.foo has no defined value
2023-09-09T23:10:36.775+0100 [TRACE] BuiltinEvalContext: Storing final value for variable var.foo
2023-09-09T23:10:36.775+0100 [TRACE] evalVariableValidations: no validation rules declared for var.foo, so skipping
2023-09-09T23:10:36.775+0100 [TRACE] vertex "var.foo": visit complete
2023-09-09T23:10:36.775+0100 [TRACE] vertex "output.bar (expand)": starting visit (*terraform.nodeExpandOutput)
2023-09-09T23:10:36.775+0100 [TRACE] vertex "output.bar (expand)": expanding dynamic subgraph
2023-09-09T23:10:36.775+0100 [TRACE] Expanding output: adding output.bar as *terraform.NodeApplyableOutput
2023-09-09T23:10:36.775+0100 [TRACE] vertex "output.bar (expand)": entering dynamic subgraph
2023-09-09T23:10:36.775+0100 [TRACE] vertex "output.bar": starting visit (*terraform.NodeApplyableOutput)
2023-09-09T23:10:36.775+0100 [TRACE] evalCheckRules: output.bar status is now StatusFail
2023-09-09T23:10:36.775+0100 [ERROR] vertex "output.bar" error: Module output value precondition failed
2023-09-09T23:10:36.775+0100 [TRACE] vertex "output.bar": visit complete, with errors
2023-09-09T23:10:36.775+0100 [TRACE] dag/walk: upstream of "root" errored, so skipping
2023-09-09T23:10:36.775+0100 [TRACE] vertex "output.bar (expand)": dynamic subgraph encountered errors: Module output value precondition failed
2023-09-09T23:10:36.775+0100 [ERROR] vertex "output.bar (expand)" error: Module output value precondition failed
2023-09-09T23:10:36.775+0100 [TRACE] vertex "output.bar (expand)": visit complete, with errors
2023-09-09T23:10:36.775+0100 [TRACE] dag/walk: upstream of "root" errored, so skipping
2023-09-09T23:10:36.775+0100 [DEBUG] TestFileRunner: completed plan for apply.tftest.hcl/apply
apply.tftest.hcl... �[31mfail�[0m�[0m
  run "apply"... �[31mfail�[0m�[0m
�[31m╷�[0m�[0m
�[31m│�[0m �[0m�[1m�[31mError: �[0m�[0m�[1mModule output value precondition failed�[0m
�[31m│�[0m �[0m
�[31m│�[0m �[0m�[0m  on main.tf line 10, in output "bar":
�[31m│�[0m �[0m  10:     condition     = �[4mfalse && var.foo�[0m�[0m
�[31m│�[0m �[0m    �[90m├────────────────�[0m
�[31m│�[0m �[0m�[0m    �[90m│�[0m �[1mvar.foo�[0m is true
�[31m│�[0m �[0m�[0m
�[31m│�[0m �[0mAlways fails
�[31m╵�[0m�[0m
2023-09-09T23:10:36.776+0100 [TRACE] TestStateManager: cleaning up state for apply.tftest.hcl
2023-09-09T23:10:36.776+0100 [TRACE] TestFileRunner: executing test file plan.tftest.hcl
2023-09-09T23:10:36.776+0100 [TRACE] TestFileRunner: executing run block plan.tftest.hcl/plan
2023-09-09T23:10:36.776+0100 [TRACE] TestFileRunner: called validate for plan.tftest.hcl/plan
2023-09-09T23:10:36.776+0100 [TRACE] terraform.NewContext: starting
2023-09-09T23:10:36.776+0100 [TRACE] terraform.NewContext: complete
2023-09-09T23:10:36.776+0100 [TRACE] TestFileRunner: waiting for execution during plan.tftest.hcl/plan
2023-09-09T23:10:36.776+0100 [DEBUG] TestFileRunner: starting validate for plan.tftest.hcl/plan
2023-09-09T23:10:36.776+0100 [DEBUG] Building and walking validate graph
2023-09-09T23:10:36.776+0100 [TRACE] building graph for walkValidate
2023-09-09T23:10:36.776+0100 [TRACE] Executing graph transform *terraform.ConfigTransformer
2023-09-09T23:10:36.776+0100 [TRACE] ConfigTransformer: Starting for path:
2023-09-09T23:10:36.776+0100 [TRACE] Completed graph transform *terraform.ConfigTransformer (no changes)
2023-09-09T23:10:36.776+0100 [TRACE] Executing graph transform *terraform.RootVariableTransformer
2023-09-09T23:10:36.776+0100 [TRACE] Completed graph transform *terraform.RootVariableTransformer with new graph:
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.776+0100 [TRACE] Executing graph transform *terraform.ModuleVariableTransformer
2023-09-09T23:10:36.776+0100 [TRACE] Completed graph transform *terraform.ModuleVariableTransformer (no changes)
2023-09-09T23:10:36.776+0100 [TRACE] Executing graph transform *terraform.LocalTransformer
2023-09-09T23:10:36.776+0100 [TRACE] Completed graph transform *terraform.LocalTransformer (no changes)
2023-09-09T23:10:36.776+0100 [TRACE] Executing graph transform *terraform.OutputTransformer
2023-09-09T23:10:36.776+0100 [TRACE] OutputTransformer: adding bar as *terraform.nodeExpandOutput
2023-09-09T23:10:36.776+0100 [TRACE] Completed graph transform *terraform.OutputTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.776+0100 [TRACE] Executing graph transform *terraform.checkTransformer
2023-09-09T23:10:36.776+0100 [TRACE] Completed graph transform *terraform.checkTransformer (no changes)
2023-09-09T23:10:36.776+0100 [TRACE] Executing graph transform *terraform.OrphanResourceInstanceTransformer
2023-09-09T23:10:36.776+0100 [TRACE] Completed graph transform *terraform.OrphanResourceInstanceTransformer (no changes)
2023-09-09T23:10:36.776+0100 [TRACE] Executing graph transform *terraform.StateTransformer
2023-09-09T23:10:36.776+0100 [TRACE] StateTransformer: pointless no-op call, creating no nodes at all
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.StateTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.AttachStateTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.AttachStateTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.OrphanOutputTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.OrphanOutputTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.AttachResourceConfigTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.AttachResourceConfigTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.graphTransformerMulti
2023-09-09T23:10:36.777+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.ProviderConfigTransformer
2023-09-09T23:10:36.777+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.ProviderConfigTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.777+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.MissingProviderTransformer
2023-09-09T23:10:36.777+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.MissingProviderTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.ProviderTransformer
2023-09-09T23:10:36.777+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.ProviderTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.PruneProviderTransformer
2023-09-09T23:10:36.777+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.PruneProviderTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.graphTransformerMulti (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.RemovedModuleTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.RemovedModuleTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.AttachSchemaTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.AttachSchemaTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.ModuleExpansionTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.ModuleExpansionTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.ExternalReferenceTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.ExternalReferenceTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.ReferenceTransformer
2023-09-09T23:10:36.777+0100 [DEBUG] ReferenceTransformer: "var.foo" references: []
2023-09-09T23:10:36.777+0100 [DEBUG] ReferenceTransformer: "output.bar (expand)" references: [var.foo var.foo]
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.ReferenceTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
    var.foo - *terraform.NodeRootVariable
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.AttachDependenciesTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.AttachDependenciesTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.attachDataResourceDependsOnTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.attachDataResourceDependsOnTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.DestroyEdgeTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.DestroyEdgeTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.pruneUnusedNodesTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.pruneUnusedNodesTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.TargetsTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.TargetsTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.ForcedCBDTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.ForcedCBDTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.CloseProviderTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.CloseProviderTransformer (no changes)
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.CloseRootModuleTransformer
2023-09-09T23:10:36.777+0100 [TRACE] Completed graph transform *terraform.CloseRootModuleTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
    var.foo - *terraform.NodeRootVariable
  root - *terraform.nodeCloseModule
    output.bar (expand) - *terraform.nodeExpandOutput
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.777+0100 [TRACE] Executing graph transform *terraform.TransitiveReductionTransformer
2023-09-09T23:10:36.778+0100 [TRACE] Completed graph transform *terraform.TransitiveReductionTransformer (no changes)
2023-09-09T23:10:36.778+0100 [DEBUG] Starting graph walk: walkValidate
2023-09-09T23:10:36.778+0100 [TRACE] vertex "var.foo": starting visit (*terraform.NodeRootVariable)
2023-09-09T23:10:36.778+0100 [TRACE] NodeRootVariable: evaluating var.foo
2023-09-09T23:10:36.778+0100 [TRACE] prepareFinalInputVariableValue: preparing var.foo
2023-09-09T23:10:36.778+0100 [TRACE] prepareFinalInputVariableValue: var.foo has a default value
2023-09-09T23:10:36.778+0100 [TRACE] BuiltinEvalContext: Storing final value for variable var.foo
2023-09-09T23:10:36.778+0100 [TRACE] evalVariableValidations: no validation rules declared for var.foo, so skipping
2023-09-09T23:10:36.778+0100 [TRACE] vertex "var.foo": visit complete
2023-09-09T23:10:36.778+0100 [TRACE] vertex "output.bar (expand)": starting visit (*terraform.nodeExpandOutput)
2023-09-09T23:10:36.778+0100 [TRACE] vertex "output.bar (expand)": expanding dynamic subgraph
2023-09-09T23:10:36.778+0100 [TRACE] Expanding output: adding output.bar as *terraform.NodeApplyableOutput
2023-09-09T23:10:36.778+0100 [TRACE] vertex "output.bar (expand)": entering dynamic subgraph
2023-09-09T23:10:36.778+0100 [TRACE] vertex "output.bar": starting visit (*terraform.NodeApplyableOutput)
2023-09-09T23:10:36.778+0100 [TRACE] evalCheckRules: output.bar status is now StatusUnknown
2023-09-09T23:10:36.778+0100 [TRACE] setValue: Saving Create change for output.bar in changeset
2023-09-09T23:10:36.778+0100 [TRACE] setValue: Saving value for output.bar in state
2023-09-09T23:10:36.778+0100 [TRACE] vertex "output.bar": visit complete
2023-09-09T23:10:36.778+0100 [TRACE] vertex "root": starting visit (terraform.graphNodeRoot)
2023-09-09T23:10:36.778+0100 [TRACE] vertex "root": visit complete
2023-09-09T23:10:36.778+0100 [TRACE] vertex "output.bar (expand)": dynamic subgraph completed successfully
2023-09-09T23:10:36.778+0100 [TRACE] vertex "output.bar (expand)": visit complete
2023-09-09T23:10:36.779+0100 [TRACE] vertex "root": starting visit (*terraform.nodeCloseModule)
2023-09-09T23:10:36.779+0100 [TRACE] vertex "root": visit complete
2023-09-09T23:10:36.779+0100 [DEBUG] TestFileRunner: completed validate for  plan.tftest.hcl/plan
2023-09-09T23:10:36.779+0100 [TRACE] TestFileRunner: called plan for plan.tftest.hcl/plan
2023-09-09T23:10:36.779+0100 [TRACE] terraform.NewContext: starting
2023-09-09T23:10:36.779+0100 [TRACE] terraform.NewContext: complete
2023-09-09T23:10:36.779+0100 [TRACE] TestFileRunner: waiting for execution during plan.tftest.hcl/plan
2023-09-09T23:10:36.779+0100 [DEBUG] TestFileRunner: starting plan for plan.tftest.hcl/plan
2023-09-09T23:10:36.779+0100 [DEBUG] Building and walking plan graph for NormalMode
2023-09-09T23:10:36.779+0100 [TRACE] building graph for walkPlan
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.ConfigTransformer
2023-09-09T23:10:36.779+0100 [TRACE] ConfigTransformer: Starting for path:
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.ConfigTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.RootVariableTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.RootVariableTransformer with new graph:
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.ModuleVariableTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.ModuleVariableTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.LocalTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.LocalTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.OutputTransformer
2023-09-09T23:10:36.779+0100 [TRACE] OutputTransformer: adding bar as *terraform.nodeExpandOutput
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.OutputTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.checkTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.checkTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.OrphanResourceInstanceTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.OrphanResourceInstanceTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.StateTransformer
2023-09-09T23:10:36.779+0100 [TRACE] StateTransformer: creating nodes for deposed instance objects only
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.StateTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.AttachStateTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.AttachStateTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.OrphanOutputTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.OrphanOutputTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.AttachResourceConfigTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.AttachResourceConfigTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.graphTransformerMulti
2023-09-09T23:10:36.779+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.ProviderConfigTransformer
2023-09-09T23:10:36.779+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.ProviderConfigTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.779+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.MissingProviderTransformer
2023-09-09T23:10:36.779+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.MissingProviderTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.ProviderTransformer
2023-09-09T23:10:36.779+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.ProviderTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] (graphTransformerMulti) Executing graph transform *terraform.PruneProviderTransformer
2023-09-09T23:10:36.779+0100 [TRACE] (graphTransformerMulti) Completed graph transform *terraform.PruneProviderTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.graphTransformerMulti (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.RemovedModuleTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.RemovedModuleTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.AttachSchemaTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.AttachSchemaTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.ModuleExpansionTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.ModuleExpansionTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.ExternalReferenceTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.ExternalReferenceTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.ReferenceTransformer
2023-09-09T23:10:36.779+0100 [DEBUG] ReferenceTransformer: "var.foo" references: []
2023-09-09T23:10:36.779+0100 [DEBUG] ReferenceTransformer: "output.bar (expand)" references: [var.foo var.foo]
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.ReferenceTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
    var.foo - *terraform.NodeRootVariable
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.AttachDependenciesTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.AttachDependenciesTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.attachDataResourceDependsOnTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.attachDataResourceDependsOnTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.DestroyEdgeTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.DestroyEdgeTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.pruneUnusedNodesTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.pruneUnusedNodesTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.TargetsTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.TargetsTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.ForcedCBDTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.ForcedCBDTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.CloseProviderTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.CloseProviderTransformer (no changes)
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.CloseRootModuleTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.CloseRootModuleTransformer with new graph:
  output.bar (expand) - *terraform.nodeExpandOutput
    var.foo - *terraform.NodeRootVariable
  root - *terraform.nodeCloseModule
    output.bar (expand) - *terraform.nodeExpandOutput
  var.foo - *terraform.NodeRootVariable
  ------
2023-09-09T23:10:36.779+0100 [TRACE] Executing graph transform *terraform.TransitiveReductionTransformer
2023-09-09T23:10:36.779+0100 [TRACE] Completed graph transform *terraform.TransitiveReductionTransformer (no changes)
2023-09-09T23:10:36.779+0100 [DEBUG] Starting graph walk: walkPlan
2023-09-09T23:10:36.779+0100 [TRACE] vertex "var.foo": starting visit (*terraform.NodeRootVariable)
2023-09-09T23:10:36.779+0100 [TRACE] NodeRootVariable: evaluating var.foo
2023-09-09T23:10:36.779+0100 [TRACE] prepareFinalInputVariableValue: preparing var.foo
2023-09-09T23:10:36.779+0100 [TRACE] prepareFinalInputVariableValue: var.foo has a default value
2023-09-09T23:10:36.779+0100 [TRACE] prepareFinalInputVariableValue: var.foo has no defined value
2023-09-09T23:10:36.779+0100 [TRACE] BuiltinEvalContext: Storing final value for variable var.foo
2023-09-09T23:10:36.779+0100 [TRACE] evalVariableValidations: no validation rules declared for var.foo, so skipping
2023-09-09T23:10:36.779+0100 [TRACE] vertex "var.foo": visit complete
2023-09-09T23:10:36.779+0100 [TRACE] vertex "output.bar (expand)": starting visit (*terraform.nodeExpandOutput)
2023-09-09T23:10:36.779+0100 [TRACE] vertex "output.bar (expand)": expanding dynamic subgraph
2023-09-09T23:10:36.779+0100 [TRACE] Expanding output: adding output.bar as *terraform.NodeApplyableOutput
2023-09-09T23:10:36.779+0100 [TRACE] vertex "output.bar (expand)": entering dynamic subgraph
2023-09-09T23:10:36.779+0100 [TRACE] vertex "output.bar": starting visit (*terraform.NodeApplyableOutput)
2023-09-09T23:10:36.780+0100 [TRACE] evalCheckRules: output.bar status is now StatusFail
2023-09-09T23:10:36.780+0100 [ERROR] vertex "output.bar" error: Module output value precondition failed
2023-09-09T23:10:36.780+0100 [TRACE] vertex "output.bar": visit complete, with errors
2023-09-09T23:10:36.780+0100 [TRACE] dag/walk: upstream of "root" errored, so skipping
2023-09-09T23:10:36.780+0100 [TRACE] vertex "output.bar (expand)": dynamic subgraph encountered errors: Module output value precondition failed
2023-09-09T23:10:36.780+0100 [ERROR] vertex "output.bar (expand)" error: Module output value precondition failed
2023-09-09T23:10:36.780+0100 [TRACE] vertex "output.bar (expand)": visit complete, with errors
2023-09-09T23:10:36.780+0100 [TRACE] dag/walk: upstream of "root" errored, so skipping
2023-09-09T23:10:36.780+0100 [DEBUG] TestFileRunner: completed plan for plan.tftest.hcl/plan
plan.tftest.hcl... �[32mpass�[0m�[0m
  run "plan"... �[32mpass�[0m�[0m
2023-09-09T23:10:36.780+0100 [TRACE] TestStateManager: cleaning up state for plan.tftest.hcl

�[31mFailure!�[0m�[0m 1 passed, 1 failed.

Expected Behavior

This configuration has a single output foo that always fails its precondition. There are two test cases, one each for command = plan and command = apply, each of which expect the output to fail its precondition.

Both tests should pass.

Actual Behavior

The "plan" test case passes, but "apply" fails. The precondition is observed to fail in the apply case.

$ terraform test
apply.tftest.hcl... fail
  run "apply"... fail
╷
│ Error: Module output value precondition failed
│
│   on main.tf line 10, in output "bar":
│   10:     condition     = false && var.foo
│     ├────────────────
│     │ var.foo is true
│
│ Always fails
╵
plan.tftest.hcl... pass
  run "plan"... pass

Failure! 1 passed, 1 failed.

Steps to Reproduce

1. terraform test

Additional Context

No response

References

No response

[liamcervante]

Hi @andrewesweet, thanks for filing this and for the feedback - it really is appreciated.

I do think that this is actually working as intended. If you have a look at the documentation for expect_failures: https://developer.hashicorp.com/terraform/language/v1.6.x/tests#expecting-failures, specifically the following section, you can see we have called this out as a potential for confusion:

Note: Terraform only expects failures in the operation specified by the command attribute of the run block.

Be careful when using expect_failures in run blocks with command = apply. A run block with command = apply that expects a custom condition failure will fail overall if that custom condition fails during the plan.

This is logically consistent, as the run block is expecting to be able to run an apply operation but can not because the plan failed. It is also potentially confusing, as you will see the failure in the diagnostics as the reason the test failed, even though that failure was marked as being expected.

Essentially, because the kind of custom condition you are using here is causing the plan to fail, terraform test can never actually execute the requested apply operation, and so the test fails overall. This a consequence of the expect_failures block not actually overriding the behaviour of the custom condition, but simply telling the test that it's okay if it fails. The test then fails because it couldn't run the requested operation, and reports back why it couldn't do that.

I agree this is confusing, but we don't have a particularly good workaround at the moment. This is all a consequence of the way Terraform operates and not something the testing framework can work around. I'm going to retag this as a documentation issue as we can have a look at making the part of the docs that discuss this more discoverable.

Thanks again for the feedback, and please do keep filing anything else you think is worth mentioning.

[andrewesweet]

@liamcervante, thank you for the prompt response. The behaviour, whilst unintuitive, is clearly documented so I agree with your summary.

Thanks again!

[github-actions]

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues.
If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.