Add terraform-plugin-log support. #93

paddycarver · 2021-07-07T13:03:09Z

Set up loggers using terraform-plugin-log v0.1.0, and update our
tfprotov5 and tfprotov6 server packages to have trace and error logs,
and to inject useful values in requests opportunistically.

kmoe

Great stuff!

Testing this out with terraform-provider-corner, which uses terraform-plugin-go directly, the only way to turn off the plugin-go logging is to set TF_LOG_SDK_PROTO=off. In particular, with TF_LOG=off, you still see plugin-go logs. Should the plugin-go logs also honour the overall TF_LOG env var, as implied in hashicorp/terraform-plugin-sdk#695?

paddycarver · 2021-07-12T03:55:56Z

Interesting! This is not supposed to be the case, but that behavior is supposed to be implemented in Terraform, as far as I know. I'll dig into this. Were you using TF_LOG_SDK_PROTO=TRACE TF_LOG=off terraform apply, or was it just terraform apply / TF_LOG=off terraform apply?

bflad · 2021-07-26T15:17:20Z

I'm able to reproduce issues with the acceptance testing:

$ terraform version
Terraform v1.0.3
on darwin_amd64

$ env | grep TF_
$

$ TF_ACC=1 go test -count=1 -v ./internal/protocolv6provider
=== RUN   TestAccV6DataSourceTime
{"@caller":"/Users/bflad/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.3.2-0.20210707143005-f28dfe771a91/tfprotov6/server/server.go:285","@level":"trace","@message":"Received request","@module":"sdk.proto","@timestamp":"2021-07-26T10:56:30.594239-04:00","tf_provider_addr":"","tf_req_id":"9daeeb6d-ba5e-2fd5-0249-60628b5a38b1","tf_rpc":"GetProviderSchema"}
{"@caller":"/Users/bflad/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.3.2-0.20210707143005-f28dfe771a91/tfprotov6/server/server.go:292","@level":"trace","@message":"Calling downstream","@module":"sdk.proto","@timestamp":"2021-07-26T10:56:30.594300-04:00","tf_provider_addr":"","tf_req_id":"9daeeb6d-ba5e-2fd5-0249-60628b5a38b1","tf_rpc":"GetProviderSchema"}
...

$ TF_ACC=1 TF_LOG=WARN go test -count=1 -v ./internal/protocolv6provider
=== RUN   TestAccV6DataSourceTime
2021/07/26 11:03:02 [ERROR] Error parsing provider name: Invalid provider source string: The "source" attribute must be in the format "[hostname/][namespace/]name"
2021/07/26 11:03:02 [ERROR] Error parsing provider name: Invalid provider source string: The "source" attribute must be in the format "[hostname/][namespace/]name"
2021/07/26 11:03:02 [ERROR] Error parsing provider name: Invalid provider source string: The "source" attribute must be in the format "[hostname/][namespace/]name"
{"@caller":"/Users/bflad/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.3.2-0.20210707143005-f28dfe771a91/tfprotov6/server/server.go:285","@level":"trace","@message":"Received request","@module":"sdk.proto","@timestamp":"2021-07-26T11:03:02.404092-04:00","tf_provider_addr":"","tf_req_id":"0ac879e7-26b7-2984-4a82-de9bded514dd","tf_rpc":"GetProviderSchema"}
{"@caller":"/Users/bflad/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.3.2-0.20210707143005-f28dfe771a91/tfprotov6/server/server.go:292","@level":"trace","@message":"Calling downstream","@module":"sdk.proto","@timestamp":"2021-07-26T11:03:02.404148-04:00","tf_provider_addr":"","tf_req_id":"0ac879e7-26b7-2984-4a82-de9bded514dd","tf_rpc":"GetProviderSchema"}
{"@caller":"/Users/bflad/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.3.2-0.20210707143005-f28dfe771a91/tfprotov6/server/server.go:298","@level":"trace","@message":"Called downstream","@module":"sdk.proto","@timestamp":"2021-07-26T11:03:02.404167-04:00","tf_provider_addr":"","tf_req_id":"0ac879e7-26b7-2984-4a82-de9bded514dd","tf_rpc":"GetProviderSchema"}
...

