helper/schema: Prevent missing SDK logging entries and confusing prov…

…ider.stdio TRACE entries (#936)

Previously, the root SDK logger context was being overwritten without taking into consideration the rewritten `os.Stderr` caused by using `go-plugin`. Since this SDK is implemented on top of terraform-plugin-go `tf5server` now, the root SDK logger context with the correct stderr handling is already in place. Use it instead.

This also removes the `helper_resource` subsystem logger from the production code path and the `helper_schema` subsystem logger from the testing code path to remove any confusion about the purpose of each.

Previous logging messages (note these are caused by `helper_schema` "Found Data Source/Resource type" TRACE messages):

```
2022-04-12T10:40:26.257-0400 [TRACE] provider.terraform-provider-aws_v4.9.0_x5: Received request: tf_req_id=de31c45e-8956-f15e-32b5-a8092751a105 tf_rpc=GetProviderSchema tf_proto_version=5.2 @module=sdk.proto tf_provider_addr=provider @caller=github.com/hashicorp/[email protected]/internal/logging/protocol.go:21 timestamp=2022-04-12T10:40:26.256-0400
2022-04-12T10:40:26.257-0400 [TRACE] provider.terraform-provider-aws_v4.9.0_x5: Calling downstream: @caller=github.com/hashicorp/[email protected]/internal/logging/protocol.go:21 tf_rpc=GetProviderSchema @module=sdk.proto tf_proto_version=5.2 tf_provider_addr=provider tf_req_id=de31c45e-8956-f15e-32b5-a8092751a105 timestamp=2022-04-12T10:40:26.256-0400
2022-04-12T10:40:26.257-0400 [TRACE] provider.stdio: received data: channel=STDERR len=236
2022-04-12T10:40:26.257-0400 [TRACE] provider.stdio: waiting for stdio data
2022-04-12T10:40:26.257-0400 [TRACE] provider.stdio: received data: channel=STDERR len=554
2022-04-12T10:40:26.257-0400 [TRACE] provider.stdio: waiting for stdio data
2022-04-12T10:40:26.257-0400 [TRACE] provider.stdio: received data: channel=STDERR len=285
2022-04-12T10:40:26.257-0400 [TRACE] provider.stdio: waiting for stdio data
...
```

Now:

```
2022-04-12T11:11:25.684-0400 [TRACE] provider.terraform-provider-aws: Received request: @caller=/Users/bflad/go/pkg/mod/github.com/hashicorp/[email protected]/internal/logging/protocol.go:21 @module=sdk.proto tf_rpc=GetProviderSchema tf_proto_version=5.2 tf_provider_addr=provider tf_req_id=0c818104-0f9d-2bb3-1fa5-998a35ecae3e timestamp=2022-04-12T11:11:25.684-0400
2022-04-12T11:11:25.684-0400 [TRACE] provider.terraform-provider-aws: Calling downstream: tf_rpc=GetProviderSchema @caller=/Users/bflad/go/pkg/mod/github.com/hashicorp/[email protected]/internal/logging/protocol.go:21 @module=sdk.proto tf_provider_addr=provider tf_req_id=0c818104-0f9d-2bb3-1fa5-998a35ecae3e tf_proto_version=5.2 timestamp=2022-04-12T11:11:25.684-0400
2022-04-12T11:11:25.684-0400 [TRACE] provider.terraform-provider-aws: Getting provider schema: @caller=/Users/bflad/src/github.com/hashicorp/terraform-plugin-sdk/internal/logging/helper_schema.go:21 @module=sdk.helper_schema timestamp=2022-04-12T11:11:25.684-0400
2022-04-12T11:11:25.685-0400 [TRACE] provider.terraform-provider-aws: Found resource type: @module=sdk.helper_schema tf_resource_type=aws_gamelift_fleet @caller=/Users/bflad/src/github.com/hashicorp/terraform-plugin-sdk/internal/logging/helper_schema.go:21 timestamp=2022-04-12T11:11:25.685-0400
2022-04-12T11:11:25.685-0400 [TRACE] provider.terraform-provider-aws: Found resource type: @module=sdk.helper_schema tf_resource_type=aws_glue_crawler @caller=/Users/bflad/src/github.com/hashicorp/terraform-plugin-sdk/internal/logging/helper_schema.go:21 timestamp=2022-04-12T11:11:25.685-0400
2022-04-12T11:11:25.685-0400 [TRACE] provider.terraform-provider-aws: Found resource type: tf_resource_type=aws_swf_domain @caller=/Users/bflad/src/github.com/hashicorp/terraform-plugin-sdk/internal/logging/helper_schema.go:21 @module=sdk.helper_schema timestamp=2022-04-12T11:11:25.685-0400
...
```

.changelog/936.txt

@@ -0,0 +1,3 @@
+```release-note:bug
+helper/schema: Prevented missing SDK logging entries and confusing provider.stdio TRACE logging entries
+```

internal/logging/context.go

@@ -8,27 +8,29 @@ import (
 	testing "github.com/mitchellh/go-testing-interface"
 )
 
-// InitContext creates SDK logger contexts.
+// InitContext creates SDK logger contexts when the provider is running in
+// "production" (not under acceptance testing). The incoming context will
+// already have the root SDK logger and root provider logger setup from
+// terraform-plugin-go tf5server RPC handlers.
 func InitContext(ctx context.Context) context.Context {
-	ctx = tfsdklog.NewRootSDKLogger(ctx)
-	ctx = tfsdklog.NewSubsystem(ctx, SubsystemHelperResource, tfsdklog.WithLevelFromEnv(EnvTfLogSdkHelperResource))
 	ctx = tfsdklog.NewSubsystem(ctx, SubsystemHelperSchema, tfsdklog.WithLevelFromEnv(EnvTfLogSdkHelperSchema))
 
 	return ctx
 }
 
 // InitTestContext registers the terraform-plugin-log/tfsdklog test sink,
 // configures the standard library log package, and creates SDK logger
-// contexts.
+// contexts. The incoming context is expected to be devoid of logging setup.
 //
-// It may be possible to eliminate the helper/logging handling if all
-// log package calls are replaced with tfsdklog and any go-plugin or
-// terraform-exec logger configurations are updated to the tfsdklog logger.
+// The standard library log package handling is important as provider code
+// under test may be using that package or another logging library outside of
+// terraform-plugin-log.
 func InitTestContext(ctx context.Context, t testing.T) context.Context {
 	helperlogging.SetOutput(t)
 
 	ctx = tfsdklog.RegisterTestSink(ctx, t)
-	ctx = InitContext(ctx)
+	ctx = tfsdklog.NewRootSDKLogger(ctx, tfsdklog.WithLevelFromEnv(EnvTfLogSdk))
+	ctx = tfsdklog.NewSubsystem(ctx, SubsystemHelperResource, tfsdklog.WithLevelFromEnv(EnvTfLogSdkHelperResource))
 	ctx = TestNameContext(ctx, t.Name())
 
 	return ctx
@@ -37,31 +39,27 @@ func InitTestContext(ctx context.Context, t testing.T) context.Context {
 // TestNameContext adds the current test name to loggers.
 func TestNameContext(ctx context.Context, testName string) context.Context {
 	ctx = tfsdklog.SubsystemWith(ctx, SubsystemHelperResource, KeyTestName, testName)
-	ctx = tfsdklog.SubsystemWith(ctx, SubsystemHelperSchema, KeyTestName, testName)
 
 	return ctx
 }
 
 // TestStepNumberContext adds the current test step number to loggers.
 func TestStepNumberContext(ctx context.Context, stepNumber int) context.Context {
 	ctx = tfsdklog.SubsystemWith(ctx, SubsystemHelperResource, KeyTestStepNumber, stepNumber)
-	ctx = tfsdklog.SubsystemWith(ctx, SubsystemHelperSchema, KeyTestStepNumber, stepNumber)
 
 	return ctx
 }
 
 // TestTerraformPathContext adds the current test Terraform CLI path to loggers.
 func TestTerraformPathContext(ctx context.Context, terraformPath string) context.Context {
 	ctx = tfsdklog.SubsystemWith(ctx, SubsystemHelperResource, KeyTestTerraformPath, terraformPath)
-	ctx = tfsdklog.SubsystemWith(ctx, SubsystemHelperSchema, KeyTestTerraformPath, terraformPath)
 
 	return ctx
 }
 
 // TestWorkingDirectoryContext adds the current test working directory to loggers.
 func TestWorkingDirectoryContext(ctx context.Context, workingDirectory string) context.Context {
 	ctx = tfsdklog.SubsystemWith(ctx, SubsystemHelperResource, KeyTestWorkingDirectory, workingDirectory)
-	ctx = tfsdklog.SubsystemWith(ctx, SubsystemHelperSchema, KeyTestWorkingDirectory, workingDirectory)
 
 	return ctx
 }

internal/logging/environment_variables.go

@@ -2,6 +2,16 @@ package logging
 
 // Environment variables.
 const (
+	// EnvTfLogSdk is an environment variable that sets the logging level of
+	// the root SDK logger, while the provider is under test. In "production"
+	// usage, this environment variable is handled by terraform-plugin-go.
+	//
+	// Terraform CLI's logging must be explicitly turned on before this
+	// environment varable can be used to reduce the SDK logging levels. It
+	// cannot be used to show only SDK logging unless all other logging levels
+	// are turned off.
+	EnvTfLogSdk = "TF_LOG_SDK"
+
 	// EnvTfLogSdkHelperResource is an environment variable that sets the logging
 	// level of SDK helper/resource loggers. Infers root SDK logging level, if
 	// unset.