From fd9ac3ce7b02626dbc2b7a5753df149bfe76f166 Mon Sep 17 00:00:00 2001 From: Brian Flad Date: Tue, 12 Apr 2022 14:07:52 -0400 Subject: [PATCH] helper/schema: Prevent missing SDK logging entries and confusing provider.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/terraform-plugin-go@v0.8.0/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/terraform-plugin-go@v0.8.0/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/terraform-plugin-go@v0.8.0/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/terraform-plugin-go@v0.8.0/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 | 3 +++ internal/logging/context.go | 22 ++++++++++------------ internal/logging/environment_variables.go | 10 ++++++++++ 3 files changed, 23 insertions(+), 12 deletions(-) create mode 100644 .changelog/936.txt diff --git a/.changelog/936.txt b/.changelog/936.txt new file mode 100644 index 00000000000..63ad5ac9c93 --- /dev/null +++ b/.changelog/936.txt @@ -0,0 +1,3 @@ +```release-note:bug +helper/schema: Prevented missing SDK logging entries and confusing provider.stdio TRACE logging entries +``` diff --git a/internal/logging/context.go b/internal/logging/context.go index 2fde858bb17..7ab00a18217 100644 --- a/internal/logging/context.go +++ b/internal/logging/context.go @@ -8,10 +8,11 @@ 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 @@ -19,16 +20,17 @@ func InitContext(ctx context.Context) context.Context { // 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,7 +39,6 @@ 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 } @@ -45,7 +46,6 @@ func TestNameContext(ctx context.Context, testName string) context.Context { // 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 } @@ -53,7 +53,6 @@ func TestStepNumberContext(ctx context.Context, stepNumber int) context.Context // 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 } @@ -61,7 +60,6 @@ func TestTerraformPathContext(ctx context.Context, terraformPath string) context // 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 } diff --git a/internal/logging/environment_variables.go b/internal/logging/environment_variables.go index 643d6b83586..db1a27a8147 100644 --- a/internal/logging/environment_variables.go +++ b/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.