Using the default logger causes duplicate timestamp and severity values in log entries

[gdavison]

SDK version

github.com/hashicorp/terraform-plugin-sdk/v2 v2.10.1

Terraform version

Terraform v1.1.4
on darwin_amd64
+ provider registry.terraform.io/hashicorp/aws v3.73.0

Expected Behavior

Log lines should look like the following

2022-01-26T16:25:33.123-0800 [DEBUG] provider.terraform-provider-aws_v3.73.0_x5: Waiting for state to become: [success]: timestamp=2022-01-26T16:25:33.123-0800

Actual Behavior

Log lines look like the following

2022-01-26T16:25:33.123-0800 [INFO] provider.terraform-provider-aws_v3.73.0_x5: 2022/01/26 16:25:33 [DEBUG] Waiting for state to become: [success]: timestamp=2022-01-26T16:25:33.123-0800

I assume the first set, 2022-01-26T16:25:33.123-0800 [INFO] provider.terraform-provider-aws_v3.73.0_x5: comes from the Terraform CLI.

The second set, 2022/01/26 16:25:33 [DEBUG], comes from the AWS provider.

Level inference is also not working, since the provider is specifying DEBUG, but Terraform is logging as INFO.

Steps to Reproduce

1. Call TF_LOG=DEBUG terraform plan with a configuration using the AWS provider.

Additional Information

We are using the standard logger as provided by terraform-plugin-sdk.

Disabling the date and time on the default logger by calling log.SetFlags(0) before plugin.Serve(opts) is a workaround.

Adding fractional seconds and UTC using log.SetFlags(log.Ldate | log.Ltime | log.Lmicroseconds | log.LUTC) does not work as a workaround

[bflad]

@gdavison out of curiosity, is this any better with terraform-plugin-sdk/v2@v2.12.0?

[bflad]

With the following configuration:

terraform {
  required_providers {
    aws = {
      source  = "hashicorp/aws"
      version = "4.8.0"
    }
  }
}

provider "aws" {
  region = "us-west-2"
}

resource "aws_vpc" "test" {
  cidr_block = "10.0.0.0/16"
}

terraform-plugin-sdk/v2@v2.12.0 with the log.SetFlags() handling in terraform-provider-aws@4.8.0 returns these log messages:

$ TF_LOG=TRACE terraform apply -auto-approve |& grep 'Waiting for state to become'
2022-03-30T20:30:05.837-0400 [DEBUG] provider.terraform-provider-aws_v4.8.0_x5: Waiting for state to become: [available]: timestamp=2022-03-30T20:30:05.837-0400
2022-03-30T20:30:06.077-0400 [DEBUG] provider.terraform-provider-aws_v4.8.0_x5: Waiting for state to become: [success]: timestamp=2022-03-30T20:30:06.077-0400

Removing the log.SetFlags() handling in the provider yields the undesirable timestamp and log level still:

$ TF_CLI_CONFIG_FILE=/Users/bflad/.terraformrc-dev TF_LOG=TRACE terraform apply -auto-approve |& grep 'Waiting for state to become'
2022-03-30T20:33:40.943-0400 [INFO]  provider.terraform-provider-aws: 2022/03/30 20:33:40 [DEBUG] Waiting for state to become: [available]: timestamp=2022-03-30T20:33:40.943-0400
2022-03-30T20:33:41.208-0400 [INFO]  provider.terraform-provider-aws: 2022/03/30 20:33:41 [DEBUG] Waiting for state to become: [success]: timestamp=2022-03-30T20:33:41.208-0400

One likely fix for this is to convert all the non-plugin-startup terraform-plugin-sdk/v2 logging from log to tfsdklog. Another might be to try and do the SetFlags handling as well, but while easier in theory to do, it is much hard to appropriately verify with the acceptance testing logging, production logging, etc.

I'll try the first option to see how it goes.

[bflad]

When using the log package for logging, I believe the log.SetFlags() call is a requirement to properly strip its date and time prefix information. This will become part of the https://terraform.io/plugin/log/writing documentation as part of hashicorp/terraform-plugin-log#80.

Fixing these specific Waiting for state to become log messages generated by the SDK is otherwise a challenge though because we cannot really switch them over to terraform-plugin-log based logging since it is not guaranteed that the context.Context coming in is a properly setup one holding the loggers (this is an issue mainly because of this terraform-plugin-log issue: hashicorp/terraform-plugin-log#52). Maybe we can treat that issue, once resolved, released, dependency updated here, and that logging switched to tfsdklog as resolution in this specific case, but there are other log package based logs that cannot be fixed since the context.Context is not available at all. 😢

[bflad]

By the way, I do not think we can switch (at least easily) non-context-aware places to fmt.Fprintf(os.Stderr, "...") instead of using log.Printf() since during testing we grab the output to control it based on environment variables. There may be equivalent logic we could do to redirect os.Stderr into our own place similar to log during testing, but that could potentially be a cursed idea.