TestJSONHook_create fails for 1.6.6

[hashworks]

Terraform Version

1.6.6

Terraform Configuration Files

None, test fails

Debug Output

--- FAIL: TestJSONHook_create (0.01s)
    hook_json_test.go:184: unexpected output on line 4:
          map[string]any{
          	"@level": string("info"),
          	"@message": strings.Join({
          		"test_instance.boop: Still creating... [",
        - 		"1",
        + 		"2",
          		"0s elapsed]",
          	}, ""),
          	"@module": string("terraform.ui"),
          	"hook": map[string]any{
          		"action":          string("create"),
        - 		"elapsed_seconds": float64(10),
        + 		"elapsed_seconds": float64(20),
          		"resource":        map[string]any{"addr": string("test_instance.boop"), "implied_provider": string("test"), "module": string(""), "resource": string("test_instance.boop"), ...},
          	},
          	"type": string("apply_progress"),
          }
FAIL

Expected Behavior

All tests are green.

Actual Behavior

Test TestJSONHook_create fails.

Steps to Reproduce

git checkout v1.6.6
go mod download
go build
go test -mod=readonly ./...

Additional Context

Golang version 1.21.5.

I'm the maintainer of the Arch Linux terraform package, this blocks the 1.6.6 release.

References

No response

[jbardin]

Hi @hashworks,

Thanks for filing the issue! That failure is unrelated to anything in the v1.6.6 release, and only due to a flaky or overly time-sensitive test fixture. The test is attempting to accurately record the output of a concurrent process over time, and if that concurrent process is slowed slightly due to runtime scheduling delays, which would usually because of being run on a more resource constrained system, the output won't exactly align any longer.

While it's something we'll want to look into to make more robust, because a fix would not change any functional code it's probably not going to warrant another patch release.

[kmoe]

The output indicates that the following message is being emitted twice:

		{
			"@level":   "info",
			"@message": "test_instance.boop: Still creating... [10s elapsed]",
			"@module":  "terraform.ui",
			"type":     "apply_progress",
			"hook": map[string]interface{}{
				"action":          string("create"),
				"elapsed_seconds": float64(10),
				"resource":        wantResource,
			},
		},

so perhaps during the second "time jump" on line 73, the progress goroutine is not actually advancing.

Works fine on a well-resourced Linux 6.6.3-arch1-1. Curious as to how resource-constrained the build machine is to cause this. Please post the spec so this can be reproduced.

[crw]

I changed this to enhancement since it seems to be more about optimizing this test to run in a resource-constrained environment which, while a reasonable thing to do, does not reflect a bug in the actual product or even in the test suite as it is run by the official build process. If this is in error, please let me know.

[jbardin]

The test relies on waiting for the goroutine to do its operation. Since time.Sleep is never a proper synchronization primitive, that delay always has the chance of failure. If the heartbeat goroutine is delayed slightly more than the sleep, the output will be recorded at the wrong time. Sleeping for 1500 microseconds after the first channel operation in the heartbeat goroutine will cause the exact output shown above.

Unfortunately testing this type of asynchronous UI code is always quite awkward, and settling for time.Sleep is a trade-off in convenience vs adding even more test hooks and complexity to make the tests resilient to timing issues. There may be some way to catch the heartbeat output to step the test without a sleep, or we will have to add another test hook to do so.

[varshneydevansh]

What I am able to understand, can we use sync.WaitGroup or maybe an action-based synchronization logic?

https://github.com/hashicorp/terraform/blob/039cced8aec491d2f6bbcc20b1d47e82cdf70686/internal/command/views/hook_json_test.go#L148

I would love to work on this, I took a pause for a while from open-source. =)

[kmoe]

A unit test run on GHA ended up reproducing this: https://github.com/hashicorp/terraform/actions/runs/7276612377/job/19826811164?pr=34432

[varshneydevansh]

A unit test run on GHA ended up reproducing this: https://github.com/hashicorp/terraform/actions/runs/7276612377/job/19826811164?pr=34432

So there's a mismatch between the expected and actual output values for the elapsed time for the 10s and the 20s? Am I right?

[hashworks]

Curious as to how resource-constrained the build machine is to cause this. Please post the spec so this can be reproduced.

@kmoe The build machine is not resource constrained (5800X, 64GB RAM), it might be related to the Arch Linux Build System that was used. You can find the respective PKGBUILD here.

On an Arch Linux system:

pacman -Syu git devtools
git clone https://gitlab.archlinux.org/archlinux/packaging/packages/terraform
cd terraform/
sed -i '/-skip TestJSONHook_create/d' PKGBUILD
extra-x86_64-build

EDIT: Huh, can't reproduce this anymore. It could be that I was building multiple things at the time I ran into this.

[usmanovbf]

Hi there! is it still actual?

[hashworks]

I wasn't able to reproduce this, so I'll remove it from the test exclusion in the Arch Linux PKGBUILD and close this. I'll reopen it if I run into it again.

[github-actions[bot]]

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