plugin: Always forward tf6server close channel (#905)

Replicating the `tf5server` close channel handling right above it -- it was a copy-paste miss on my part. Without this, `tf6server` (such as terraform-plugin-framework providers) will hang until test timeouts.

As part of troubleshooting this, was able to add some helpful trace and debug logging for future travelers. Also, CI has been updated to run all terraform-provider-corner testing.

Author: bflad

.github/workflows/ci-go.yml

@@ -4,7 +4,7 @@ name: ci-go
 on:
   pull_request:
     paths:
-      - .github/workflows/test.yml
+      - .github/workflows/ci-go.yml
       - .golangci.yml
       - .go-version
       - go.mod
@@ -48,7 +48,7 @@ jobs:
           go-version: ${{ steps.go-version.outputs.version }}
       - run: go mod edit -replace=github.com/hashicorp/terraform-plugin-sdk/v2=../
       - run: go mod tidy
-      - run: go test -v ./internal/sdkv2provider
+      - run: go test -v ./...
         env:
           TF_ACC: '1'
   test:

helper/resource/plugin.go

@@ -14,6 +14,7 @@ import (
 	"github.com/hashicorp/terraform-plugin-go/tfprotov5"
 	"github.com/hashicorp/terraform-plugin-go/tfprotov6"
 	"github.com/hashicorp/terraform-plugin-sdk/v2/helper/schema"
+	"github.com/hashicorp/terraform-plugin-sdk/v2/internal/logging"
 	"github.com/hashicorp/terraform-plugin-sdk/v2/internal/plugintest"
 	"github.com/hashicorp/terraform-plugin-sdk/v2/plugin"
 	testing "github.com/mitchellh/go-testing-interface"
@@ -69,12 +70,17 @@ func runProviderCommand(ctx context.Context, t testing.T, f func() error, wd *pl
 		// providerName may be returned as terraform-provider-foo, and
 		// we need just foo. So let's fix that.
 		providerName = strings.TrimPrefix(providerName, "terraform-provider-")
+		providerAddress := getProviderAddr(providerName)
+
+		logging.HelperResourceDebug(ctx, "Creating sdkv2 provider instance", map[string]interface{}{logging.KeyProviderAddress: providerAddress})
 
 		provider, err := factory()
 		if err != nil {
 			return fmt.Errorf("unable to create provider %q from factory: %w", providerName, err)
 		}
 
+		logging.HelperResourceDebug(ctx, "Created sdkv2 provider instance", map[string]interface{}{logging.KeyProviderAddress: providerAddress})
+
 		// keep track of the running factory, so we can make sure it's
 		// shut down.
 		wg.Add(1)
@@ -94,14 +100,18 @@ func runProviderCommand(ctx context.Context, t testing.T, f func() error, wd *pl
 			}),
 			NoLogOutputOverride: true,
 			UseTFLogSink:        t,
-			ProviderAddr:        getProviderAddr(providerName),
+			ProviderAddr:        providerAddress,
 		}
 
-		// let's actually start the provider server
+		logging.HelperResourceDebug(ctx, "Starting sdkv2 provider instance server", map[string]interface{}{logging.KeyProviderAddress: providerAddress})
+
 		config, closeCh, err := plugin.DebugServe(ctx, opts)
 		if err != nil {
 			return fmt.Errorf("unable to serve provider %q: %w", providerName, err)
 		}
+
+		logging.HelperResourceDebug(ctx, "Started sdkv2 provider instance server", map[string]interface{}{logging.KeyProviderAddress: providerAddress})
+
 		tfexecConfig := tfexec.ReattachConfig{
 			Protocol:        config.Protocol,
 			ProtocolVersion: config.ProtocolVersion,
@@ -136,6 +146,7 @@ func runProviderCommand(ctx context.Context, t testing.T, f func() error, wd *pl
 		// providerName may be returned as terraform-provider-foo, and
 		// we need just foo. So let's fix that.
 		providerName = strings.TrimPrefix(providerName, "terraform-provider-")
+		providerAddress := getProviderAddr(providerName)
 
 		// If the user has supplied the same provider in both
 		// ProviderFactories and ProtoV5ProviderFactories, they made a
@@ -149,11 +160,15 @@ func runProviderCommand(ctx context.Context, t testing.T, f func() error, wd *pl
 			}
 		}
 
+		logging.HelperResourceDebug(ctx, "Creating tfprotov5 provider instance", map[string]interface{}{logging.KeyProviderAddress: providerAddress})
+
 		provider, err := factory()
 		if err != nil {
 			return fmt.Errorf("unable to create provider %q from factory: %w", providerName, err)
 		}
 
+		logging.HelperResourceDebug(ctx, "Created tfprotov5 provider instance", map[string]interface{}{logging.KeyProviderAddress: providerAddress})
+
 		// keep track of the running factory, so we can make sure it's
 		// shut down.
 		wg.Add(1)
@@ -173,14 +188,18 @@ func runProviderCommand(ctx context.Context, t testing.T, f func() error, wd *pl
 			}),
 			NoLogOutputOverride: true,
 			UseTFLogSink:        t,
-			ProviderAddr:        getProviderAddr(providerName),
+			ProviderAddr:        providerAddress,
 		}
 
-		// let's actually start the provider server
+		logging.HelperResourceDebug(ctx, "Starting tfprotov5 provider instance server", map[string]interface{}{logging.KeyProviderAddress: providerAddress})
+
 		config, closeCh, err := plugin.DebugServe(ctx, opts)
 		if err != nil {
 			return fmt.Errorf("unable to serve provider %q: %w", providerName, err)
 		}
+
+		logging.HelperResourceDebug(ctx, "Started tfprotov5 provider instance server", map[string]interface{}{logging.KeyProviderAddress: providerAddress})
+
 		tfexecConfig := tfexec.ReattachConfig{
 			Protocol:        config.Protocol,
 			ProtocolVersion: config.ProtocolVersion,
@@ -216,6 +235,7 @@ func runProviderCommand(ctx context.Context, t testing.T, f func() error, wd *pl
 		// providerName may be returned as terraform-provider-foo, and
 		// we need just foo. So let's fix that.
 		providerName = strings.TrimPrefix(providerName, "terraform-provider-")
+		providerAddress := getProviderAddr(providerName)
 
 		// If the user has already registered this provider in
 		// ProviderFactories or ProtoV5ProviderFactories, they made a
@@ -229,11 +249,15 @@ func runProviderCommand(ctx context.Context, t testing.T, f func() error, wd *pl
 			}
 		}
 
+		logging.HelperResourceDebug(ctx, "Creating tfprotov6 provider instance", map[string]interface{}{logging.KeyProviderAddress: providerAddress})
+
 		provider, err := factory()
 		if err != nil {
 			return fmt.Errorf("unable to create provider %q from factory: %w", providerName, err)
 		}
 
+		logging.HelperResourceDebug(ctx, "Created tfprotov6 provider instance", map[string]interface{}{logging.KeyProviderAddress: providerAddress})
+
 		// keep track of the running factory, so we can make sure it's
 		// shut down.
 		wg.Add(1)
@@ -249,15 +273,18 @@ func runProviderCommand(ctx context.Context, t testing.T, f func() error, wd *pl
 			}),
 			NoLogOutputOverride: true,
 			UseTFLogSink:        t,
-			ProviderAddr:        getProviderAddr(providerName),
+			ProviderAddr:        providerAddress,
 		}
 
-		// let's actually start the provider server
+		logging.HelperResourceDebug(ctx, "Starting tfprotov6 provider instance server", map[string]interface{}{logging.KeyProviderAddress: providerAddress})
+
 		config, closeCh, err := plugin.DebugServe(ctx, opts)
 		if err != nil {
 			return fmt.Errorf("unable to serve provider %q: %w", providerName, err)
 		}
 