$ TF_ACC=1 TF_LOG=off go test -count=1 -v ./internal/protocolv6provider
=== RUN   TestAccV6DataSourceTime
2021/07/26 11:04:44 [WARN] Invalid log level: "off". Defaulting to level: TRACE. Valid levels are: [TRACE DEBUG INFO WARN ERROR]
2021/07/26 11:04:45 [ERROR] Error parsing provider name: Invalid provider source string: The "source" attribute must be in the format "[hostname/][namespace/]name"
2021/07/26 11:04:45 [ERROR] Error parsing provider name: Invalid provider source string: The "source" attribute must be in the format "[hostname/][namespace/]name"
2021/07/26 11:04:45 [ERROR] Error parsing provider name: Invalid provider source string: The "source" attribute must be in the format "[hostname/][namespace/]name"
{"@caller":"/Users/bflad/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.3.2-0.20210707143005-f28dfe771a91/tfprotov6/server/server.go:285","@level":"trace","@message":"Received request","@module":"sdk.proto","@timestamp":"2021-07-26T11:04:45.339550-04:00","tf_provider_addr":"","tf_req_id":"b472e4ac-6bb9-8ccd-5e86-942c1ad0d45d","tf_rpc":"GetProviderSchema"}
{"@caller":"/Users/bflad/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.3.2-0.20210707143005-f28dfe771a91/tfprotov6/server/server.go:292","@level":"trace","@message":"Calling downstream","@module":"sdk.proto","@timestamp":"2021-07-26T11:04:45.339595-04:00","tf_provider_addr":"","tf_req_id":"b472e4ac-6bb9-8ccd-5e86-942c1ad0d45d","tf_rpc":"GetProviderSchema"}
{"@caller":"/Users/bflad/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.3.2-0.20210707143005-f28dfe771a91/tfprotov6/server/server.go:298","@level":"trace","@message":"Called downstream","@module":"sdk.proto","@timestamp":"2021-07-26T11:04:45.339614-04:00","tf_provider_addr":"","tf_req_id":"b472e4ac-6bb9-8ccd-5e86-942c1ad0d45d","tf_rpc":"GetProviderSchema"}
...

# Able to disable parent

$ TF_ACC=1 TF_LOG_SDK=off go test -count=1 -v ./internal/protocolv6provider
=== RUN   TestAccV6DataSourceTime
--- PASS: TestAccV6DataSourceTime (1.44s)
PASS
ok      github.com/hashicorp/terraform-provider-corner/internal/protocolv6provider      1.765s

# Able to disable directly

$ TF_ACC=1 TF_LOG_SDK_PROTO=off go test -count=1 -v ./internal/protocolv6provider
=== RUN   TestAccV6DataSourceTime
--- PASS: TestAccV6DataSourceTime (1.46s)
PASS
ok      github.com/hashicorp/terraform-provider-corner/internal/protocolv6provider      1.761s

Similar occurs with ./internal/protocolprovider (v5).

Trying to install and run the provider via development overrides yields:

terraform {
  required_providers {
    corner = {
      source = "hashicorp/corner"
    }
  }

  required_version = "1.0.3"
}

data "corner_time" "test" {}

output "test" {
  value = data.corner_time.test.id
}

$ terraform apply
╷
│ Warning: Provider development overrides are in effect
│
│ The following provider development overrides are set in the CLI configuration:
│  - hashicorp/corner in /Users/bflad/go/bin
│
│ The behavior may therefore not match any released version of the provider and applying changes may cause the state to become incompatible
│ with published releases.
╵

Stack trace from the terraform-provider-corner plugin:

panic: got a different provider schema from two servers (*schema.GRPCProviderServer, protocol.server). Provider schemas must be identical across providers. Diff:   &tfprotov5.Schema{
- 	Version: 1,
+ 	Version: 0,
  	Block: &tfprotov5.SchemaBlock{
- 		Version:    1,
+ 		Version:    0,
  		Attributes: nil,
  		BlockTypes: nil,
  		... // 3 identical fields
  	},
  }


goroutine 1 [running]:
main.main()
	/Users/bflad/src/github.com/hashicorp/terraform-provider-corner/main.go:17 +0x2a5

Error: The terraform-provider-corner plugin crashed!

This is always indicative of a bug within the plugin. It would be immensely
helpful if you could report the crash with the plugin's maintainers so that it
can be fixed. The output above should help diagnose the issue.

╷
│ Error: Could not load plugin
│
│
│ Plugin reinitialization required. Please run "terraform init".
│
│ Plugins are external binaries that Terraform uses to access and manipulate
│ resources. The configuration provided requires plugins which can't be located,
│ don't satisfy the version constraints, or are otherwise incompatible.
│
│ Terraform automatically discovers provider requirements from your
│ configuration, including providers used in child modules. To see the
│ requirements and constraints, run "terraform providers".
│
│ failed to instantiate provider "registry.terraform.io/hashicorp/corner" to obtain schema: Unrecognized remote plugin message:
│
│ This usually means that the plugin is either invalid or simply
│ needs to be recompiled to support the latest protocol.
│
╵

bflad · 2021-07-26T15:44:10Z

Created hashicorp/terraform-provider-corner#22 for the above.

paddycarver · 2021-07-29T00:38:25Z

It's looking like TF_LOG=off isn't actually valid, which makes sense, because that's supposed to be its default state.

Why this isn't honouring the default state, I'll confess, I find a tad confusing.

paddycarver · 2021-07-29T00:50:11Z

Ah, this is hashicorp/terraform-plugin-sdk#666 all over again. In normal operation, the original stderr of the plugin is what Terraform listens to and filters on. When testing, it's the actual stderr that writes to the user's console. We want to send this back to Terraform, not to the console.

I think a True Fix for this is going to require fixing how Terraform captures stderr, but for the moment, we have a few options:

We can leave it as is, which is unfortunate for people running tests. (Let's not do this.)
We can disable it when running tests. This seems not-great, because then people can't get at these logs when running tests. I believe this is what currently happens in SDKv2.
We can optionally write log files ourselves from the framework when testing.

I'd, personally, be in favor of 2 or 3.

paddycarver · 2021-07-29T20:50:10Z

OK, having thought more about this, I'm leaning heavily towards option three, where we just let the test framework act as a logging sink. This is driven by the fact that the test framework interacts with many Terraform processes, and may want to write logs when no Terraform processes are running, and so we should not count on Terraform acting as our test sink.

Instead, conceptually, we should think of the framework/provider as "log producers" and Terraform/the test framework as "log sinks", and just mirror the log filtering functionality Terraform providers in the test framework. I don't know that we need to do that as part of this change, we can probably just adopt the current strategy, I'm just trying to think about where that belongs (plugin-go, plugin-log, helper/resource, etc.) and think I'm coming down on "helpers in plugin-log, call the helpers in helper/resource and the eventual plugin-testing". So setting up a log sink for tests lives in plugin-log, and we indicate that logs should go to that sink instead of Terraform in helper/resource and eventually in plugin-testing.

@hashicorp/terraform-enablement-sdk everyone feel ok with this plan?

bflad · 2021-07-30T20:42:13Z

I'm on board with this although I'm a little fuzzy on the underlying details.

bflad

Just dropping these thoughts now, before re-verifying acceptance testing.

.changelog/93.txt

go.mod

tfprotov5/tf5server/server.go

bflad · 2021-09-15T16:17:50Z

tfprotov5/tf5server/server.go

+
+	// set up our protocol-level subsystem logger
+	ctx = tfsdklog.NewSubsystem(ctx, tflogSubsystemName, append(tfsdklog.Options{
+		tfsdklog.WithLevelFromEnv("TF", "LOG", "SDK", "PROTO"),


Similarly with this environment variable.

Same rationale here, though I could see documenting it. I think that would be a separate PR to terraform-website, though.

Conversely, are people going to know to look for line 218 to find this environment variable name while looking through this code? It's also used in line 264.

Who is "people", here? I think provider devs/practitioners would know about the environment variable from the website, not from reading the code, whether it's a constant or inlined.

An example person is myself, a maintainer that will most likely not look at this code for months, then try to reassemble context on what environment variables are used or are implemented where. In this case searching for TF_LOG_SDK_PROTO will not yield anything in the code.

Yeah, the search argument is good. I've updated it to use the full environment variable. Can you help me understand why you'd be looking for a list of environment variables used? My usual experience with environment variables is I'm looking for a specific variable, and find it via grep. If that grep leads me to a constants file, I then need to grep for the constant to find where it's used, and that's harder, because it can take multiple forms (MyConstant and mypkg.MyConstant, because MyConstant may be reused as an identifier in a different package).

This is related to hashicorp/terraform-plugin-log#12, which explicitly notes:

Proper log handling in Terraform is complex! ... and the plethora of TF_LOG* environment variables that are available to control logging

Having a single, easy to find place with those environment variables in the code (and which ones are explicitly handled in this code) makes that discovery easier. Honestly, it doesn't matter too much to me how it is documented in the code, I just feel it can be more difficult to know how this particular thing applies to the overall system or code when it is buried in the middle of logic.

I guess this boils down to a heuristic I mentally try to apply to my own code. What outside things might affect or be affected by this code, potentially unexpectedly? Those tend to be treated more special in terms of documentation or coding patterns. Environment variables tends to meet that bar for me because it is a side-effect or logic branch due to the execution environment. (The log keys present in output as noted in the other thread also do for their potential effects on consumers if they get changed.)

If that grep leads me to a constants file, I then need to grep for the constant to find where it's used, and that's harder, because it can take multiple forms (MyConstant and mypkg.MyConstant, because MyConstant may be reused as an identifier in a different package).

Language servers can infer proper references versus generic text tooling like grep. Decent naming can also help, as I would hope this would never be named something generic like that. Something like envTfLogSdkProto doesn't seem like it would be too common elsewhere and cues to the fact it is something environment related to Terraform, logging, the SDK, and protocol.

Regardless of constant or not, my main point here is that I personally don't want to continue a game of "find the environment variable and figure out what it does or how it is affected by other environment variables" every time a bug report or feature request comes in for Terraform's logging.

I have found that a quick way to do that is a constant definition that explains its purpose and expected behaviors:

// Environment variables const ( // Logging level for Terraform protocol logging. // Includes protocol call information and handoffs to plugins. // Does not include request or response data for those calls, see TF_LOG_SDK_PROTO_DATA. // Infers logging level from SDK loggers and above. // Valid values match other loggers, except JSON. envTfLogSdkProto = "TF_LOG_SDK_PROTO" )

Another quick way is code comments where it is used with the same explanations, or even comments at the package level. A longer form way to do that is separate hard copy, such as intended by hashicorp/terraform-plugin-log#12, although that can be trickier to keep up to date and does not necessarily help while you're looking at the code within the codebase itself.

Agree that we need to make sure all env vars are well documented here, and prefer to err on the side of too much documentation. I like @bflad's suggestion of colocating them in the code as constants, as well as a dedicated section in the website docs for the plethora of TF_LOG* variables.

From experience with plugintest (in particular the code for Terraform binary discovery, https://github.com/hashicorp/terraform-plugin-sdk/blob/main/internal/plugintest/config.go#L26), even basic precedence logic between env vars can be very confusing for users if they can't see a list of all the env vars in one place, or have a step-by-step guide to setting the ones they need. The potential for frustrating debugging is even greater here as these env vars pertain to logging itself.

I think the disagreement here is less about whether we need to document environment variables and more about whether constants are necessary to document environment variables and where the appropriate place(s) to document environment variables is.

tfprotov5/tf5server/server.go

Upgrade to the latest version of terraform-plugin-go, bringing support for terraform-plugin-log. Use the terraform-plugin-log logging sink when setting up the helper/resource test framework. The idea here is that we'll use the logging sink to reroute all terraform-plugin-log logs, and leave the `log.Print` logs the way they are with the existing override. Over time, it may be nice to migrate those logs to use terraform-plugin-log, which we've introduced `logging.GetTestLogContext` as a helper for. But that may be a mistake, and maybe we should wait until we need it to introduce that function. In theory, this PR should result in no logs being written to the CLI during testing, which was happening in hashicorp/terraform-plugin-go#93. It should respect `TF_LOG` and `TF_LOG_PATH`, as well as any terraform-plugin-log style environment variables in use.

Set up loggers using terraform-plugin-log v0.1.0, and update our tfprotov5 and tfprotov6 server packages to have trace and error logs, and to inject useful values in requests opportunistically. Let providers configure the name for logging purposes and to control the environment variable that is used for the provider's log level. It defaults to the shortname of the provider from the registry address provided, or no environment variable control if the registry address can't be parsed. Make it so we can inject a log sink.

Upgrade to the latest version of terraform-plugin-go, bringing support for terraform-plugin-log. Use the terraform-plugin-log logging sink when setting up the helper/resource test framework. The idea here is that we'll use the logging sink to reroute all terraform-plugin-log logs, and leave the `log.Print` logs the way they are with the existing override. Over time, it may be nice to migrate those logs to use terraform-plugin-log, probably by extending `helper/logging.GetTestLogContext` to include a root SDK logger. In theory, this PR should result in no logs being written to the CLI during testing, which was happening in hashicorp/terraform-plugin-go#93. It should respect `TF_LOG`, `TF_LOG_PATH`, `TF_ACC_LOG_PATH`, and `TF_LOG_PATH_MASK`, as well as any terraform-plugin-log style environment variables in use. This also fixes `TF_ACC_LOG_PATH` to record the logs from the provider under test, not just the logs from Terraform and any providers the provider under test depends on.

bflad

Looks good to me 🚀

Upgrade to the latest version of terraform-plugin-go, bringing support for terraform-plugin-log. Use the terraform-plugin-log logging sink when setting up the helper/resource test framework. The idea here is that we'll use the logging sink to reroute all terraform-plugin-log logs, and leave the `log.Print` logs the way they are with the existing override. Over time, it may be nice to migrate those logs to use terraform-plugin-log, probably by extending `helper/logging.GetTestLogContext` to include a root SDK logger. In theory, this PR should result in no logs being written to the CLI during testing, which was happening in hashicorp/terraform-plugin-go#93. It should respect `TF_LOG`, `TF_LOG_PATH`, `TF_ACC_LOG_PATH`, and `TF_LOG_PATH_MASK`, as well as any terraform-plugin-log style environment variables in use. This also fixes `TF_ACC_LOG_PATH` to record the logs from the provider under test, not just the logs from Terraform and any providers the provider under test depends on. Co-authored-by: Brian Flad <bflad417@gmail.com>

github-actions · 2024-05-27T05:07:33Z

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.

paddycarver force-pushed the paddy_logging branch 2 times, most recently from 06855e0 to 4abad96 Compare July 7, 2021 13:10

paddycarver requested a review from a team July 7, 2021 13:11

paddycarver added the enhancement New feature or request label Jul 7, 2021

paddycarver force-pushed the paddy_logging branch from 4abad96 to 0177ed2 Compare July 7, 2021 13:27

paddycarver mentioned this pull request Jul 7, 2021

Integration with terraform-plugin-log hashicorp/terraform-plugin-framework#63

Closed

kmoe reviewed Jul 9, 2021

View reviewed changes

paddycarver mentioned this pull request Aug 9, 2021

Set up a logging sink hashicorp/terraform-plugin-log#6

Closed

paddycarver force-pushed the paddy_logging branch from f28dfe7 to 0aa7840 Compare September 4, 2021 06:46

paddycarver added this to the v0.4.0 milestone Sep 4, 2021

This was referenced Sep 15, 2021

Integration with terraform-plugin-log hashicorp/terraform-plugin-sdk#804

Closed

Integrate with terraform-plugin-log hashicorp/terraform-plugin-mux#24

Closed

bflad reviewed Sep 15, 2021

View reviewed changes

bflad mentioned this pull request Sep 16, 2021

Consider Subsystem Logger with Protocol Request and Response Data #107

Closed

paddycarver force-pushed the paddy_logging branch from 1dec5fd to e2c7b78 Compare September 21, 2021 12:07

paddycarver mentioned this pull request Sep 21, 2021

Upgrade to latest terraform-plugin-go, add logging sink. hashicorp/terraform-plugin-sdk#805

Merged

paddycarver self-assigned this Sep 21, 2021

bflad modified the milestones: v0.4.0, v0.5.0 Sep 30, 2021

paddycarver force-pushed the paddy_logging branch from 2017340 to 1ef303e Compare November 11, 2021 19:06

paddycarver force-pushed the paddy_logging branch from 1ef303e to 882e75a Compare December 7, 2021 18:59

paddycarver added 2 commits December 7, 2021 11:15

Use released version of plugin-log.

d676dd6

go mod tidy

dc83d98

paddycarver requested a review from bflad December 7, 2021 19:17

bflad approved these changes Dec 7, 2021

View reviewed changes

paddycarver merged commit 0b29f73 into main Dec 7, 2021

paddycarver deleted the paddy_logging branch December 7, 2021 19:27

bflad mentioned this pull request Dec 22, 2021

Create terraform.io/plugin Section for terraform-plugin-go Documentation #129

Open

nfagerlund mentioned this pull request Jan 12, 2023

Enable suppressed linters and fix issues hashicorp/terraform-provider-tfe#645

Merged

github-actions bot locked as resolved and limited conversation to collaborators May 27, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add terraform-plugin-log support. #93

Add terraform-plugin-log support. #93

paddycarver commented Jul 7, 2021

kmoe left a comment

paddycarver commented Jul 12, 2021

bflad commented Jul 26, 2021

bflad commented Jul 26, 2021

paddycarver commented Jul 29, 2021

paddycarver commented Jul 29, 2021

paddycarver commented Jul 29, 2021

bflad commented Jul 30, 2021

bflad left a comment

bflad Sep 15, 2021

paddycarver Sep 21, 2021

bflad Sep 21, 2021

paddycarver Sep 21, 2021

bflad Sep 21, 2021

paddycarver Sep 22, 2021

bflad Sep 22, 2021

kmoe Oct 4, 2021

paddycarver Oct 5, 2021

bflad left a comment

github-actions bot commented May 27, 2024

Add terraform-plugin-log support. #93

Add terraform-plugin-log support. #93

Conversation

paddycarver commented Jul 7, 2021

kmoe left a comment

Choose a reason for hiding this comment

paddycarver commented Jul 12, 2021

bflad commented Jul 26, 2021

bflad commented Jul 26, 2021

paddycarver commented Jul 29, 2021

paddycarver commented Jul 29, 2021

paddycarver commented Jul 29, 2021

bflad commented Jul 30, 2021

bflad left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bflad left a comment

Choose a reason for hiding this comment

github-actions bot commented May 27, 2024