Structured logging

[jbardin]

Take the first steps towards end-to-end structured logging in core. The primary goal of this PR is to remove the LevelFilter which attempted to filter log output based on the TF_LOG setting, and use the capabilities of hclog.Logger directly. We do this by injecting a wrapped hclog.Logger into the std lib log output, which can more correctly infer the log level as it gets the entire message as a single argument, rather than LevelFilter which can only guess or set a default level when encountering multiple unstructured and untagged lines.

The global loggers are initialized in the github.com/hashicorp/terraform/internal/logging package. If proper filtering is needed by a package for testing using the std library log package, importing github.com/hashicorp/terraform/internal/logging is sufficient to setup the global logger with the requested level.

If a package wishes to use hclog directly, a global hclog.Logger can be obtained via the logging.HCLogger function, or a new logger can be create with logging.NewHCLogger. This is used to setup the plugin clients for example, as they can accept an hclog.Logger instance directly.

There are still some upstream changes that will need to be made in go-plugin and terraform-plugin-sdk in order to maintain structured end-to-end logging from providers, but these changes set us up in core to accept and filter the logs correctly.

[codecov]

Codecov Report

Merging #26632 into master will increase coverage by 0.08%.
The diff coverage is 47.72%.

Impacted Files	Coverage Δ
backend/remote-state/azure/sender.go	0.00% <ø> (ø)
backend/remote-state/s3/backend.go	0.00% <ø> (ø)
command/meta_providers.go	33.33% <0.00%> (+2.29%)	⬆️
command/plugins.go	38.27% <0.00%> (-4.79%)	⬇️
dag/walk.go	92.25% <ø> (-0.06%)	⬇️
helper/resource/testing.go	28.53% <ø> (+0.30%)	⬆️
internal/logging/indent.go	100.00% <ø> (ø)
main.go	33.19% <0.00%> (+0.39%)	⬆️
terraform/context.go	87.22% <ø> (ø)
terraform/graph_builder.go	82.14% <ø> (ø)
... and 8 more

[mildwonkey]

😱 THIS IS AWESOME!

I did notice that a warning got printed twice when I used DEBUG level logging; this isn't a merge blocker but if you know how to clean it up it would be nice.

BUT LOOK AT THE FILTERING ITS SO GOOD!!!

TF_LOG=INFO terraform init
2020/10/20 09:14:54 [WARN] Log levels other than TRACE are currently unreliable, and are supported only for backward compatibility.
  Use TF_LOG=TRACE to see Terraform's internal logs.
  ----
2020/10/20 09:14:54 [WARN] Log levels other than TRACE are currently unreliable, and are supported only for backward compatibility.
  Use TF_LOG=TRACE to see Terraform's internal logs.
  ----
2020-10-20T09:14:54.201-0400 [INFO]  Terraform version: 0.14.0 dev
2020-10-20T09:14:54.201-0400 [INFO]  Go runtime version: go1.15.2
2020-10-20T09:14:54.201-0400 [INFO]  CLI args: []string{"/Users/kristin/go/bin/terraform", "init"}
2020-10-20T09:14:54.202-0400 [INFO]  Loading CLI configuration from /Users/kristin/.terraformrc
2020-10-20T09:14:54.202-0400 [INFO]  Loading CLI configuration from /Users/kristin/.terraform.d/credentials.tfrc.json
2020-10-20T09:14:54.204-0400 [INFO]  Checkpoint disabled. Not running.
2020-10-20T09:14:54.204-0400 [INFO]  CLI command args: []string{"init"}

TF_LOG=DEBUG terraform init
2020/10/20 09:12:13 [WARN] Log levels other than TRACE are currently unreliable, and are supported only for backward compatibility.
  Use TF_LOG=TRACE to see Terraform's internal logs.
  ----
2020/10/20 09:12:13 [WARN] Log levels other than TRACE are currently unreliable, and are supported only for backward compatibility.
  Use TF_LOG=TRACE to see Terraform's internal logs.
  ----
2020-10-20T09:12:13.605-0400 [INFO]  Terraform version: 0.14.0 dev
2020-10-20T09:12:13.605-0400 [INFO]  Go runtime version: go1.15.2
2020-10-20T09:12:13.605-0400 [INFO]  CLI args: []string{"/Users/kristin/go/bin/terraform", "init"}
2020-10-20T09:12:13.605-0400 [DEBUG] Attempting to open CLI config file: /Users/kristin/.terraformrc
2020-10-20T09:12:13.605-0400 [INFO]  Loading CLI configuration from /Users/kristin/.terraformrc
2020-10-20T09:12:13.606-0400 [INFO]  Loading CLI configuration from /Users/kristin/.terraform.d/credentials.tfrc.json

TF_LOG=TRACE terraform init
2020-10-20T09:11:59.226-0400 [INFO]  Terraform version: 0.14.0 dev
2020-10-20T09:11:59.226-0400 [INFO]  Go runtime version: go1.15.2
2020-10-20T09:11:59.226-0400 [INFO]  CLI args: []string{"/Users/kristin/go/bin/terraform", "init"}
2020-10-20T09:11:59.226-0400 [DEBUG] Attempting to open CLI config file: /Users/kristin/.terraformrc
2020-10-20T09:11:59.226-0400 [INFO]  Loading CLI configuration from /Users/kristin/.terraformrc
2020-10-20T09:11:59.229-0400 [INFO]  Loading CLI configuration from /Users/kristin/.terraform.d/credentials.tfrc.json
2020-10-20T09:11:59.230-0400 [DEBUG] checking for credentials in "/Users/kristin/.terraform.d/plugins"
2020-10-20T09:11:59.231-0400 [DEBUG] ignoring non-existing provider search directory terraform.d/plugins
2020-10-20T09:11:59.231-0400 [DEBUG] will search for provider plugins in /Users/kristin/.terraform.d/plugins
2020-10-20T09:11:59.231-0400 [TRACE] getproviders.SearchLocalDirectory: /Users/kristin/.terraform.d/plugins is a symlink to /Users/kristin/.terraform.d/plugins
2020-10-20T09:11:59.234-0400 [TRACE] getproviders.SearchLocalDirectory: found registry.terraform.io/mildwonkey/random v0.0.1 for darwin_amd64 at /Users/kristin/.terraform.d/plugins/registry.terraform.io/mildwonkey/random/0.0.1/darwin_amd64
2020-10-20T09:11:59.234-0400 [DEBUG] will search for provider plugins in /Users/kristin/Library/Application Support/io.terraform/plugins

[mildwonkey]

I don't think I even knew this was an option, very nice!

[mildwonkey]

This looks great! I was going to ask about documentation but (in case anyone else is wondering the same thing) we never documented that TRACE was effectively the only option anyway: https://www.terraform.io/docs/internals/debugging.html

[jbardin]

Yes, that message gets printed each time we check the level, but it will be removed or come from a new location (to indicate the situation only applies to certain providers) once the upstream changes are in place.

[ghost]

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues.

If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.