+		logging.HelperResourceDebug(ctx, "Started tfprotov6 provider instance server", map[string]interface{}{logging.KeyProviderAddress: providerAddress})
+
 		tfexecConfig := tfexec.ReattachConfig{
 			Protocol:        config.Protocol,
 			ProtocolVersion: config.ProtocolVersion,
@@ -289,7 +316,9 @@ func runProviderCommand(ctx context.Context, t testing.T, f func() error, wd *pl
 
 	// set the working directory reattach info that will tell Terraform how to
 	// connect to our various running servers.
-	wd.SetReattachInfo(reattachInfo)
+	wd.SetReattachInfo(ctx, reattachInfo)
+
+	logging.HelperResourceTrace(ctx, "Calling wrapped Terraform CLI command")
 
 	// ok, let's call whatever Terraform command the test was trying to
 	// call, now that we know it'll attach back to those servers we just
@@ -299,16 +328,23 @@ func runProviderCommand(ctx context.Context, t testing.T, f func() error, wd *pl
 		log.Printf("[WARN] Got error running Terraform: %s", err)
 	}
 
+	logging.HelperResourceTrace(ctx, "Called wrapped Terraform CLI command")
+	logging.HelperResourceDebug(ctx, "Stopping providers")
+
 	// cancel the servers so they'll return. Otherwise, this closeCh won't
 	// get closed, and we'll hang here.
 	cancel()
 
+	logging.HelperResourceTrace(ctx, "Waiting for providers to stop")
+
 	// wait for the servers to actually shut down; it may take a moment for
 	// them to clean up, or whatever.
 	// TODO: add a timeout here?
 	// PC: do we need one? The test will time out automatically...
 	wg.Wait()
 
+	logging.HelperResourceTrace(ctx, "Providers have successfully stopped")
+
 	// once we've run the Terraform command, let's remove the reattach
 	// information from the WorkingDir's environment. The WorkingDir will
 	// persist until the next call, but the server in the reattach info

helper/resource/testing_new.go

@@ -103,6 +103,8 @@ func runNewTest(ctx context.Context, t testing.T, c TestCase, helper *plugintest
 		return
 	}
 
+	logging.HelperResourceDebug(ctx, "Starting TestSteps")
+
 	// use this to track last step succesfully applied
 	// acts as default for import tests
 	var appliedCfg string

internal/logging/keys.go

@@ -14,6 +14,10 @@ const (
 	// Underlying Go error string when logging an error.
 	KeyError = "error"
 
+	// The full address of the provider, such as
+	// registry.terraform.io/hashicorp/random
+	KeyProviderAddress = "tf_provider_addr"
+
 	// The type of resource being operated on, such as "random_pet"
 	KeyResourceType = "tf_resource_type"
 

internal/plugintest/working_dir.go

@@ -65,7 +65,8 @@ func (wd *WorkingDir) Unsetenv(envVar string) {
 	delete(wd.env, envVar)
 }
 
-func (wd *WorkingDir) SetReattachInfo(reattachInfo tfexec.ReattachInfo) {
+func (wd *WorkingDir) SetReattachInfo(ctx context.Context, reattachInfo tfexec.ReattachInfo) {
+	logging.HelperResourceTrace(ctx, "Setting Terraform CLI reattach configuration", map[string]interface{}{"tf_reattach_config": reattachInfo})
 	wd.reattachInfo = reattachInfo
 }
 

plugin/serve.go

@@ -199,11 +199,10 @@ func tf6serverServe(opts *ServeOpts) error {
 		reattachConfigCh := make(chan *plugin.ReattachConfig)
 
 		go func() {
-			val, ok := <-closeCh
-
-			if ok {
-				opts.TestConfig.CloseCh <- val
-			}
+			// Always forward close channel receive, since its signaling that
+			// the channel is closed.
+			val := <-closeCh
+			opts.TestConfig.CloseCh <- val
 		}()
 
 		go func() {