diff --git a/internal/command/views/hook_json_test.go b/internal/command/views/hook_json_test.go index 3da407cf3a..fc6ec8c8a6 100644 --- a/internal/command/views/hook_json_test.go +++ b/internal/command/views/hook_json_test.go @@ -6,9 +6,9 @@ package views import ( "errors" "fmt" - "strings" "sync" "testing" + "testing/synctest" "time" "github.com/zclconf/go-cty/cty" @@ -415,110 +415,107 @@ func TestJSONHook_EphemeralOp(t *testing.T) { } func TestJSONHook_EphemeralOp_progress(t *testing.T) { - streams, done := terminal.StreamsForTesting(t) - hook := newJSONHook(NewJSONView(NewView(streams))) - hook.periodicUiTimer = 1 * time.Second - - addr := addrs.Resource{ - Mode: addrs.ManagedResourceMode, - Type: "test_instance", - Name: "boop", - }.Instance(addrs.NoKey).Absolute(addrs.RootModuleInstance) - - action, err := hook.PreEphemeralOp(testJSONHookResourceID(addr), plans.Open) - testHookReturnValues(t, action, err) - - time.Sleep(2005 * time.Millisecond) - - action, err = hook.PostEphemeralOp(testJSONHookResourceID(addr), plans.Open, nil) - testHookReturnValues(t, action, err) - - want := []map[string]interface{}{ - { - "@level": "info", - "@message": "test_instance.boop: Opening...", - "@module": "terraform.ui", - "type": "ephemeral_op_start", - "hook": map[string]interface{}{ - "action": string("open"), - "resource": map[string]interface{}{ - "addr": string("test_instance.boop"), - "implied_provider": string("test"), - "module": string(""), - "resource": string("test_instance.boop"), - "resource_key": nil, - "resource_name": string("boop"), - "resource_type": string("test_instance"), + syncTest, streams, done := streamableSyncTest(t) + + syncTest(t, func(t *testing.T) { + start := time.Now() + hook := newJSONHook(NewJSONView(NewView(streams))) + hook.periodicUiTimer = 1 * time.Second + t.Log(time.Since(start)) + + addr := addrs.Resource{ + Mode: addrs.ManagedResourceMode, + Type: "test_instance", + Name: "boop", + }.Instance(addrs.NoKey).Absolute(addrs.RootModuleInstance) + + action, err := hook.PreEphemeralOp(testJSONHookResourceID(addr), plans.Open) + testHookReturnValues(t, action, err) + time.Sleep(2005 * time.Millisecond) + + action, err = hook.PostEphemeralOp(testJSONHookResourceID(addr), plans.Open, nil) + testHookReturnValues(t, action, err) + + want := []map[string]interface{}{ + { + "@level": "info", + "@message": "test_instance.boop: Opening...", + "@module": "terraform.ui", + "type": "ephemeral_op_start", + "hook": map[string]interface{}{ + "action": string("open"), + "resource": map[string]interface{}{ + "addr": string("test_instance.boop"), + "implied_provider": string("test"), + "module": string(""), + "resource": string("test_instance.boop"), + "resource_key": nil, + "resource_name": string("boop"), + "resource_type": string("test_instance"), + }, }, }, - }, - { - "@level": "info", - "@message": "test_instance.boop: Still opening... [1s elapsed]", - "@module": "terraform.ui", - "type": "ephemeral_op_progress", - "hook": map[string]interface{}{ - "action": string("open"), - "elapsed_seconds": float64(1), - "resource": map[string]interface{}{ - "addr": string("test_instance.boop"), - "implied_provider": string("test"), - "module": string(""), - "resource": string("test_instance.boop"), - "resource_key": nil, - "resource_name": string("boop"), - "resource_type": string("test_instance"), + { + "@level": "info", + "@message": "test_instance.boop: Still opening... [1s elapsed]", + "@module": "terraform.ui", + "type": "ephemeral_op_progress", + "hook": map[string]interface{}{ + "action": string("open"), + "elapsed_seconds": float64(1), + "resource": map[string]interface{}{ + "addr": string("test_instance.boop"), + "implied_provider": string("test"), + "module": string(""), + "resource": string("test_instance.boop"), + "resource_key": nil, + "resource_name": string("boop"), + "resource_type": string("test_instance"), + }, }, }, - }, - { - "@level": "info", - "@message": "test_instance.boop: Still opening... [2s elapsed]", - "@module": "terraform.ui", - "type": "ephemeral_op_progress", - "hook": map[string]interface{}{ - "action": string("open"), - "elapsed_seconds": float64(2), - "resource": map[string]interface{}{ - "addr": string("test_instance.boop"), - "implied_provider": string("test"), - "module": string(""), - "resource": string("test_instance.boop"), - "resource_key": nil, - "resource_name": string("boop"), - "resource_type": string("test_instance"), + { + "@level": "info", + "@message": "test_instance.boop: Still opening... [2s elapsed]", + "@module": "terraform.ui", + "type": "ephemeral_op_progress", + "hook": map[string]interface{}{ + "action": string("open"), + "elapsed_seconds": float64(2), + "resource": map[string]interface{}{ + "addr": string("test_instance.boop"), + "implied_provider": string("test"), + "module": string(""), + "resource": string("test_instance.boop"), + "resource_key": nil, + "resource_name": string("boop"), + "resource_type": string("test_instance"), + }, }, }, - }, - { - "@level": "info", - "@message": "test_instance.boop: Opening complete after 2s", - "@module": "terraform.ui", - "type": "ephemeral_op_complete", - "hook": map[string]interface{}{ - "action": string("open"), - "elapsed_seconds": float64(2), - "resource": map[string]interface{}{ - "addr": string("test_instance.boop"), - "implied_provider": string("test"), - "module": string(""), - "resource": string("test_instance.boop"), - "resource_key": nil, - "resource_name": string("boop"), - "resource_type": string("test_instance"), + { + "@level": "info", + "@message": "test_instance.boop: Opening complete after 2s", + "@module": "terraform.ui", + "type": "ephemeral_op_complete", + "hook": map[string]interface{}{ + "action": string("open"), + "elapsed_seconds": float64(2), + "resource": map[string]interface{}{ + "addr": string("test_instance.boop"), + "implied_provider": string("test"), + "module": string(""), + "resource": string("test_instance.boop"), + "resource_key": nil, + "resource_name": string("boop"), + "resource_type": string("test_instance"), + }, }, }, - }, - } - - stdout := done(t).Stdout() - - // time.Sleep can take longer than declared time - // so we only test the first lines we expect to see after sleeping - lines := strings.SplitN(stdout, "\n", 4) - firstLines := strings.Join(lines[:4], "\n") - - testJSONViewOutputEquals(t, firstLines, want) + } + stdout := done(t).Stdout() + testJSONViewOutputEquals(t, stdout, want) + }) } func TestJSONHook_EphemeralOp_error(t *testing.T) { @@ -821,3 +818,10 @@ func testHookReturnValues(t *testing.T, action terraform.HookAction, err error) t.Fatalf("Expected hook to continue, given: %#v", action) } } + +// streamableSyncTest is a helper to ensure that the long-running streaming goroutines are started outside of the synctest bubble. +// Otherwise, the sync bubble will be unable to advance time, and the main goroutine will become infinitely paused on any time.Sleep operation. +func streamableSyncTest(t *testing.T) (func(t *testing.T, f func(*testing.T)), *terminal.Streams, func(*testing.T) *terminal.TestOutput) { + streams, done := terminal.StreamsForTesting(t) + return synctest.Test, streams, done +} diff --git a/internal/command/views/hook_ui_test.go b/internal/command/views/hook_ui_test.go index 5241ff104b..57b06d74ea 100644 --- a/internal/command/views/hook_ui_test.go +++ b/internal/command/views/hook_ui_test.go @@ -93,66 +93,67 @@ func TestUiHookPreApply_create(t *testing.T) { // Test the PreApply hook's use of a periodic timer to display "still working" // log lines func TestUiHookPreApply_periodicTimer(t *testing.T) { - streams, done := terminal.StreamsForTesting(t) - view := NewView(streams) - h := NewUiHook(view) - h.periodicUiTimer = 1 * time.Second - h.resources = map[string]uiResourceState{ - "test_instance.foo": { - Op: uiResourceModify, - Start: time.Now(), - }, - } + syncTest, streams, done := streamableSyncTest(t) + syncTest(t, func(t *testing.T) { + view := NewView(streams) + h := NewUiHook(view) + h.periodicUiTimer = 1 * time.Second + h.resources = map[string]uiResourceState{ + "test_instance.foo": { + Op: uiResourceModify, + Start: time.Now(), + }, + } - addr := addrs.Resource{ - Mode: addrs.ManagedResourceMode, - Type: "test_instance", - Name: "foo", - }.Instance(addrs.NoKey).Absolute(addrs.RootModuleInstance) + addr := addrs.Resource{ + Mode: addrs.ManagedResourceMode, + Type: "test_instance", + Name: "foo", + }.Instance(addrs.NoKey).Absolute(addrs.RootModuleInstance) - priorState := cty.ObjectVal(map[string]cty.Value{ - "id": cty.StringVal("test"), - "bar": cty.ListValEmpty(cty.String), - }) - plannedNewState := cty.ObjectVal(map[string]cty.Value{ - "id": cty.StringVal("test"), - "bar": cty.ListVal([]cty.Value{ - cty.StringVal("baz"), - }), - }) + priorState := cty.ObjectVal(map[string]cty.Value{ + "id": cty.StringVal("test"), + "bar": cty.ListValEmpty(cty.String), + }) + plannedNewState := cty.ObjectVal(map[string]cty.Value{ + "id": cty.StringVal("test"), + "bar": cty.ListVal([]cty.Value{ + cty.StringVal("baz"), + }), + }) - action, err := h.PreApply(testUiHookResourceID(addr), addrs.NotDeposed, plans.Update, priorState, plannedNewState) - if err != nil { - t.Fatal(err) - } - if action != terraform.HookActionContinue { - t.Fatalf("Expected hook to continue, given: %#v", action) - } + action, err := h.PreApply(testUiHookResourceID(addr), addrs.NotDeposed, plans.Update, priorState, plannedNewState) + if err != nil { + t.Fatal(err) + } + if action != terraform.HookActionContinue { + t.Fatalf("Expected hook to continue, given: %#v", action) + } - time.Sleep(3005 * time.Millisecond) + time.Sleep(3005 * time.Millisecond) - // stop the background writer - uiState := h.resources[addr.String()] - close(uiState.DoneCh) - <-uiState.done + // stop the background writer + uiState := h.resources[addr.String()] + close(uiState.DoneCh) + <-uiState.done - expectedOutput := `test_instance.foo: Modifying... [id=test] + expectedOutput := `test_instance.foo: Modifying... [id=test] test_instance.foo: Still modifying... [id=test, 00m01s elapsed] test_instance.foo: Still modifying... [id=test, 00m02s elapsed] test_instance.foo: Still modifying... [id=test, 00m03s elapsed] ` - result := done(t) - output := result.Stdout() - // we do not test for equality because time.Sleep can take longer than declared time - if !strings.HasPrefix(output, expectedOutput) { - t.Fatalf("Output didn't match.\nExpected: %q\nGiven: %q", expectedOutput, output) - } - - expectedErrOutput := "" - errOutput := result.Stderr() - if errOutput != expectedErrOutput { - t.Fatalf("Error output didn't match.\nExpected: %q\nGiven: %q", expectedErrOutput, errOutput) - } + result := done(t) + output := result.Stdout() + if output != expectedOutput { + t.Fatalf("Output didn't match.\nExpected: %q\nGiven: %q", expectedOutput, output) + } + + expectedErrOutput := "" + errOutput := result.Stderr() + if errOutput != expectedErrOutput { + t.Fatalf("Error output didn't match.\nExpected: %q\nGiven: %q", expectedErrOutput, errOutput) + } + }) } // Test the PreApply hook's destroy path, including passing a deposed key as @@ -735,52 +736,54 @@ ephemeral.test_instance.foo: Closing complete after 0s } func TestUiHookEphemeralOp_progress(t *testing.T) { - streams, done := terminal.StreamsForTesting(t) - view := NewView(streams) - h := NewUiHook(view) - h.periodicUiTimer = 1 * time.Second - - addr := addrs.Resource{ - Mode: addrs.EphemeralResourceMode, - Type: "test_instance", - Name: "foo", - }.Instance(addrs.NoKey).Absolute(addrs.RootModuleInstance) - - action, err := h.PreEphemeralOp(testUiHookResourceID(addr), plans.Open) - if err != nil { - t.Fatal(err) - } - if action != terraform.HookActionContinue { - t.Fatalf("Expected hook to continue, given: %#v", action) - } - - start := time.Now() - time.Sleep(2005 * time.Millisecond) - elapsed := time.Since(start).Round(time.Second) - - action, err = h.PostEphemeralOp(testUiHookResourceID(addr), plans.Open, nil) - if err != nil { - t.Fatal(err) - } - if action != terraform.HookActionContinue { - t.Fatalf("Expected hook to continue, given: %#v", action) - } - - result := done(t) - stdout := result.Stdout() - - // we do not test for equality because time.Sleep can take longer than declared time - wantPrefix := `ephemeral.test_instance.foo: Opening... + syncTest, streams, done := streamableSyncTest(t) + syncTest(t, func(t *testing.T) { + view := NewView(streams) + h := NewUiHook(view) + h.periodicUiTimer = 1 * time.Second + + addr := addrs.Resource{ + Mode: addrs.EphemeralResourceMode, + Type: "test_instance", + Name: "foo", + }.Instance(addrs.NoKey).Absolute(addrs.RootModuleInstance) + + action, err := h.PreEphemeralOp(testUiHookResourceID(addr), plans.Open) + if err != nil { + t.Fatal(err) + } + if action != terraform.HookActionContinue { + t.Fatalf("Expected hook to continue, given: %#v", action) + } + + start := time.Now() + time.Sleep(2005 * time.Millisecond) + elapsed := time.Since(start).Round(time.Second) + + action, err = h.PostEphemeralOp(testUiHookResourceID(addr), plans.Open, nil) + if err != nil { + t.Fatal(err) + } + if action != terraform.HookActionContinue { + t.Fatalf("Expected hook to continue, given: %#v", action) + } + + result := done(t) + stdout := result.Stdout() + + // we do not test for equality because time.Sleep can take longer than declared time + wantPrefix := `ephemeral.test_instance.foo: Opening... ephemeral.test_instance.foo: Still opening... [00m01s elapsed] ephemeral.test_instance.foo: Still opening... [00m02s elapsed]` - if !strings.HasPrefix(stdout, wantPrefix) { - t.Fatalf("unexpected prefix\n got: %q\nwant: %q", stdout, wantPrefix) - } - wantSuffix := fmt.Sprintf(`ephemeral.test_instance.foo: Opening complete after %s + if !strings.HasPrefix(stdout, wantPrefix) { + t.Fatalf("unexpected prefix\n got: %q\nwant: %q", stdout, wantPrefix) + } + wantSuffix := fmt.Sprintf(`ephemeral.test_instance.foo: Opening complete after %s `, elapsed) - if !strings.HasSuffix(stdout, wantSuffix) { - t.Fatalf("unexpected prefix\n got: %q\nwant: %q", stdout, wantSuffix) - } + if !strings.HasSuffix(stdout, wantSuffix) { + t.Fatalf("unexpected prefix\n got: %q\nwant: %q", stdout, wantSuffix) + } + }) } func TestUiHookEphemeralOp_error(t *testing.T) {