Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

helper/schema: Prevent missing SDK logging entries and confusing provider.stdio TRACE entries #936

Merged
merged 2 commits into from Apr 12, 2022

Conversation

bflad
Copy link
Member

@bflad bflad commented Apr 12, 2022

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
...

…ider.stdio TRACE entries

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
...
```
@bflad bflad added the bug Something isn't working label Apr 12, 2022
@bflad bflad added this to the v2.14.0 milestone Apr 12, 2022
@bflad bflad requested a review from jbardin April 12, 2022 15:16
@bflad bflad requested a review from a team as a code owner April 12, 2022 15:16
Copy link
Contributor

@detro detro left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just a question to see if we can end up in an undesired state, but nothing worth blocking this.

internal/logging/context.go Show resolved Hide resolved
@bflad bflad merged commit fd9ac3c into main Apr 12, 2022
@bflad bflad deleted the bflad-provider-stdio-logs branch April 12, 2022 18:07
@github-actions
Copy link

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

@github-actions github-actions bot locked as resolved and limited conversation to collaborators May 13, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants