diff --git a/internal/backend/local/test.go b/internal/backend/local/test.go index b0f65c7717..bfa45bf4d3 100644 --- a/internal/backend/local/test.go +++ b/internal/backend/local/test.go @@ -9,6 +9,7 @@ import ( "log" "path" "sort" + "time" "github.com/hashicorp/hcl/v2" "github.com/zclconf/go-cty/cty" @@ -252,7 +253,7 @@ func (runner *TestFileRunner) Test(file *moduletest.File) { // Then the test was requested to be stopped, so we just mark each // following test as skipped, print the status, and move on. run.Status = moduletest.Skip - runner.Suite.View.Run(run, file) + runner.Suite.View.Run(run, file, moduletest.Complete, 0) continue } @@ -261,7 +262,7 @@ func (runner *TestFileRunner) Test(file *moduletest.File) { // execute tests. Instead, we mark all remaining run blocks as // skipped, print the status, and move on. run.Status = moduletest.Skip - runner.Suite.View.Run(run, file) + runner.Suite.View.Run(run, file, moduletest.Complete, 0) continue } @@ -306,7 +307,7 @@ func (runner *TestFileRunner) Test(file *moduletest.File) { runner.RelevantStates[key].Run = run } - runner.Suite.View.Run(run, file) + runner.Suite.View.Run(run, file, moduletest.Complete, 0) file.Status = file.Status.Merge(run.Status) } } @@ -327,6 +328,9 @@ func (runner *TestFileRunner) run(run *moduletest.Run, file *moduletest.File, st return state, false } + start := time.Now().UTC().UnixMilli() + runner.Suite.View.Run(run, file, moduletest.Starting, 0) + run.Diagnostics = run.Diagnostics.Append(run.Config.Validate()) if run.Diagnostics.HasErrors() { run.Status = moduletest.Error @@ -342,7 +346,7 @@ func (runner *TestFileRunner) run(run *moduletest.Run, file *moduletest.File, st return state, false } - validateDiags := runner.validate(config, run, file) + validateDiags := runner.validate(config, run, file, start) run.Diagnostics = run.Diagnostics.Append(validateDiags) if validateDiags.HasErrors() { run.Status = moduletest.Error @@ -356,7 +360,7 @@ func (runner *TestFileRunner) run(run *moduletest.Run, file *moduletest.File, st return state, false } - planCtx, plan, planDiags := runner.plan(config, state, run, file, references) + planCtx, plan, planDiags := runner.plan(config, state, run, file, references, start) if run.Config.Command == configs.PlanTestCommand { // Then we want to assess our conditions and diagnostics differently. planDiags = run.ValidateExpectedFailures(planDiags) @@ -439,7 +443,7 @@ func (runner *TestFileRunner) run(run *moduletest.Run, file *moduletest.File, st } run.Diagnostics = filteredDiags - applyCtx, updated, applyDiags := runner.apply(plan, state, config, run, file) + applyCtx, updated, applyDiags := runner.apply(plan, state, config, run, file, moduletest.Running, start) // Remove expected diagnostics, and add diagnostics in case anything that should have failed didn't. applyDiags = run.ValidateExpectedFailures(applyDiags) @@ -504,7 +508,7 @@ func (runner *TestFileRunner) run(run *moduletest.Run, file *moduletest.File, st return updated, true } -func (runner *TestFileRunner) validate(config *configs.Config, run *moduletest.Run, file *moduletest.File) tfdiags.Diagnostics { +func (runner *TestFileRunner) validate(config *configs.Config, run *moduletest.Run, file *moduletest.File, start int64) tfdiags.Diagnostics { log.Printf("[TRACE] TestFileRunner: called validate for %s/%s", file.Name, run.Name) var diags tfdiags.Diagnostics @@ -526,7 +530,7 @@ func (runner *TestFileRunner) validate(config *configs.Config, run *moduletest.R validateDiags = tfCtx.Validate(config) log.Printf("[DEBUG] TestFileRunner: completed validate for %s/%s", file.Name, run.Name) }() - waitDiags, cancelled := runner.wait(tfCtx, runningCtx, run, file, nil) + waitDiags, cancelled := runner.wait(tfCtx, runningCtx, run, file, nil, moduletest.Running, start) if cancelled { diags = diags.Append(tfdiags.Sourceless(tfdiags.Error, "Test interrupted", "The test operation could not be completed due to an interrupt signal. Please read the remaining diagnostics carefully for any sign of failed state cleanup or dangling resources.")) @@ -568,6 +572,9 @@ func (runner *TestFileRunner) destroy(config *configs.Config, state *states.Stat runningCtx, done := context.WithCancel(context.Background()) + start := time.Now().UTC().UnixMilli() + runner.Suite.View.Run(run, file, moduletest.TearDown, 0) + var plan *plans.Plan var planDiags tfdiags.Diagnostics go func() { @@ -578,7 +585,7 @@ func (runner *TestFileRunner) destroy(config *configs.Config, state *states.Stat plan, planDiags = tfCtx.Plan(config, state, planOpts) log.Printf("[DEBUG] TestFileRunner: completed destroy plan for %s/%s", file.Name, run.Name) }() - waitDiags, cancelled := runner.wait(tfCtx, runningCtx, run, file, nil) + waitDiags, cancelled := runner.wait(tfCtx, runningCtx, run, file, nil, moduletest.TearDown, start) if cancelled { diags = diags.Append(tfdiags.Sourceless(tfdiags.Error, "Test interrupted", "The test operation could not be completed due to an interrupt signal. Please read the remaining diagnostics carefully for any sign of failed state cleanup or dangling resources.")) @@ -591,12 +598,12 @@ func (runner *TestFileRunner) destroy(config *configs.Config, state *states.Stat return state, diags } - _, updated, applyDiags := runner.apply(plan, state, config, run, file) + _, updated, applyDiags := runner.apply(plan, state, config, run, file, moduletest.TearDown, start) diags = diags.Append(applyDiags) return updated, diags } -func (runner *TestFileRunner) plan(config *configs.Config, state *states.State, run *moduletest.Run, file *moduletest.File, references []*addrs.Reference) (*terraform.Context, *plans.Plan, tfdiags.Diagnostics) { +func (runner *TestFileRunner) plan(config *configs.Config, state *states.State, run *moduletest.Run, file *moduletest.File, references []*addrs.Reference, start int64) (*terraform.Context, *plans.Plan, tfdiags.Diagnostics) { log.Printf("[TRACE] TestFileRunner: called plan for %s/%s", file.Name, run.Name) var diags tfdiags.Diagnostics @@ -648,7 +655,7 @@ func (runner *TestFileRunner) plan(config *configs.Config, state *states.State, plan, planDiags = tfCtx.Plan(config, state, planOpts) log.Printf("[DEBUG] TestFileRunner: completed plan for %s/%s", file.Name, run.Name) }() - waitDiags, cancelled := runner.wait(tfCtx, runningCtx, run, file, nil) + waitDiags, cancelled := runner.wait(tfCtx, runningCtx, run, file, nil, moduletest.Running, start) if cancelled { diags = diags.Append(tfdiags.Sourceless(tfdiags.Error, "Test interrupted", "The test operation could not be completed due to an interrupt signal. Please read the remaining diagnostics carefully for any sign of failed state cleanup or dangling resources.")) @@ -660,7 +667,7 @@ func (runner *TestFileRunner) plan(config *configs.Config, state *states.State, return tfCtx, plan, diags } -func (runner *TestFileRunner) apply(plan *plans.Plan, state *states.State, config *configs.Config, run *moduletest.Run, file *moduletest.File) (*terraform.Context, *states.State, tfdiags.Diagnostics) { +func (runner *TestFileRunner) apply(plan *plans.Plan, state *states.State, config *configs.Config, run *moduletest.Run, file *moduletest.File, progress moduletest.Progress, start int64) (*terraform.Context, *states.State, tfdiags.Diagnostics) { log.Printf("[TRACE] TestFileRunner: called apply for %s/%s", file.Name, run.Name) var diags tfdiags.Diagnostics @@ -702,7 +709,7 @@ func (runner *TestFileRunner) apply(plan *plans.Plan, state *states.State, confi updated, applyDiags = tfCtx.Apply(plan, config) log.Printf("[DEBUG] TestFileRunner: completed apply for %s/%s", file.Name, run.Name) }() - waitDiags, cancelled := runner.wait(tfCtx, runningCtx, run, file, created) + waitDiags, cancelled := runner.wait(tfCtx, runningCtx, run, file, created, progress, start) if cancelled { diags = diags.Append(tfdiags.Sourceless(tfdiags.Error, "Test interrupted", "The test operation could not be completed due to an interrupt signal. Please read the remaining diagnostics carefully for any sign of failed state cleanup or dangling resources.")) @@ -714,7 +721,7 @@ func (runner *TestFileRunner) apply(plan *plans.Plan, state *states.State, confi return tfCtx, updated, diags } -func (runner *TestFileRunner) wait(ctx *terraform.Context, runningCtx context.Context, run *moduletest.Run, file *moduletest.File, created []*plans.ResourceInstanceChangeSrc) (diags tfdiags.Diagnostics, cancelled bool) { +func (runner *TestFileRunner) wait(ctx *terraform.Context, runningCtx context.Context, run *moduletest.Run, file *moduletest.File, created []*plans.ResourceInstanceChangeSrc, progress moduletest.Progress, start int64) (diags tfdiags.Diagnostics, cancelled bool) { var identifier string if file == nil { identifier = "validate" @@ -726,6 +733,9 @@ func (runner *TestFileRunner) wait(ctx *terraform.Context, runningCtx context.Co } log.Printf("[TRACE] TestFileRunner: waiting for execution during %s", identifier) + // Keep track of when the execution is actually finished. + finished := false + // This function handles what happens when the user presses the second // interrupt. This is a "hard cancel", we are going to stop doing whatever // it is we're doing. This means even if we're halfway through creating or @@ -746,9 +756,19 @@ func (runner *TestFileRunner) wait(ctx *terraform.Context, runningCtx context.Co cancelled = true go ctx.Stop() - // Just wait for things to finish now, the overall test execution will - // exit early if this takes too long. - <-runningCtx.Done() + for !finished { + select { + case <-time.After(2 * time.Second): + // Print an update while we're waiting. + now := time.Now().UTC().UnixMilli() + runner.Suite.View.Run(run, file, progress, now-start) + case <-runningCtx.Done(): + // Just wait for things to finish now, the overall test execution will + // exit early if this takes too long. + finished = true + } + } + } // This function handles what happens when the user presses the first @@ -758,25 +778,39 @@ func (runner *TestFileRunner) wait(ctx *terraform.Context, runningCtx context.Co handleStopped := func() { log.Printf("[DEBUG] TestFileRunner: test execution stopped during %s", identifier) + for !finished { + select { + case <-time.After(2 * time.Second): + // Print an update while we're waiting. + now := time.Now().UTC().UnixMilli() + runner.Suite.View.Run(run, file, progress, now-start) + case <-runner.Suite.CancelledCtx.Done(): + // We've been asked again. This time we stop whatever we're doing + // and abandon all attempts to do anything reasonable. + handleCancelled() + case <-runningCtx.Done(): + // Do nothing, we finished safely and skipping the remaining tests + // will be handled elsewhere. + finished = true + } + } + + } + + for !finished { select { + case <-time.After(2 * time.Second): + // Print an update while we're waiting. + now := time.Now().UTC().UnixMilli() + runner.Suite.View.Run(run, file, progress, now-start) + case <-runner.Suite.StoppedCtx.Done(): + handleStopped() case <-runner.Suite.CancelledCtx.Done(): - // We've been asked again. This time we stop whatever we're doing - // and abandon all attempts to do anything reasonable. handleCancelled() case <-runningCtx.Done(): - // Do nothing, we finished safely and skipping the remaining tests - // will be handled elsewhere. + // The operation exited normally. + finished = true } - - } - - select { - case <-runner.Suite.StoppedCtx.Done(): - handleStopped() - case <-runner.Suite.CancelledCtx.Done(): - handleCancelled() - case <-runningCtx.Done(): - // The operation exited normally. } return diags, cancelled diff --git a/internal/cloud/test_test.go b/internal/cloud/test_test.go index 8207b411ad..2b1dbee164 100644 --- a/internal/cloud/test_test.go +++ b/internal/cloud/test_test.go @@ -173,8 +173,8 @@ func TestTest_JSON(t *testing.T) { expected := `{"@level":"info","@message":"Terraform 1.6.0-dev","@module":"terraform.ui","@timestamp":"2023-09-12T08:29:27.257413+02:00","terraform":"1.6.0-dev","type":"version","ui":"1.2"} {"@level":"info","@message":"Found 1 file and 2 run blocks","@module":"terraform.ui","@timestamp":"2023-09-12T08:29:27.268731+02:00","test_abstract":{"main.tftest.hcl":["defaults","overrides"]},"type":"test_abstract"} {"@level":"info","@message":"main.tftest.hcl... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-12T08:29:27.268889+02:00","test_file":{"path":"main.tftest.hcl","progress":"starting"},"type":"test_file"} -{"@level":"info","@message":" \"defaults\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T08:29:27.710541+02:00","test_run":{"path":"main.tftest.hcl","run":"defaults","status":"pass"},"type":"test_run"} -{"@level":"info","@message":" \"overrides\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T08:29:27.833351+02:00","test_run":{"path":"main.tftest.hcl","run":"overrides","status":"pass"},"type":"test_run"} +{"@level":"info","@message":" \"defaults\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T08:29:27.710541+02:00","test_run":{"path":"main.tftest.hcl","run":"defaults","progress":"complete","status":"pass"},"type":"test_run"} +{"@level":"info","@message":" \"overrides\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T08:29:27.833351+02:00","test_run":{"path":"main.tftest.hcl","run":"overrides","progress":"complete","status":"pass"},"type":"test_run"} {"@level":"info","@message":"main.tftest.hcl... tearing down","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-12T08:29:27.833375+02:00","test_file":{"path":"main.tftest.hcl","progress":"teardown"},"type":"test_file"} {"@level":"info","@message":"main.tftest.hcl... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-12T08:29:27.956488+02:00","test_file":{"path":"main.tftest.hcl","progress":"complete","status":"pass"},"type":"test_file"} {"@level":"info","@message":"Success! 2 passed, 0 failed.","@module":"terraform.ui","@timestamp":"2023-09-12T08:29:27.956510+02:00","test_summary":{"status":"pass","passed":2,"failed":0,"errored":0,"skipped":0},"type":"test_summary"} @@ -753,3 +753,181 @@ Failure! 1 passed, 1 failed. t.Errorf("incorrect number of cancels, expected 2 but was %d", mock.TestRuns.cancels) } } + +func TestTest_LongRunningTest(t *testing.T) { + + streams, done := terminal.StreamsForTesting(t) + view := views.NewTest(arguments.ViewHuman, views.NewView(streams)) + + colorize := mockColorize() + colorize.Disable = true + + mock := NewMockClient() + client := &tfe.Client{ + ConfigurationVersions: mock.ConfigurationVersions, + Organizations: mock.Organizations, + RegistryModules: mock.RegistryModules, + TestRuns: mock.TestRuns, + } + + if _, err := client.Organizations.Create(context.Background(), tfe.OrganizationCreateOptions{ + Name: tfe.String("organisation"), + }); err != nil { + t.Fatalf("failed to create organisation: %v", err) + } + + if _, err := client.RegistryModules.Create(context.Background(), "organisation", tfe.RegistryModuleCreateOptions{ + Name: tfe.String("name"), + Provider: tfe.String("provider"), + RegistryName: "app.terraform.io", + Namespace: "organisation", + }); err != nil { + t.Fatalf("failed to create registry module: %v", err) + } + + runner := TestSuiteRunner{ + // Configuration data. + ConfigDirectory: "testdata/test-long-running", + TestingDirectory: "tests", + Config: nil, // We don't need this for this test. + Source: "app.terraform.io/organisation/name/provider", + + // Cancellation controls, we won't be doing any cancellations in this + // test. + Stopped: false, + Cancelled: false, + StoppedCtx: context.Background(), + CancelledCtx: context.Background(), + + // Test Options, empty for this test. + GlobalVariables: nil, + Verbose: false, + Filters: nil, + + // Outputs + Renderer: &jsonformat.Renderer{ + Streams: streams, + Colorize: colorize, + RunningInAutomation: false, + }, + View: view, + Streams: streams, + + // Networking + Services: nil, // Don't need this when the client is overridden. + clientOverride: client, + } + + _, diags := runner.Test() + if len(diags) > 0 { + t.Errorf("found diags and expected none: %s", diags.ErrWithWarnings()) + } + + output := done(t) + actual := output.All() + + // The long running test logs actually contain additional progress updates, + // but this test should ignore them and just show the usual output. + + expected := `main.tftest.hcl... in progress + just_go... pass +main.tftest.hcl... tearing down +main.tftest.hcl... pass + +Success! 1 passed, 0 failed. +` + + if diff := cmp.Diff(expected, actual); len(diff) > 0 { + t.Errorf("expected:\n%s\nactual:\n%s\ndiff:\n%s", expected, actual, diff) + } +} + +func TestTest_LongRunningTestJSON(t *testing.T) { + + streams, done := terminal.StreamsForTesting(t) + view := views.NewTest(arguments.ViewHuman, views.NewView(streams)) + + colorize := mockColorize() + colorize.Disable = true + + mock := NewMockClient() + client := &tfe.Client{ + ConfigurationVersions: mock.ConfigurationVersions, + Organizations: mock.Organizations, + RegistryModules: mock.RegistryModules, + TestRuns: mock.TestRuns, + } + + if _, err := client.Organizations.Create(context.Background(), tfe.OrganizationCreateOptions{ + Name: tfe.String("organisation"), + }); err != nil { + t.Fatalf("failed to create organisation: %v", err) + } + + if _, err := client.RegistryModules.Create(context.Background(), "organisation", tfe.RegistryModuleCreateOptions{ + Name: tfe.String("name"), + Provider: tfe.String("provider"), + RegistryName: "app.terraform.io", + Namespace: "organisation", + }); err != nil { + t.Fatalf("failed to create registry module: %v", err) + } + + runner := TestSuiteRunner{ + // Configuration data. + ConfigDirectory: "testdata/test-long-running", + TestingDirectory: "tests", + Config: nil, // We don't need this for this test. + Source: "app.terraform.io/organisation/name/provider", + + // Cancellation controls, we won't be doing any cancellations in this + // test. + Stopped: false, + Cancelled: false, + StoppedCtx: context.Background(), + CancelledCtx: context.Background(), + + // Test Options, empty for this test. + GlobalVariables: nil, + Verbose: false, + Filters: nil, + + // Outputs + Renderer: nil, // This should force the logs to render as JSON. + View: view, + Streams: streams, + + // Networking + Services: nil, // Don't need this when the client is overridden. + clientOverride: client, + } + + _, diags := runner.Test() + if len(diags) > 0 { + t.Errorf("found diags and expected none: %s", diags.ErrWithWarnings()) + } + + output := done(t) + actual := output.All() + + // This test should still include the progress updates as we're doing the + // JSON output. + + expected := `{"@level":"info","@message":"Terraform 1.7.0-dev","@module":"terraform.ui","@timestamp":"2023-09-28T14:57:09.175210+02:00","terraform":"1.7.0-dev","type":"version","ui":"1.2"} +{"@level":"info","@message":"Found 1 file and 1 run block","@module":"terraform.ui","@timestamp":"2023-09-28T14:57:09.189212+02:00","test_abstract":{"main.tftest.hcl":["just_go"]},"type":"test_abstract"} +{"@level":"info","@message":"main.tftest.hcl... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-28T14:57:09.189386+02:00","test_file":{"path":"main.tftest.hcl","progress":"starting"},"type":"test_file"} +{"@level":"info","@message":" \"just_go\"... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"just_go","@timestamp":"2023-09-28T14:57:09.189429+02:00","test_run":{"path":"main.tftest.hcl","run":"just_go","progress":"starting","elapsed":0},"type":"test_run"} +{"@level":"info","@message":" \"just_go\"... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"just_go","@timestamp":"2023-09-28T14:57:11.341278+02:00","test_run":{"path":"main.tftest.hcl","run":"just_go","progress":"running","elapsed":2152},"type":"test_run"} +{"@level":"info","@message":" \"just_go\"... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"just_go","@timestamp":"2023-09-28T14:57:13.343465+02:00","test_run":{"path":"main.tftest.hcl","run":"just_go","progress":"running","elapsed":4154},"type":"test_run"} +{"@level":"info","@message":" \"just_go\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"just_go","@timestamp":"2023-09-28T14:57:14.381552+02:00","test_run":{"path":"main.tftest.hcl","run":"just_go","progress":"complete","status":"pass"},"type":"test_run"} +{"@level":"info","@message":"main.tftest.hcl... tearing down","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-28T14:57:14.381655+02:00","test_file":{"path":"main.tftest.hcl","progress":"teardown"},"type":"test_file"} +{"@level":"info","@message":" \"just_go\"... tearing down","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"just_go","@timestamp":"2023-09-28T14:57:14.381712+02:00","test_run":{"path":"main.tftest.hcl","run":"just_go","progress":"teardown","elapsed":0},"type":"test_run"} +{"@level":"info","@message":" \"just_go\"... tearing down","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"just_go","@timestamp":"2023-09-28T14:57:16.477705+02:00","test_run":{"path":"main.tftest.hcl","run":"just_go","progress":"teardown","elapsed":2096},"type":"test_run"} +{"@level":"info","@message":"main.tftest.hcl... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-28T14:57:17.517309+02:00","test_file":{"path":"main.tftest.hcl","progress":"complete","status":"pass"},"type":"test_file"} +{"@level":"info","@message":"Success! 1 passed, 0 failed.","@module":"terraform.ui","@timestamp":"2023-09-28T14:57:17.517494+02:00","test_summary":{"status":"pass","passed":1,"failed":0,"errored":0,"skipped":0},"type":"test_summary"} +` + + if diff := cmp.Diff(expected, actual); len(diff) > 0 { + t.Errorf("expected:\n%s\nactual:\n%s\ndiff:\n%s", expected, actual, diff) + } +} diff --git a/internal/cloud/testdata/test-cancel/test.log b/internal/cloud/testdata/test-cancel/test.log index ac6a5b6051..104451b48d 100644 --- a/internal/cloud/testdata/test-cancel/test.log +++ b/internal/cloud/testdata/test-cancel/test.log @@ -2,8 +2,8 @@ {"@level":"info","@message":"Found 1 file and 2 run blocks","@module":"terraform.ui","@timestamp":"2023-09-12T09:24:05.440805+02:00","test_abstract":{"main.tftest.hcl":["defaults","overrides"]},"type":"test_abstract"} {"@level":"info","@message":"main.tftest.hcl... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-12T09:24:05.440916+02:00","test_file":{"path":"main.tftest.hcl","progress":"starting"},"type":"test_file"} {"@level":"info","@message":"\nInterrupt received.\nPlease wait for Terraform to exit or data loss may occur.\nGracefully shutting down...\n","@module":"terraform.ui","@timestamp":"2023-09-12T09:24:05.606776+02:00","type":"log"} -{"@level":"info","@message":" \"defaults\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T09:24:05.645827+02:00","test_run":{"path":"main.tftest.hcl","run":"defaults","status":"pass"},"type":"test_run"} -{"@level":"info","@message":" \"overrides\"... skip","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T09:24:05.645853+02:00","test_run":{"path":"main.tftest.hcl","run":"overrides","status":"skip"},"type":"test_run"} +{"@level":"info","@message":" \"defaults\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T09:24:05.645827+02:00","test_run":{"path":"main.tftest.hcl","run":"defaults","progress":"complete","status":"pass"},"type":"test_run"} +{"@level":"info","@message":" \"overrides\"... skip","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T09:24:05.645853+02:00","test_run":{"path":"main.tftest.hcl","run":"overrides","progress":"complete","status":"skip"},"type":"test_run"} {"@level":"info","@message":"main.tftest.hcl... tearing down","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-12T09:24:05.645859+02:00","test_file":{"path":"main.tftest.hcl","progress":"teardown"},"type":"test_file"} {"@level":"info","@message":"main.tftest.hcl... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-12T09:24:05.645868+02:00","test_file":{"path":"main.tftest.hcl","progress":"complete","status":"pass"},"type":"test_file"} {"@level":"info","@message":"Success! 1 passed, 0 failed, 1 skipped.","@module":"terraform.ui","@timestamp":"2023-09-12T09:24:05.645907+02:00","test_summary":{"status":"pass","passed":1,"failed":0,"errored":0,"skipped":1},"type":"test_summary"} diff --git a/internal/cloud/testdata/test-force-cancel/test.log b/internal/cloud/testdata/test-force-cancel/test.log index 452f77293d..9956d5b9b9 100644 --- a/internal/cloud/testdata/test-force-cancel/test.log +++ b/internal/cloud/testdata/test-force-cancel/test.log @@ -1,11 +1,11 @@ {"@level":"info","@message":"Terraform 1.7.0-dev","@module":"terraform.ui","@timestamp":"2023-09-12T09:25:39.749719+02:00","terraform":"1.7.0-dev","type":"version","ui":"1.2"} {"@level":"info","@message":"Found 1 file and 2 run blocks","@module":"terraform.ui","@timestamp":"2023-09-12T09:25:39.771279+02:00","test_abstract":{"main.tftest.hcl":["defaults","overrides"]},"type":"test_abstract"} {"@level":"info","@message":"main.tftest.hcl... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-12T09:25:39.771341+02:00","test_file":{"path":"main.tftest.hcl","progress":"starting"},"type":"test_file"} -{"@level":"info","@message":" \"defaults\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T09:25:39.984002+02:00","test_run":{"path":"main.tftest.hcl","run":"defaults","status":"pass"},"type":"test_run"} +{"@level":"info","@message":" \"defaults\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T09:25:39.984002+02:00","test_run":{"path":"main.tftest.hcl","run":"defaults","progress":"complete","status":"pass"},"type":"test_run"} {"@level":"info","@message":"\nInterrupt received.\nPlease wait for Terraform to exit or data loss may occur.\nGracefully shutting down...\n","@module":"terraform.ui","@timestamp":"2023-09-12T09:25:41.055021+02:00","type":"log"} {"@level":"info","@message":"\nTwo interrupts received. Exiting immediately. Note that data loss may have occurred.\n","@module":"terraform.ui","@timestamp":"2023-09-12T09:25:41.206917+02:00","type":"log"} {"@level":"error","@message":"Terraform was interrupted during test execution, and may not have performed the expected cleanup operations.","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T09:25:41.207183+02:00","test_interrupt":{"planned":["time_sleep.wait_5_seconds","tfcoremock_simple_resource.resource"]},"type":"test_interrupt"} -{"@level":"info","@message":" \"overrides\"... fail","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T09:25:41.210583+02:00","test_run":{"path":"main.tftest.hcl","run":"overrides","status":"error"},"type":"test_run"} +{"@level":"info","@message":" \"overrides\"... fail","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T09:25:41.210583+02:00","test_run":{"path":"main.tftest.hcl","run":"overrides","progress":"complete","status":"error"},"type":"test_run"} {"@level":"error","@message":"Error: Test interrupted","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T09:25:41.210638+02:00","diagnostic":{"severity":"error","summary":"Test interrupted","detail":"The test operation could not be completed due to an interrupt signal. Please read the remaining diagnostics carefully for any sign of failed state cleanup or dangling resources."},"type":"diagnostic"} {"@level":"error","@message":"Error: Create time sleep error","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T09:25:41.211201+02:00","diagnostic":{"severity":"error","summary":"Create time sleep error","detail":"Original Error: context canceled","address":"time_sleep.wait_5_seconds","range":{"filename":"main.tf","start":{"line":7,"column":40,"byte":110},"end":{"line":7,"column":41,"byte":111}},"snippet":{"context":"resource \"time_sleep\" \"wait_5_seconds\"","code":"resource \"time_sleep\" \"wait_5_seconds\" {","start_line":7,"highlight_start_offset":39,"highlight_end_offset":40,"values":[]}},"type":"diagnostic"} {"@level":"error","@message":"Error: execution halted","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T09:25:41.211224+02:00","diagnostic":{"severity":"error","summary":"execution halted","detail":""},"type":"diagnostic"} diff --git a/internal/cloud/testdata/test-long-running/main.tf b/internal/cloud/testdata/test-long-running/main.tf new file mode 100644 index 0000000000..9438a3ae57 --- /dev/null +++ b/internal/cloud/testdata/test-long-running/main.tf @@ -0,0 +1,5 @@ + +resource "time_sleep" "sleep" { + create_duration = "5s" + destroy_duration = "3s" +} diff --git a/internal/cloud/testdata/test-long-running/main.tftest.hcl b/internal/cloud/testdata/test-long-running/main.tftest.hcl new file mode 100644 index 0000000000..5080662b55 --- /dev/null +++ b/internal/cloud/testdata/test-long-running/main.tftest.hcl @@ -0,0 +1 @@ +run "just_go" {} diff --git a/internal/cloud/testdata/test-long-running/test.log b/internal/cloud/testdata/test-long-running/test.log new file mode 100644 index 0000000000..be70381d15 --- /dev/null +++ b/internal/cloud/testdata/test-long-running/test.log @@ -0,0 +1,12 @@ +{"@level":"info","@message":"Terraform 1.7.0-dev","@module":"terraform.ui","@timestamp":"2023-09-28T14:57:09.175210+02:00","terraform":"1.7.0-dev","type":"version","ui":"1.2"} +{"@level":"info","@message":"Found 1 file and 1 run block","@module":"terraform.ui","@timestamp":"2023-09-28T14:57:09.189212+02:00","test_abstract":{"main.tftest.hcl":["just_go"]},"type":"test_abstract"} +{"@level":"info","@message":"main.tftest.hcl... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-28T14:57:09.189386+02:00","test_file":{"path":"main.tftest.hcl","progress":"starting"},"type":"test_file"} +{"@level":"info","@message":" \"just_go\"... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"just_go","@timestamp":"2023-09-28T14:57:09.189429+02:00","test_run":{"path":"main.tftest.hcl","run":"just_go","progress":"starting","elapsed":0},"type":"test_run"} +{"@level":"info","@message":" \"just_go\"... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"just_go","@timestamp":"2023-09-28T14:57:11.341278+02:00","test_run":{"path":"main.tftest.hcl","run":"just_go","progress":"running","elapsed":2152},"type":"test_run"} +{"@level":"info","@message":" \"just_go\"... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"just_go","@timestamp":"2023-09-28T14:57:13.343465+02:00","test_run":{"path":"main.tftest.hcl","run":"just_go","progress":"running","elapsed":4154},"type":"test_run"} +{"@level":"info","@message":" \"just_go\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"just_go","@timestamp":"2023-09-28T14:57:14.381552+02:00","test_run":{"path":"main.tftest.hcl","run":"just_go","progress":"complete","status":"pass"},"type":"test_run"} +{"@level":"info","@message":"main.tftest.hcl... tearing down","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-28T14:57:14.381655+02:00","test_file":{"path":"main.tftest.hcl","progress":"teardown"},"type":"test_file"} +{"@level":"info","@message":" \"just_go\"... tearing down","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"just_go","@timestamp":"2023-09-28T14:57:14.381712+02:00","test_run":{"path":"main.tftest.hcl","run":"just_go","progress":"teardown","elapsed":0},"type":"test_run"} +{"@level":"info","@message":" \"just_go\"... tearing down","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"just_go","@timestamp":"2023-09-28T14:57:16.477705+02:00","test_run":{"path":"main.tftest.hcl","run":"just_go","progress":"teardown","elapsed":2096},"type":"test_run"} +{"@level":"info","@message":"main.tftest.hcl... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-28T14:57:17.517309+02:00","test_file":{"path":"main.tftest.hcl","progress":"complete","status":"pass"},"type":"test_file"} +{"@level":"info","@message":"Success! 1 passed, 0 failed.","@module":"terraform.ui","@timestamp":"2023-09-28T14:57:17.517494+02:00","test_summary":{"status":"pass","passed":1,"failed":0,"errored":0,"skipped":0},"type":"test_summary"} diff --git a/internal/cloud/testdata/test-verbose/test.log b/internal/cloud/testdata/test-verbose/test.log index 92aeb4f1f8..4763511200 100644 --- a/internal/cloud/testdata/test-verbose/test.log +++ b/internal/cloud/testdata/test-verbose/test.log @@ -1,11 +1,11 @@ {"@level":"info","@message":"Terraform 1.7.0-dev","@module":"terraform.ui","@timestamp":"2023-09-12T08:30:36.443282+02:00","terraform":"1.7.0-dev","type":"version","ui":"1.2"} {"@level":"info","@message":"Found 1 file and 2 run blocks","@module":"terraform.ui","@timestamp":"2023-09-12T08:30:36.453493+02:00","test_abstract":{"main.tftest.hcl":["defaults","overrides"]},"type":"test_abstract"} {"@level":"info","@message":"main.tftest.hcl... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-12T08:30:36.453557+02:00","test_file":{"path":"main.tftest.hcl","progress":"starting"},"type":"test_file"} -{"@level":"info","@message":" \"defaults\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T08:30:37.184747+02:00","test_run":{"path":"main.tftest.hcl","run":"defaults","status":"pass"},"type":"test_run"} +{"@level":"info","@message":" \"defaults\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T08:30:37.184747+02:00","test_run":{"path":"main.tftest.hcl","run":"defaults","progress":"complete","status":"pass"},"type":"test_run"} {"@level":"info","@message":"-verbose flag enabled, printing plan","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T08:30:37.184891+02:00","test_plan":{"plan_format_version":"1.2","output_changes":{"input":{"actions":["create"],"before":null,"after":"Hello, world!","after_unknown":false,"before_sensitive":false,"after_sensitive":false}},"relevant_attributes":[{"resource":"data.null_data_source.values","attribute":["outputs","data"]}],"provider_format_version":"1.0","provider_schemas":{"registry.terraform.io/hashicorp/null":{"provider":{"version":0,"block":{"description_kind":"plain"}},"resource_schemas":{"null_resource":{"version":0,"block":{"attributes":{"id":{"type":"string","description":"This is set to a random value at create time.","description_kind":"plain","computed":true},"triggers":{"type":["map","string"],"description":"A map of arbitrary strings that, when changed, will force the null resource to be replaced, re-running any associated provisioners.","description_kind":"plain","optional":true}},"description":"The `null_resource` resource implements the standard resource lifecycle but takes no further action.\n\nThe `triggers` argument allows specifying an arbitrary set of values that, when changed, will cause the resource to be replaced.","description_kind":"plain"}}},"data_source_schemas":{"null_data_source":{"version":0,"block":{"attributes":{"has_computed_default":{"type":"string","description":"If set, its literal value will be stored and returned. If not, its value defaults to `\"default\"`. This argument exists primarily for testing and has little practical use.","description_kind":"plain","optional":true,"computed":true},"id":{"type":"string","description":"This attribute is only present for some legacy compatibility issues and should not be used. It will be removed in a future version.","description_kind":"plain","deprecated":true,"computed":true},"inputs":{"type":["map","string"],"description":"A map of arbitrary strings that is copied into the `outputs` attribute, and accessible directly for interpolation.","description_kind":"plain","optional":true},"outputs":{"type":["map","string"],"description":"After the data source is \"read\", a copy of the `inputs` map.","description_kind":"plain","computed":true},"random":{"type":"string","description":"A random value. This is primarily for testing and has little practical use; prefer the [hashicorp/random provider](https://registry.terraform.io/providers/hashicorp/random) for more practical random number use-cases.","description_kind":"plain","computed":true}},"description":"The `null_data_source` data source implements the standard data source lifecycle but does not\ninteract with any external APIs.\n\nHistorically, the `null_data_source` was typically used to construct intermediate values to re-use elsewhere in configuration. The\nsame can now be achieved using [locals](https://www.terraform.io/docs/language/values/locals.html).\n","description_kind":"plain","deprecated":true}}}}}},"type":"test_plan"} {"@level":"warn","@message":"Warning: Deprecated","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T08:30:37.185952+02:00","diagnostic":{"severity":"warning","summary":"Deprecated","detail":"The null_data_source was historically used to construct intermediate values to re-use elsewhere in configuration, the same can now be achieved using locals","address":"data.null_data_source.values","range":{"filename":"main.tf","start":{"line":7,"column":34,"byte":104},"end":{"line":7,"column":35,"byte":105}},"snippet":{"context":"data \"null_data_source\" \"values\"","code":"data \"null_data_source\" \"values\" {","start_line":7,"highlight_start_offset":33,"highlight_end_offset":34,"values":[]}},"type":"diagnostic"} {"@level":"warn","@message":"Warning: Deprecated","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T08:30:37.186067+02:00","diagnostic":{"severity":"warning","summary":"Deprecated","detail":"The null_data_source was historically used to construct intermediate values to re-use elsewhere in configuration, the same can now be achieved using locals","address":"data.null_data_source.values","range":{"filename":"main.tf","start":{"line":7,"column":34,"byte":104},"end":{"line":7,"column":35,"byte":105}},"snippet":{"context":"data \"null_data_source\" \"values\"","code":"data \"null_data_source\" \"values\" {","start_line":7,"highlight_start_offset":33,"highlight_end_offset":34,"values":[]}},"type":"diagnostic"} -{"@level":"info","@message":" \"overrides\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T08:30:37.246268+02:00","test_run":{"path":"main.tftest.hcl","run":"overrides","status":"pass"},"type":"test_run"} +{"@level":"info","@message":" \"overrides\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T08:30:37.246268+02:00","test_run":{"path":"main.tftest.hcl","run":"overrides","progress":"complete","status":"pass"},"type":"test_run"} {"@level":"info","@message":"-verbose flag enabled, printing state","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T08:30:37.246362+02:00","test_state":{"state_format_version":"1.0","root_module":{"resources":[{"address":"data.null_data_source.values","mode":"data","type":"null_data_source","name":"values","provider_name":"registry.terraform.io/hashicorp/null","schema_version":0,"values":{"has_computed_default":"default","id":"static","inputs":{"data":"Hello, universe!"},"outputs":{"data":"Hello, universe!"},"random":"8484833523059069761"},"sensitive_values":{"inputs":{},"outputs":{}}}]},"outputs":{"input":{"sensitive":false,"value":"Hello, universe!","type":"string"}},"provider_format_version":"1.0","provider_schemas":{"registry.terraform.io/hashicorp/null":{"provider":{"version":0,"block":{"description_kind":"plain"}},"resource_schemas":{"null_resource":{"version":0,"block":{"attributes":{"id":{"type":"string","description":"This is set to a random value at create time.","description_kind":"plain","computed":true},"triggers":{"type":["map","string"],"description":"A map of arbitrary strings that, when changed, will force the null resource to be replaced, re-running any associated provisioners.","description_kind":"plain","optional":true}},"description":"The `null_resource` resource implements the standard resource lifecycle but takes no further action.\n\nThe `triggers` argument allows specifying an arbitrary set of values that, when changed, will cause the resource to be replaced.","description_kind":"plain"}}},"data_source_schemas":{"null_data_source":{"version":0,"block":{"attributes":{"has_computed_default":{"type":"string","description":"If set, its literal value will be stored and returned. If not, its value defaults to `\"default\"`. This argument exists primarily for testing and has little practical use.","description_kind":"plain","optional":true,"computed":true},"id":{"type":"string","description":"This attribute is only present for some legacy compatibility issues and should not be used. It will be removed in a future version.","description_kind":"plain","deprecated":true,"computed":true},"inputs":{"type":["map","string"],"description":"A map of arbitrary strings that is copied into the `outputs` attribute, and accessible directly for interpolation.","description_kind":"plain","optional":true},"outputs":{"type":["map","string"],"description":"After the data source is \"read\", a copy of the `inputs` map.","description_kind":"plain","computed":true},"random":{"type":"string","description":"A random value. This is primarily for testing and has little practical use; prefer the [hashicorp/random provider](https://registry.terraform.io/providers/hashicorp/random) for more practical random number use-cases.","description_kind":"plain","computed":true}},"description":"The `null_data_source` data source implements the standard data source lifecycle but does not\ninteract with any external APIs.\n\nHistorically, the `null_data_source` was typically used to construct intermediate values to re-use elsewhere in configuration. The\nsame can now be achieved using [locals](https://www.terraform.io/docs/language/values/locals.html).\n","description_kind":"plain","deprecated":true}}}}}},"type":"test_state"} {"@level":"warn","@message":"Warning: Deprecated","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T08:30:37.247116+02:00","diagnostic":{"severity":"warning","summary":"Deprecated","detail":"The null_data_source was historically used to construct intermediate values to re-use elsewhere in configuration, the same can now be achieved using locals","address":"data.null_data_source.values","range":{"filename":"main.tf","start":{"line":7,"column":34,"byte":104},"end":{"line":7,"column":35,"byte":105}},"snippet":{"context":"data \"null_data_source\" \"values\"","code":"data \"null_data_source\" \"values\" {","start_line":7,"highlight_start_offset":33,"highlight_end_offset":34,"values":[]}},"type":"diagnostic"} {"@level":"warn","@message":"Warning: Deprecated","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T08:30:37.247182+02:00","diagnostic":{"severity":"warning","summary":"Deprecated","detail":"The null_data_source was historically used to construct intermediate values to re-use elsewhere in configuration, the same can now be achieved using locals","address":"data.null_data_source.values","range":{"filename":"main.tf","start":{"line":7,"column":34,"byte":104},"end":{"line":7,"column":35,"byte":105}},"snippet":{"context":"data \"null_data_source\" \"values\"","code":"data \"null_data_source\" \"values\" {","start_line":7,"highlight_start_offset":33,"highlight_end_offset":34,"values":[]}},"type":"diagnostic"} diff --git a/internal/cloud/testdata/test/test.log b/internal/cloud/testdata/test/test.log index 441d2858ad..82eef95b5c 100644 --- a/internal/cloud/testdata/test/test.log +++ b/internal/cloud/testdata/test/test.log @@ -1,8 +1,8 @@ {"@level":"info","@message":"Terraform 1.6.0-dev","@module":"terraform.ui","@timestamp":"2023-09-12T08:29:27.257413+02:00","terraform":"1.6.0-dev","type":"version","ui":"1.2"} {"@level":"info","@message":"Found 1 file and 2 run blocks","@module":"terraform.ui","@timestamp":"2023-09-12T08:29:27.268731+02:00","test_abstract":{"main.tftest.hcl":["defaults","overrides"]},"type":"test_abstract"} {"@level":"info","@message":"main.tftest.hcl... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-12T08:29:27.268889+02:00","test_file":{"path":"main.tftest.hcl","progress":"starting"},"type":"test_file"} -{"@level":"info","@message":" \"defaults\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T08:29:27.710541+02:00","test_run":{"path":"main.tftest.hcl","run":"defaults","status":"pass"},"type":"test_run"} -{"@level":"info","@message":" \"overrides\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T08:29:27.833351+02:00","test_run":{"path":"main.tftest.hcl","run":"overrides","status":"pass"},"type":"test_run"} +{"@level":"info","@message":" \"defaults\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"defaults","@timestamp":"2023-09-12T08:29:27.710541+02:00","test_run":{"path":"main.tftest.hcl","run":"defaults","progress":"complete","status":"pass"},"type":"test_run"} +{"@level":"info","@message":" \"overrides\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"overrides","@timestamp":"2023-09-12T08:29:27.833351+02:00","test_run":{"path":"main.tftest.hcl","run":"overrides","progress":"complete","status":"pass"},"type":"test_run"} {"@level":"info","@message":"main.tftest.hcl... tearing down","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-12T08:29:27.833375+02:00","test_file":{"path":"main.tftest.hcl","progress":"teardown"},"type":"test_file"} {"@level":"info","@message":"main.tftest.hcl... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@timestamp":"2023-09-12T08:29:27.956488+02:00","test_file":{"path":"main.tftest.hcl","progress":"complete","status":"pass"},"type":"test_file"} {"@level":"info","@message":"Success! 2 passed, 0 failed.","@module":"terraform.ui","@timestamp":"2023-09-12T08:29:27.956510+02:00","test_summary":{"status":"pass","passed":2,"failed":0,"errored":0,"skipped":0},"type":"test_summary"} diff --git a/internal/command/jsonformat/renderer.go b/internal/command/jsonformat/renderer.go index 31336fd5cf..7e3c7164b8 100644 --- a/internal/command/jsonformat/renderer.go +++ b/internal/command/jsonformat/renderer.go @@ -218,6 +218,9 @@ func (renderer Renderer) RenderLog(log *JSONLog) error { case "skip", "pending": msg = fmt.Sprintf(renderer.Colorize.Color("%s... [light_gray]%s[reset]"), status.Path, string(status.Status)) } + case "running": + // Don't print anything for the running status. + break } renderer.Streams.Println(msg) @@ -225,6 +228,12 @@ func (renderer Renderer) RenderLog(log *JSONLog) error { case LogTestRun: status := log.TestRunStatus + if status.Progress != "complete" { + // Don't print anything for status updates, we only report when the + // run is actually finished. + break + } + var msg string switch status.Status { case "error", "fail": diff --git a/internal/command/test_test.go b/internal/command/test_test.go index 7d45a1427c..fd7b848981 100644 --- a/internal/command/test_test.go +++ b/internal/command/test_test.go @@ -4,6 +4,7 @@ package command import ( + "encoding/json" "fmt" "path" "strings" @@ -1458,3 +1459,134 @@ operation, and the specified output value is only known after apply. } } + +// This test takes around 10 seconds to complete, as we're testing the progress +// updates that are printed every 2 seconds. Sorry! +func TestTest_LongRunningTest(t *testing.T) { + td := t.TempDir() + testCopyDir(t, testFixturePath(path.Join("test", "long_running")), td) + defer testChdir(t, td)() + + provider := testing_command.NewProvider(nil) + view, done := testView(t) + + c := &TestCommand{ + Meta: Meta{ + testingOverrides: metaOverridesForProvider(provider.Provider), + View: view, + }, + } + + code := c.Run([]string{"-no-color"}) + output := done(t) + + if code != 0 { + t.Errorf("expected status code 0 but got %d", code) + } + + actual := output.All() + expected := `main.tftest.hcl... in progress + run "test"... pass +main.tftest.hcl... tearing down +main.tftest.hcl... pass + +Success! 1 passed, 0 failed. +` + + if code != 0 { + t.Errorf("expected return code %d but got %d", 0, code) + } + + if diff := cmp.Diff(expected, actual); len(diff) > 0 { + t.Errorf("unexpected output\n\nexpected:\n%s\nactual:\n%s\ndiff:\n%s", expected, actual, diff) + } +} + +// This test takes around 10 seconds to complete, as we're testing the progress +// updates that are printed every 2 seconds. Sorry! +func TestTest_LongRunningTestJSON(t *testing.T) { + td := t.TempDir() + testCopyDir(t, testFixturePath(path.Join("test", "long_running")), td) + defer testChdir(t, td)() + + provider := testing_command.NewProvider(nil) + view, done := testView(t) + + c := &TestCommand{ + Meta: Meta{ + testingOverrides: metaOverridesForProvider(provider.Provider), + View: view, + }, + } + + code := c.Run([]string{"-json"}) + output := done(t) + + if code != 0 { + t.Errorf("expected status code 0 but got %d", code) + } + + actual := output.All() + var messages []string + for ix, line := range strings.Split(actual, "\n") { + if len(line) == 0 { + // Skip empty lines. + continue + } + + if ix == 0 { + // skip the first one, it's version information + continue + } + + var obj map[string]interface{} + + if err := json.Unmarshal([]byte(line), &obj); err != nil { + t.Errorf("failed to unmarshal returned line: %s", line) + continue + } + + // Remove the timestamp as it changes every time. + delete(obj, "@timestamp") + + if obj["type"].(string) == "test_run" { + // Then we need to delete the `elapsed` field from within the run + // as it'll cause flaky tests. + + run := obj["test_run"].(map[string]interface{}) + if run["progress"].(string) != "complete" { + delete(run, "elapsed") + } + } + + message, err := json.Marshal(obj) + if err != nil { + t.Errorf("failed to remarshal returned line: %s", line) + continue + } + + messages = append(messages, string(message)) + } + + expected := []string{ + `{"@level":"info","@message":"Found 1 file and 1 run block","@module":"terraform.ui","test_abstract":{"main.tftest.hcl":["test"]},"type":"test_abstract"}`, + `{"@level":"info","@message":"main.tftest.hcl... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","test_file":{"path":"main.tftest.hcl","progress":"starting"},"type":"test_file"}`, + `{"@level":"info","@message":" \"test\"... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"test","test_run":{"path":"main.tftest.hcl","progress":"starting","run":"test"},"type":"test_run"}`, + `{"@level":"info","@message":" \"test\"... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"test","test_run":{"path":"main.tftest.hcl","progress":"running","run":"test"},"type":"test_run"}`, + `{"@level":"info","@message":" \"test\"... in progress","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"test","test_run":{"path":"main.tftest.hcl","progress":"running","run":"test"},"type":"test_run"}`, + `{"@level":"info","@message":" \"test\"... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"test","test_run":{"path":"main.tftest.hcl","progress":"complete","run":"test","status":"pass"},"type":"test_run"}`, + `{"@level":"info","@message":"main.tftest.hcl... tearing down","@module":"terraform.ui","@testfile":"main.tftest.hcl","test_file":{"path":"main.tftest.hcl","progress":"teardown"},"type":"test_file"}`, + `{"@level":"info","@message":" \"test\"... tearing down","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"test","test_run":{"path":"main.tftest.hcl","progress":"teardown","run":"test"},"type":"test_run"}`, + `{"@level":"info","@message":" \"test\"... tearing down","@module":"terraform.ui","@testfile":"main.tftest.hcl","@testrun":"test","test_run":{"path":"main.tftest.hcl","progress":"teardown","run":"test"},"type":"test_run"}`, + `{"@level":"info","@message":"main.tftest.hcl... pass","@module":"terraform.ui","@testfile":"main.tftest.hcl","test_file":{"path":"main.tftest.hcl","progress":"complete","status":"pass"},"type":"test_file"}`, + `{"@level":"info","@message":"Success! 1 passed, 0 failed.","@module":"terraform.ui","test_summary":{"errored":0,"failed":0,"passed":1,"skipped":0,"status":"pass"},"type":"test_summary"}`, + } + + if code != 0 { + t.Errorf("expected return code %d but got %d", 0, code) + } + + if diff := cmp.Diff(expected, messages); len(diff) > 0 { + t.Errorf("unexpected output\n\nexpected:\n%s\nactual:\n%s\ndiff:\n%s", strings.Join(expected, "\n"), strings.Join(messages, "\n"), diff) + } +} diff --git a/internal/command/testdata/test/long_running/main.tf b/internal/command/testdata/test/long_running/main.tf new file mode 100644 index 0000000000..3613cbd124 --- /dev/null +++ b/internal/command/testdata/test/long_running/main.tf @@ -0,0 +1,4 @@ +resource "test_resource" "foo" { + create_wait_seconds = 5 + destroy_wait_seconds = 3 +} diff --git a/internal/command/testdata/test/long_running/main.tftest.hcl b/internal/command/testdata/test/long_running/main.tftest.hcl new file mode 100644 index 0000000000..d3995cae55 --- /dev/null +++ b/internal/command/testdata/test/long_running/main.tftest.hcl @@ -0,0 +1,2 @@ + +run "test" {} diff --git a/internal/command/testing/test_provider.go b/internal/command/testing/test_provider.go index 3d14cd2dab..934b6d3bc7 100644 --- a/internal/command/testing/test_provider.go +++ b/internal/command/testing/test_provider.go @@ -33,10 +33,12 @@ var ( "test_resource": { Block: &configschema.Block{ Attributes: map[string]*configschema.Attribute{ - "id": {Type: cty.String, Optional: true, Computed: true}, - "value": {Type: cty.String, Optional: true}, - "interrupt_count": {Type: cty.Number, Optional: true}, - "destroy_fail": {Type: cty.Bool, Optional: true, Computed: true}, + "id": {Type: cty.String, Optional: true, Computed: true}, + "value": {Type: cty.String, Optional: true}, + "interrupt_count": {Type: cty.Number, Optional: true}, + "destroy_fail": {Type: cty.Bool, Optional: true, Computed: true}, + "create_wait_seconds": {Type: cty.Number, Optional: true}, + "destroy_wait_seconds": {Type: cty.Number, Optional: true}, }, }, }, @@ -45,10 +47,18 @@ var ( "test_data_source": { Block: &configschema.Block{ Attributes: map[string]*configschema.Attribute{ - "id": {Type: cty.String, Required: true}, - "value": {Type: cty.String, Computed: true}, - "interrupt_count": {Type: cty.Number, Computed: true}, - "destroy_fail": {Type: cty.Bool, Computed: true}, + "id": {Type: cty.String, Required: true}, + "value": {Type: cty.String, Computed: true}, + + // We never actually reference these values from a data + // source, but we have tests that use the same cty.Value + // to represent a test_resource and a test_data_source + // so the schemas have to match. + + "interrupt_count": {Type: cty.Number, Computed: true}, + "destroy_fail": {Type: cty.Bool, Computed: true}, + "create_wait_seconds": {Type: cty.Number, Computed: true}, + "destroy_wait_seconds": {Type: cty.Number, Computed: true}, }, }, }, @@ -218,6 +228,11 @@ func (provider *TestProvider) ApplyResourceChange(request providers.ApplyResourc } } + if wait := request.PriorState.GetAttr("destroy_wait_seconds"); !wait.IsNull() && wait.IsKnown() { + waitTime, _ := wait.AsBigFloat().Int64() + time.Sleep(time.Second * time.Duration(waitTime)) + } + provider.Store.Delete(provider.GetResourceKey(request.PriorState.GetAttr("id").AsString())) return providers.ApplyResourceChangeResponse{ NewState: request.PlannedState, @@ -251,6 +266,11 @@ func (provider *TestProvider) ApplyResourceChange(request providers.ApplyResourc time.Sleep(time.Second) } + if wait := resource.GetAttr("create_wait_seconds"); !wait.IsNull() && wait.IsKnown() { + waitTime, _ := wait.AsBigFloat().Int64() + time.Sleep(time.Second * time.Duration(waitTime)) + } + if destroyFail := resource.GetAttr("destroy_fail"); !destroyFail.IsKnown() { vals := resource.AsValueMap() vals["destroy_fail"] = cty.False diff --git a/internal/command/views/json/test.go b/internal/command/views/json/test.go index 794bd6158a..1afe4e4c05 100644 --- a/internal/command/views/json/test.go +++ b/internal/command/views/json/test.go @@ -22,9 +22,11 @@ type TestFileStatus struct { } type TestRunStatus struct { - Path string `json:"path"` - Run string `json:"run"` - Status TestStatus `json:"status"` + Path string `json:"path"` + Run string `json:"run"` + Progress TestProgress `json:"progress"` + Elapsed *int64 `json:"elapsed,omitempty"` + Status TestStatus `json:"status,omitempty"` } type TestSuiteSummary struct { diff --git a/internal/command/views/test.go b/internal/command/views/test.go index 1c26e2bdda..cf970992f5 100644 --- a/internal/command/views/test.go +++ b/internal/command/views/test.go @@ -45,7 +45,7 @@ type Test interface { File(file *moduletest.File, progress moduletest.Progress) // Run prints out the summary for a single test run block. - Run(run *moduletest.Run, file *moduletest.File) + Run(run *moduletest.Run, file *moduletest.File, progress moduletest.Progress, elapsed int64) // DestroySummary prints out the summary of the destroy step of each test // file. If everything goes well, this should be empty. @@ -145,7 +145,7 @@ func (t *TestHuman) Conclusion(suite *moduletest.Suite) { func (t *TestHuman) File(file *moduletest.File, progress moduletest.Progress) { switch progress { - case moduletest.Starting: + case moduletest.Starting, moduletest.Running: t.view.streams.Printf(t.view.colorize.Color("%s... [light_gray]in progress[reset]\n"), file.Name) case moduletest.TearDown: t.view.streams.Printf(t.view.colorize.Color("%s... [light_gray]tearing down[reset]\n"), file.Name) @@ -157,7 +157,16 @@ func (t *TestHuman) File(file *moduletest.File, progress moduletest.Progress) { } } -func (t *TestHuman) Run(run *moduletest.Run, file *moduletest.File) { +func (t *TestHuman) Run(run *moduletest.Run, file *moduletest.File, progress moduletest.Progress, _ int64) { + switch progress { + case moduletest.Starting, moduletest.Running, moduletest.TearDown: + return // We don't print progress updates in human mode + case moduletest.Complete: + // Do nothing, the rest of the function handles this. + default: + panic("unrecognized test progress: " + progress.String()) + } + t.view.streams.Printf(" run %q... %s\n", run.Name, colorizeTestStatus(run.Status, t.view.colorize)) if run.Verbose != nil { @@ -449,7 +458,7 @@ func (t *TestJSON) Conclusion(suite *moduletest.Suite) { func (t *TestJSON) File(file *moduletest.File, progress moduletest.Progress) { switch progress { - case moduletest.Starting: + case moduletest.Starting, moduletest.Running: t.view.log.Info( fmt.Sprintf("%s... in progress", file.Name), "type", json.MessageTestFile, @@ -483,11 +492,48 @@ func (t *TestJSON) File(file *moduletest.File, progress moduletest.Progress) { } } -func (t *TestJSON) Run(run *moduletest.Run, file *moduletest.File) { +func (t *TestJSON) Run(run *moduletest.Run, file *moduletest.File, progress moduletest.Progress, elapsed int64) { + switch progress { + case moduletest.Starting, moduletest.Running: + t.view.log.Info( + fmt.Sprintf(" %q... in progress", run.Name), + "type", json.MessageTestRun, + json.MessageTestRun, json.TestRunStatus{ + Path: file.Name, + Run: run.Name, + Progress: json.ToTestProgress(progress), + Elapsed: &elapsed, + }, + "@testfile", file.Name, + "@testrun", run.Name) + return + case moduletest.TearDown: + t.view.log.Info( + fmt.Sprintf(" %q... tearing down", run.Name), + "type", json.MessageTestRun, + json.MessageTestRun, json.TestRunStatus{ + Path: file.Name, + Run: run.Name, + Progress: json.ToTestProgress(progress), + Elapsed: &elapsed, + }, + "@testfile", file.Name, + "@testrun", run.Name) + return + case moduletest.Complete: + // Do nothing, the rest of the function handles this case. + default: + panic("unrecognized test progress: " + progress.String()) + } + t.view.log.Info( fmt.Sprintf(" %q... %s", run.Name, testStatus(run.Status)), "type", json.MessageTestRun, - json.MessageTestRun, json.TestRunStatus{file.Name, run.Name, json.ToTestStatus(run.Status)}, + json.MessageTestRun, json.TestRunStatus{ + Path: file.Name, + Run: run.Name, + Progress: json.ToTestProgress(progress), + Status: json.ToTestStatus(run.Status)}, "@testfile", file.Name, "@testrun", run.Name) diff --git a/internal/command/views/test_test.go b/internal/command/views/test_test.go index e737e14fb6..c107e6e126 100644 --- a/internal/command/views/test_test.go +++ b/internal/command/views/test_test.go @@ -474,13 +474,15 @@ func TestTestHuman_File(t *testing.T) { func TestTestHuman_Run(t *testing.T) { tcs := map[string]struct { - Run *moduletest.Run - StdOut string - StdErr string + Run *moduletest.Run + Progress moduletest.Progress + StdOut string + StdErr string }{ "pass": { - Run: &moduletest.Run{Name: "run_block", Status: moduletest.Pass}, - StdOut: " run \"run_block\"... pass\n", + Run: &moduletest.Run{Name: "run_block", Status: moduletest.Pass}, + Progress: moduletest.Complete, + StdOut: " run \"run_block\"... pass\n", }, "pass_with_diags": { @@ -489,6 +491,7 @@ func TestTestHuman_Run(t *testing.T) { Status: moduletest.Pass, Diagnostics: tfdiags.Diagnostics{tfdiags.Sourceless(tfdiags.Warning, "a warning occurred", "some warning happened during this test")}, }, + Progress: moduletest.Complete, StdOut: ` run "run_block"... pass Warning: a warning occurred @@ -499,18 +502,21 @@ some warning happened during this test }, "pending": { - Run: &moduletest.Run{Name: "run_block", Status: moduletest.Pending}, - StdOut: " run \"run_block\"... pending\n", + Run: &moduletest.Run{Name: "run_block", Status: moduletest.Pending}, + Progress: moduletest.Complete, + StdOut: " run \"run_block\"... pending\n", }, "skip": { - Run: &moduletest.Run{Name: "run_block", Status: moduletest.Skip}, - StdOut: " run \"run_block\"... skip\n", + Run: &moduletest.Run{Name: "run_block", Status: moduletest.Skip}, + Progress: moduletest.Complete, + StdOut: " run \"run_block\"... skip\n", }, "fail": { - Run: &moduletest.Run{Name: "run_block", Status: moduletest.Fail}, - StdOut: " run \"run_block\"... fail\n", + Run: &moduletest.Run{Name: "run_block", Status: moduletest.Fail}, + Progress: moduletest.Complete, + StdOut: " run \"run_block\"... fail\n", }, "fail_with_diags": { @@ -522,7 +528,8 @@ some warning happened during this test tfdiags.Sourceless(tfdiags.Error, "a second comparison failed", "other details"), }, }, - StdOut: " run \"run_block\"... fail\n", + Progress: moduletest.Complete, + StdOut: " run \"run_block\"... fail\n", StdErr: ` Error: a comparison failed @@ -535,8 +542,9 @@ other details }, "error": { - Run: &moduletest.Run{Name: "run_block", Status: moduletest.Error}, - StdOut: " run \"run_block\"... fail\n", + Run: &moduletest.Run{Name: "run_block", Status: moduletest.Error}, + Progress: moduletest.Complete, + StdOut: " run \"run_block\"... fail\n", }, "error_with_diags": { @@ -545,7 +553,8 @@ other details Status: moduletest.Error, Diagnostics: tfdiags.Diagnostics{tfdiags.Sourceless(tfdiags.Error, "an error occurred", "something bad happened during this test")}, }, - StdOut: " run \"run_block\"... fail\n", + Progress: moduletest.Complete, + StdOut: " run \"run_block\"... fail\n", StdErr: ` Error: an error occurred @@ -630,6 +639,7 @@ something bad happened during this test }, }, }, + Progress: moduletest.Complete, StdOut: ` run "run_block"... pass Terraform used the selected providers to generate the following execution @@ -702,6 +712,7 @@ Plan: 1 to add, 0 to change, 0 to destroy. }, }, }, + Progress: moduletest.Complete, StdOut: ` run "run_block"... pass # test_resource.creating: @@ -711,6 +722,20 @@ resource "test_resource" "creating" { `, }, + // These next three tests should print nothing, as we only report on + // progress complete. + "progress_starting": { + Run: &moduletest.Run{Name: "run_block", Status: moduletest.Pass}, + Progress: moduletest.Starting, + }, + "progress_running": { + Run: &moduletest.Run{Name: "run_block", Status: moduletest.Pass}, + Progress: moduletest.Running, + }, + "progress_teardown": { + Run: &moduletest.Run{Name: "run_block", Status: moduletest.Pass}, + Progress: moduletest.TearDown, + }, } for name, tc := range tcs { t.Run(name, func(t *testing.T) { @@ -721,7 +746,7 @@ resource "test_resource" "creating" { streams, done := terminal.StreamsForTesting(t) view := NewTest(arguments.ViewHuman, NewView(streams)) - view.Run(tc.Run, file) + view.Run(tc.Run, file, tc.Progress, 0) output := done(t) actual, expected := output.Stdout(), tc.StdOut @@ -2349,11 +2374,78 @@ func TestTestJSON_File(t *testing.T) { func TestTestJSON_Run(t *testing.T) { tcs := map[string]struct { - run *moduletest.Run - want []map[string]interface{} + run *moduletest.Run + progress moduletest.Progress + elapsed int64 + want []map[string]interface{} }{ + "starting": { + run: &moduletest.Run{Name: "run_block", Status: moduletest.Pass}, + progress: moduletest.Starting, + want: []map[string]interface{}{ + { + "@level": "info", + "@message": " \"run_block\"... in progress", + "@module": "terraform.ui", + "@testfile": "main.tftest.hcl", + "@testrun": "run_block", + "test_run": map[string]interface{}{ + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "starting", + "elapsed": float64(0), + }, + "type": "test_run", + }, + }, + }, + + "running": { + run: &moduletest.Run{Name: "run_block", Status: moduletest.Pass}, + progress: moduletest.Running, + elapsed: 2024, + want: []map[string]interface{}{ + { + "@level": "info", + "@message": " \"run_block\"... in progress", + "@module": "terraform.ui", + "@testfile": "main.tftest.hcl", + "@testrun": "run_block", + "test_run": map[string]interface{}{ + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "running", + "elapsed": float64(2024), + }, + "type": "test_run", + }, + }, + }, + + "teardown": { + run: &moduletest.Run{Name: "run_block", Status: moduletest.Pass}, + progress: moduletest.TearDown, + want: []map[string]interface{}{ + { + "@level": "info", + "@message": " \"run_block\"... tearing down", + "@module": "terraform.ui", + "@testfile": "main.tftest.hcl", + "@testrun": "run_block", + "test_run": map[string]interface{}{ + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "teardown", + "elapsed": float64(0), + }, + "type": "test_run", + }, + }, + }, + "pass": { - run: &moduletest.Run{Name: "run_block", Status: moduletest.Pass}, + run: &moduletest.Run{Name: "run_block", Status: moduletest.Pass}, + progress: moduletest.Complete, want: []map[string]interface{}{ { "@level": "info", @@ -2362,9 +2454,10 @@ func TestTestJSON_Run(t *testing.T) { "@testfile": "main.tftest.hcl", "@testrun": "run_block", "test_run": map[string]interface{}{ - "path": "main.tftest.hcl", - "run": "run_block", - "status": "pass", + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "complete", + "status": "pass", }, "type": "test_run", }, @@ -2377,6 +2470,7 @@ func TestTestJSON_Run(t *testing.T) { Status: moduletest.Pass, Diagnostics: tfdiags.Diagnostics{tfdiags.Sourceless(tfdiags.Warning, "a warning occurred", "some warning happened during this test")}, }, + progress: moduletest.Complete, want: []map[string]interface{}{ { "@level": "info", @@ -2385,9 +2479,10 @@ func TestTestJSON_Run(t *testing.T) { "@testfile": "main.tftest.hcl", "@testrun": "run_block", "test_run": map[string]interface{}{ - "path": "main.tftest.hcl", - "run": "run_block", - "status": "pass", + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "complete", + "status": "pass", }, "type": "test_run", }, @@ -2408,7 +2503,8 @@ func TestTestJSON_Run(t *testing.T) { }, "pending": { - run: &moduletest.Run{Name: "run_block", Status: moduletest.Pending}, + run: &moduletest.Run{Name: "run_block", Status: moduletest.Pending}, + progress: moduletest.Complete, want: []map[string]interface{}{ { "@level": "info", @@ -2417,9 +2513,10 @@ func TestTestJSON_Run(t *testing.T) { "@testfile": "main.tftest.hcl", "@testrun": "run_block", "test_run": map[string]interface{}{ - "path": "main.tftest.hcl", - "run": "run_block", - "status": "pending", + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "complete", + "status": "pending", }, "type": "test_run", }, @@ -2427,7 +2524,8 @@ func TestTestJSON_Run(t *testing.T) { }, "skip": { - run: &moduletest.Run{Name: "run_block", Status: moduletest.Skip}, + run: &moduletest.Run{Name: "run_block", Status: moduletest.Skip}, + progress: moduletest.Complete, want: []map[string]interface{}{ { "@level": "info", @@ -2436,9 +2534,10 @@ func TestTestJSON_Run(t *testing.T) { "@testfile": "main.tftest.hcl", "@testrun": "run_block", "test_run": map[string]interface{}{ - "path": "main.tftest.hcl", - "run": "run_block", - "status": "skip", + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "complete", + "status": "skip", }, "type": "test_run", }, @@ -2446,7 +2545,8 @@ func TestTestJSON_Run(t *testing.T) { }, "fail": { - run: &moduletest.Run{Name: "run_block", Status: moduletest.Fail}, + run: &moduletest.Run{Name: "run_block", Status: moduletest.Fail}, + progress: moduletest.Complete, want: []map[string]interface{}{ { "@level": "info", @@ -2455,9 +2555,10 @@ func TestTestJSON_Run(t *testing.T) { "@testfile": "main.tftest.hcl", "@testrun": "run_block", "test_run": map[string]interface{}{ - "path": "main.tftest.hcl", - "run": "run_block", - "status": "fail", + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "complete", + "status": "fail", }, "type": "test_run", }, @@ -2473,6 +2574,7 @@ func TestTestJSON_Run(t *testing.T) { tfdiags.Sourceless(tfdiags.Error, "a second comparison failed", "other details"), }, }, + progress: moduletest.Complete, want: []map[string]interface{}{ { "@level": "info", @@ -2481,9 +2583,10 @@ func TestTestJSON_Run(t *testing.T) { "@testfile": "main.tftest.hcl", "@testrun": "run_block", "test_run": map[string]interface{}{ - "path": "main.tftest.hcl", - "run": "run_block", - "status": "fail", + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "complete", + "status": "fail", }, "type": "test_run", }, @@ -2517,7 +2620,8 @@ func TestTestJSON_Run(t *testing.T) { }, "error": { - run: &moduletest.Run{Name: "run_block", Status: moduletest.Error}, + run: &moduletest.Run{Name: "run_block", Status: moduletest.Error}, + progress: moduletest.Complete, want: []map[string]interface{}{ { "@level": "info", @@ -2526,9 +2630,10 @@ func TestTestJSON_Run(t *testing.T) { "@testfile": "main.tftest.hcl", "@testrun": "run_block", "test_run": map[string]interface{}{ - "path": "main.tftest.hcl", - "run": "run_block", - "status": "error", + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "complete", + "status": "error", }, "type": "test_run", }, @@ -2541,6 +2646,7 @@ func TestTestJSON_Run(t *testing.T) { Status: moduletest.Error, Diagnostics: tfdiags.Diagnostics{tfdiags.Sourceless(tfdiags.Error, "an error occurred", "something bad happened during this test")}, }, + progress: moduletest.Complete, want: []map[string]interface{}{ { "@level": "info", @@ -2549,9 +2655,10 @@ func TestTestJSON_Run(t *testing.T) { "@testfile": "main.tftest.hcl", "@testrun": "run_block", "test_run": map[string]interface{}{ - "path": "main.tftest.hcl", - "run": "run_block", - "status": "error", + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "complete", + "status": "error", }, "type": "test_run", }, @@ -2653,6 +2760,7 @@ func TestTestJSON_Run(t *testing.T) { }, }, }, + progress: moduletest.Complete, want: []map[string]interface{}{ { "@level": "info", @@ -2661,9 +2769,10 @@ func TestTestJSON_Run(t *testing.T) { "@testfile": "main.tftest.hcl", "@testrun": "run_block", "test_run": map[string]interface{}{ - "path": "main.tftest.hcl", - "run": "run_block", - "status": "pass", + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "complete", + "status": "pass", }, "type": "test_run", }, @@ -2721,6 +2830,7 @@ func TestTestJSON_Run(t *testing.T) { }, }, }, + "verbose_apply": { run: &moduletest.Run{ Name: "run_block", @@ -2778,6 +2888,7 @@ func TestTestJSON_Run(t *testing.T) { }, }, }, + progress: moduletest.Complete, want: []map[string]interface{}{ { "@level": "info", @@ -2786,9 +2897,10 @@ func TestTestJSON_Run(t *testing.T) { "@testfile": "main.tftest.hcl", "@testrun": "run_block", "test_run": map[string]interface{}{ - "path": "main.tftest.hcl", - "run": "run_block", - "status": "pass", + "path": "main.tftest.hcl", + "run": "run_block", + "progress": "complete", + "status": "pass", }, "type": "test_run", }, @@ -2851,7 +2963,7 @@ func TestTestJSON_Run(t *testing.T) { file := &moduletest.File{Name: "main.tftest.hcl"} - view.Run(tc.run, file) + view.Run(tc.run, file, tc.progress, tc.elapsed) testJSONViewOutputEquals(t, done(t).All(), tc.want, cmp.FilterPath(func(path cmp.Path) bool { return strings.Contains(path.Last().String(), "version") || strings.Contains(path.Last().String(), "timestamp") }, cmp.Ignore())) diff --git a/internal/moduletest/progress.go b/internal/moduletest/progress.go index 98da39ceb2..b5172dbde9 100644 --- a/internal/moduletest/progress.go +++ b/internal/moduletest/progress.go @@ -13,6 +13,7 @@ type Progress int const ( Starting Progress = iota + Running TearDown Complete ) diff --git a/internal/moduletest/progress_string.go b/internal/moduletest/progress_string.go index 7764621e35..3fef101f70 100644 --- a/internal/moduletest/progress_string.go +++ b/internal/moduletest/progress_string.go @@ -9,13 +9,14 @@ func _() { // Re-run the stringer command to generate them again. var x [1]struct{} _ = x[Starting-0] - _ = x[TearDown-1] - _ = x[Complete-2] + _ = x[Running-1] + _ = x[TearDown-2] + _ = x[Complete-3] } -const _Progress_name = "StartingTearDownComplete" +const _Progress_name = "StartingRunningTearDownComplete" -var _Progress_index = [...]uint8{0, 8, 16, 24} +var _Progress_index = [...]uint8{0, 8, 15, 23, 31} func (i Progress) String() string { if i < 0 || i >= Progress(len(_Progress_index)-1) { diff --git a/website/docs/internals/machine-readable-ui.mdx b/website/docs/internals/machine-readable-ui.mdx index d5b040e667..d691a76701 100644 --- a/website/docs/internals/machine-readable-ui.mdx +++ b/website/docs/internals/machine-readable-ui.mdx @@ -635,7 +635,7 @@ The `terraform test` command emits a `test_abstract` message describing the test ## Test File -After Terraform completes execution of each test file, `terraform test` emits a `test_file` message with the status of the test file. +Throughout a `terraform test` execution, Terraform will produce several progress updates for each test file. The progress field can be `starting`, `teardown`, or `complete`. Each test file will emit each progress update exactly once. When a test file emits the `complete` progress update, it will also include a status field containing one of `pass`, `error`, `fail`, or `skip` denoting the overall status of the completed test file. ### Example @@ -648,6 +648,7 @@ After Terraform completes execution of each test file, `terraform test` emits a "@timestamp": "2023-08-09T16:12:30.724368+02:00", "test_file": { "path": "validation.tftest.hcl", + "progress": "complete", "status": "pass" }, "type": "test_file" @@ -656,9 +657,15 @@ After Terraform completes execution of each test file, `terraform test` emits a ## Test Run -After Terraform completes execution of each test file, `terraform test` emits a series of `test_run` messages with each run block's status within the test file. +While executing `run` blocks within a test file, Terraform will also produce several status updates for each `run` block. The progress field for a `run` block progress update can be `starting`, `running`, `teardown`, and `complete`. The `starting` and `complete` progress updates will be emitted exactly once. While the `running` and `teardown` progress updates can be emitted multiple times. -### Example +The `starting`, `running` and `teardown` updates will also include an `elapsed` field indicating the number of milliseconds the current test operation (for `starting` and `running`) or the current destroy operation (for `teardown`) has been in progress. + +The `complete` progress update will also include a `status` field containing one of `pass`, `error`, `fail`, or `skip` denoting the overall status of the completed `run` block`. + +Not every `run` block will emit `teardown` progress updates, as only the most recently executed `run` blocks reference the latest in-memory state files that need to be torn down. In addition, the `run` block tear down process is only initiated once the overall test file has already emitted its `teardown` status update. This means you can expect the `complete` progress update to be issued for a `run` block before any `teardown` updates are provided. There will always be a `complete` progress update issued by the enclosing test file when the tear down process for all `run` blocks is complete. + +### Examples ```json { @@ -671,12 +678,31 @@ After Terraform completes execution of each test file, `terraform test` emits a "test_run": { "path": "main.tftest.hcl", "run": "successful_validation", + "progress": "complete", "status": "pass" }, "type": "test_run" } ``` +```json +{ + "@level": "info", + "@message": " \"successful_validation\"... in progress", + "@module": "terraform.ui", + "@testfile": "validation.tftest.hcl", + "@testrun": "successful_validation", + "@timestamp": "2023-08-09T16:12:30.724407+02:00", + "test_run": { + "path": "main.tftest.hcl", + "run": "successful_validation", + "progress": "running", + "elapsed": 2024 + }, + "type": "test_run" +} +``` + ## Test Cleanup After Terraform completes the execution of each test file, `terraform test` may emit a series of `test_cleanup` messages detailing any state it could not destroy. You must locate and destroy the resources listed in these resources manually.