Add terraform-plugin-log support.

[paddycarver]

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]

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]

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]

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

[paddycarver]

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]

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:

1. We can leave it as is, which is unfortunate for people running tests. (Let's not do this.)
2. 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.
3. We can optionally write log files ourselves from the framework when testing.

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

[paddycarver]

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]

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.

[bflad]

Similarly with this environment variable.

[paddycarver]

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

[bflad]

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.

[paddycarver]

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.

[bflad]

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.

[paddycarver]

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

[bflad]

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.

[kmoe]

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.

[paddycarver]

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.

[bflad]

Looks good to me 🚀

[github-actions]

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.