From 3bb41e994f442c8b1c83e1017d8c3a07410fb4dd Mon Sep 17 00:00:00 2001 From: Brian Flad Date: Fri, 15 Jul 2022 11:45:27 -0400 Subject: [PATCH 1/3] website: Add tflog requirements section and legacy logging section Reference: https://github.com/hashicorp/terraform-plugin-log/issues/57 Reference: https://github.com/hashicorp/terraform-plugin-sdk/issues/863 This also makes some minor fixes to use recently updated `SetField()` function names. --- website/docs/plugin/log/writing.mdx | 133 +++++++++++++++++++++++----- 1 file changed, 113 insertions(+), 20 deletions(-) diff --git a/website/docs/plugin/log/writing.mdx b/website/docs/plugin/log/writing.mdx index a69c6a5..78c27c6 100644 --- a/website/docs/plugin/log/writing.mdx +++ b/website/docs/plugin/log/writing.mdx @@ -8,18 +8,28 @@ description: >- Use the [`tflog` package](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog) to write logs for your provider. SDKs like the `terraform-plugin-framework`, `terraform-plugin-go`, and `terraform-plugin-sdk/v2` set up logging for you, so you only need to write the logs themselves. You can write log output at varying verbosity levels, add variables to logs, and create subsystems to group logs that relate to distinct sections of code (e.g., the API client). -!> **Warning:** Do not use `fmt.Println` and similar methods to log. They will silently fail, making the output unavailable. - +!> **Warning:** Do not use `fmt.Println` and similar methods to log to standard output (stdout). They will not generate visible output in older versions of Terraform and are truncated in recent versions of Terraform. ## Structured Logging The `tflog` package uses structured logging, based on [`go-hclog`](https://pkg.go.dev/github.com/hashicorp/go-hclog). Rather than writing logs as sentences with embedded variables and values, `tflog` takes a sentence describing the logging event and a set of variables to log. When variables are separate from the log description, you can use them to programmatically parse, filter, and search log output. This separation also allows other parts of the system to associate variables with downstream log output. -## Log Levels +### Requirements + +One of the following SDK versions is required to properly output structured logs with the `tflog` package: + +- [`terraform-plugin-framework`](/plugin/framework) version 0.6.0 or later +- [`terraform-plugin-sdk`](/plugin/sdkv2) version 2.10.0 or later + +Follow the [legacy logging](#legacy-logging) instructions to write logs with older versions. + +All calls to `tflog` package functionality must use an SDK provided `context.Context`, which stores the logging implementation. Every `terraform-plugin-framework` method implemented by providers automatically includes the correct `context.Context`. Providers written with `terraform-plugin-sdk` must use context-aware functionality, such as the [`helper/schema.Resource` type `ReadContext` field](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-sdk/v2/helper/schema#Resource.ReadContext). + +### Log Levels You must choose a verbosity level for each line of log output. This lets consumers [specify a type of log output](/plugin/log/managing#log-levels) to write from your provider. For example, you can use environment variables to set your provider to write only logs of type `Warn` during a Terraform run. -### Error +#### Error The least verbose output that typically describes an unexpected condition prior to halting execution. It often provides more information about a user-facing error. @@ -27,7 +37,7 @@ The least verbose output that typically describes an unexpected condition prior tflog.Error(ctx, "Unrecognized API response body") ``` -### Warn +#### Warn Output that describes an unexpected condition, but not one that should halt execution. It often includes deprecations or environment issues. @@ -35,7 +45,7 @@ Output that describes an unexpected condition, but not one that should halt exec tflog.Warn(ctx, "Retrying due to API server-side error") ``` -### Info +#### Info Output that describes a certain logic condition or event. It often includes details about the environment your provider is running in or how it has been configured to run. @@ -43,7 +53,7 @@ Output that describes a certain logic condition or event. It often includes deta tflog.Info(ctx, "Using API token for authentication") ``` -### Debug +#### Debug Verbose output that typically describes important operational details like milestones in logic. It often describes behaviors that may confusing even though they are correct. @@ -51,7 +61,7 @@ Verbose output that typically describes important operational details like miles tflog.Debug(ctx, "Two identical diagnostics in the response, deduplicating down to one") ``` -### Trace +#### Trace The most verbose output that describes the lowest level operational details, such as intra-function steps or raw data. @@ -59,13 +69,13 @@ The most verbose output that describes the lowest level operational details, suc tflog.Trace(ctx, "Creating the widget") ``` -## Variables +### Fields -Use variables to attach information to specific logs or to an entire logger, which adds that information to all subsequent logs. You can also combine both methods to simplify your logging code. +Use fields to attach information to specific logs or to an entire logger, which adds that information to all subsequent logs. You can also combine both methods to simplify your logging code. -### Single Log Variables +#### Single Log Fields -To specify filterable variables in the log output, add a map of additional fields after the log message. +To specify filterable fields in the log output, add a map of additional fields after the log message. The following example adds both a URL and a method for an API request. @@ -88,7 +98,7 @@ tflog.Trace(ctx, "executing API request", map[string]interface{}{ }) ``` -### Multiple Log Variables +#### Multiple Log Fields Loggers are transported using a `context.Context` type, so injecting a variable into a logger returns a new `context.Context` containing the modified logger. Subsequent calls to `tflog` with that logger will implicitly include the variable. @@ -96,7 +106,7 @@ Use [`tflog.SetField()`](https://pkg.go.dev/github.com/hashicorp/terraform-plugi ```go // overwrite logger to include new `url` variable -ctx = tflog.With(ctx, "url", "https://www.example.com/my/endpoint") +ctx = tflog.SetField(ctx, "url", "https://www.example.com/my/endpoint") // will include the `url` variable tflog.Debug(ctx, "Calling API") @@ -106,7 +116,7 @@ You can also conditionally attach the variables by creating a new context and in ```go // create new logger that includes `url` variable -apiContext := tflog.With(ctx, "url", "https://www.example.com/my/endpoint") +apiContext := tflog.SetField(ctx, "url", "https://www.example.com/my/endpoint") // will not include the `url` variable tflog.Debug(ctx, "Calling database") @@ -115,11 +125,11 @@ tflog.Debug(ctx, "Calling database") tflog.Debug(apiContext, "Calling API") ``` -## Subsystems +### Subsystems You can create a subsystem to manage loggers for sections of code that are large, complex, or have distinct functionality. You can then configure environment variables that allow each subsystem to be included or excluded from log output. For example, you may want to create a subsystem for logs that relate to the API client so that you can turn them off when when debugging an unrelated issue. -### Create Subsystems +#### Create Subsystems To create a new subsystem, pass context and the subsystem name to the `NewSubsystem()` method. @@ -143,7 +153,7 @@ ctx = tflog.NewSubsystem(ctx, "my-subsystem", tflog.WithLevelFromEnv("TF_LOG_PROVIDER_MYPROVIDER_CLIENT")) ``` -### Use Subsystems +#### Use Subsystems Logging or adding variables to subsystem loggers requires separate function calls for each [log level](#log-levels): @@ -166,7 +176,7 @@ Use [`tflog.SubsystemSetField()`](https://pkg.go.dev/github.com/hashicorp/terraf ```go // overwrite logger to include new `url` variable -ctx = tflog.SubsystemWith(ctx, "my-subsystem", "url", "https://www.example.com/my/endpoint") +ctx = tflog.SubsystemSetField(ctx, "my-subsystem", "url", "https://www.example.com/my/endpoint") // will include the `url` variable tflog.SubsystemDebug(ctx, "my-subsystem", "Calling API") @@ -176,7 +186,7 @@ You can also conditionally attach variables by creating a new context and inject ```go // create new logger that includes `url` variable -apiContext := tflog.SubsystemWith(ctx, "my-subsystem", "url", "https://www.example.com/my/endpoint") +apiContext := tflog.SubsystemSetField(ctx, "my-subsystem", "url", "https://www.example.com/my/endpoint") // will not include the `url` variable tflog.SubsystemDebug(ctx, "my-subsystem", "Calling database") @@ -184,3 +194,86 @@ tflog.SubsystemDebug(ctx, "my-subsystem", "Calling database") // will include the `url` variable tflog.SubsystemDebug(apiContext, "my-subsystem", "Calling API") ``` + +## Legacy Logging + +Providers on older SDK versions should write logs via the Go standard library [`log` package](https://pkg.go.dev/log). Only a log level and message are supported. There is no support for fields, filtering, or subsystems. + +### Legacy Log Levels + +You must choose a verbosity level for each line of log output. This lets consumers [specify a type of log output](/plugin/log/managing#log-levels) to write from your provider. For example, you can use environment variables to set your provider to write only logs at the warning or higher level during a Terraform run. + +Terraform has specific message formatting requirements to properly set the log level when using the `log` package: + +```go +log.Printf("[LEVEL] MESSAGE") +``` + +#### Error + +The least verbose output that typically describes an unexpected condition prior to halting execution. It often provides more information about a user-facing error. + +```go +log.Printf("[ERROR] Unrecognized API response body") +``` + +#### Warn + +Output that describes an unexpected condition, but not one that should halt execution. It often includes deprecations or environment issues. + +```go +log.Printf("[WARN] Retrying due to API server-side error") +``` + +#### Info + +Output that describes a certain logic condition or event. It often includes details about the environment your provider is running in or how it has been configured to run. + +```go +log.Printf("[INFO] Using API token for authentication") +``` + +#### Debug + +Verbose output that typically describes important operational details like milestones in logic. It often describes behaviors that may confusing even though they are correct. + +```go +log.Printf("[DEBUG] Two identical diagnostics in the response, deduplicating down to one") +``` + +#### Trace + +The most verbose output that describes the lowest level operational details, such as intra-function steps or raw data. + +```go +log.Printf("[TRACE] Creating the widget") +``` + +### Legacy Log Troubleshooting + +#### Duplicate Timestamp and Incorrect Level Messages + +Using the `log` package for logging can generate messages that look like the following in the output from Terraform: + +``` +2022-01-26T16:25:33.123-0800 [INFO] provider.terraform-provider-example: 2022/01/26 16:25:33 [DEBUG] Example message +``` + +Resolve this by adjusting the `log` package to not include a timestamp prefix via the [`log.SetFlags()` function](https://pkg.go.dev/log#SetFlags) before the provider server starts. + +This example shows an updated `main.go` implementation for a `terraform-plugin-sdk` based provider: + +```go +func main() { + // ... potentially other provider server startup logic ... + + // Remove any date and time prefix in log package function output to + // prevent duplicate timestamp and incorrect log level setting + log.SetFlags(log.Flags() &^ (log.Ldate | log.Ltime)) + + // Start the provider server + plugin.Serve(/* ... */) +} +``` + +Also ensure the [`log.SetPrefix()` function](https://pkg.go.dev/log#SetPrefix) is not being used, as log messages must start with the `[LEVEL]` prefix. From 09d3829814cc437af22581e0baec213f01b74553 Mon Sep 17 00:00:00 2001 From: Brian Flad Date: Fri, 15 Jul 2022 11:55:20 -0400 Subject: [PATCH 2/3] website: Further standardize on field terminology over variable --- website/docs/plugin/log/writing.mdx | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/website/docs/plugin/log/writing.mdx b/website/docs/plugin/log/writing.mdx index 78c27c6..6e5bef1 100644 --- a/website/docs/plugin/log/writing.mdx +++ b/website/docs/plugin/log/writing.mdx @@ -6,13 +6,13 @@ description: >- # Writing Log Output -Use the [`tflog` package](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog) to write logs for your provider. SDKs like the `terraform-plugin-framework`, `terraform-plugin-go`, and `terraform-plugin-sdk/v2` set up logging for you, so you only need to write the logs themselves. You can write log output at varying verbosity levels, add variables to logs, and create subsystems to group logs that relate to distinct sections of code (e.g., the API client). +Use the [`tflog` package](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog) to write logs for your provider. SDKs like the `terraform-plugin-framework`, `terraform-plugin-go`, and `terraform-plugin-sdk/v2` set up logging for you, so you only need to write the logs themselves. You can write log output at varying verbosity levels, add fields to logs, and create subsystems to group logs that relate to distinct sections of code (e.g., the API client). !> **Warning:** Do not use `fmt.Println` and similar methods to log to standard output (stdout). They will not generate visible output in older versions of Terraform and are truncated in recent versions of Terraform. ## Structured Logging -The `tflog` package uses structured logging, based on [`go-hclog`](https://pkg.go.dev/github.com/hashicorp/go-hclog). Rather than writing logs as sentences with embedded variables and values, `tflog` takes a sentence describing the logging event and a set of variables to log. When variables are separate from the log description, you can use them to programmatically parse, filter, and search log output. This separation also allows other parts of the system to associate variables with downstream log output. +The `tflog` package uses structured logging, based on [`go-hclog`](https://pkg.go.dev/github.com/hashicorp/go-hclog). Rather than writing logs as sentences with embedded fields and values, `tflog` takes a sentence describing the logging event and a set of fields to log. When fields are separate from the log description, you can use them to programmatically parse, filter, and search log output. This separation also allows other parts of the system to associate fields with downstream log output. ### Requirements @@ -27,7 +27,7 @@ All calls to `tflog` package functionality must use an SDK provided `context.Con ### Log Levels -You must choose a verbosity level for each line of log output. This lets consumers [specify a type of log output](/plugin/log/managing#log-levels) to write from your provider. For example, you can use environment variables to set your provider to write only logs of type `Warn` during a Terraform run. +You must choose a verbosity level for each line of log output. This lets consumers [specify a type of log output](/plugin/log/managing#log-levels) to write from your provider. For example, you can use environment fields to set your provider to write only logs of type `Warn` during a Terraform run. #### Error @@ -102,7 +102,7 @@ tflog.Trace(ctx, "executing API request", map[string]interface{}{ Loggers are transported using a `context.Context` type, so injecting a variable into a logger returns a new `context.Context` containing the modified logger. Subsequent calls to `tflog` with that logger will implicitly include the variable. -Use [`tflog.SetField()`](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog#SetField) to attach variables to a logger. +Use [`tflog.SetField()`](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog#SetField) to attach fields to a logger. ```go // overwrite logger to include new `url` variable @@ -112,7 +112,7 @@ ctx = tflog.SetField(ctx, "url", "https://www.example.com/my/endpoint") tflog.Debug(ctx, "Calling API") ``` -You can also conditionally attach the variables by creating a new context and injecting it into the logger. +You can also conditionally attach the fields by creating a new context and injecting it into the logger. ```go // create new logger that includes `url` variable @@ -127,7 +127,7 @@ tflog.Debug(apiContext, "Calling API") ### Subsystems -You can create a subsystem to manage loggers for sections of code that are large, complex, or have distinct functionality. You can then configure environment variables that allow each subsystem to be included or excluded from log output. For example, you may want to create a subsystem for logs that relate to the API client so that you can turn them off when when debugging an unrelated issue. +You can create a subsystem to manage loggers for sections of code that are large, complex, or have distinct functionality. You can then configure environment fields that allow each subsystem to be included or excluded from log output. For example, you may want to create a subsystem for logs that relate to the API client so that you can turn them off when when debugging an unrelated issue. #### Create Subsystems @@ -155,7 +155,7 @@ ctx = tflog.NewSubsystem(ctx, "my-subsystem", #### Use Subsystems -Logging or adding variables to subsystem loggers requires separate function calls for each [log level](#log-levels): +Logging or adding fields to subsystem loggers requires separate function calls for each [log level](#log-levels): * [`tflog.SubsystemError()`](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog#SubsystemError): Equivalent to [`tflog.Error()`](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog#Error), but using a subsystem logger. * [`tflog.SubsystemWarn()`](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog#SubsystemWarn): Equivalent to [`tflog.Warn()`](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog#Warn), but using a subsystem logger. @@ -172,7 +172,7 @@ tflog.SubsystemDebug(ctx, "my-subsystem", "writing to a subsystem", map[string]i }) ``` -Use [`tflog.SubsystemSetField()`](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog#SubsystemSetField) to attach variables to a specific subsystem. +Use [`tflog.SubsystemSetField()`](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog#SubsystemSetField) to attach fields to a specific subsystem. ```go // overwrite logger to include new `url` variable @@ -182,7 +182,7 @@ ctx = tflog.SubsystemSetField(ctx, "my-subsystem", "url", "https://www.example.c tflog.SubsystemDebug(ctx, "my-subsystem", "Calling API") ``` -You can also conditionally attach variables by creating a new context and injecting it into the logger. +You can also conditionally attach fields by creating a new context and injecting it into the logger. ```go // create new logger that includes `url` variable @@ -201,7 +201,7 @@ Providers on older SDK versions should write logs via the Go standard library [` ### Legacy Log Levels -You must choose a verbosity level for each line of log output. This lets consumers [specify a type of log output](/plugin/log/managing#log-levels) to write from your provider. For example, you can use environment variables to set your provider to write only logs at the warning or higher level during a Terraform run. +You must choose a verbosity level for each line of log output. This lets consumers [specify a type of log output](/plugin/log/managing#log-levels) to write from your provider. For example, you can use environment fields to set your provider to write only logs at the warning or higher level during a Terraform run. Terraform has specific message formatting requirements to properly set the log level when using the `log` package: From 544c6b9acbfcea67bda419ca64efc93754d08990 Mon Sep 17 00:00:00 2001 From: Brian Flad Date: Fri, 15 Jul 2022 11:56:03 -0400 Subject: [PATCH 3/3] website: Further standardize on field terminology over variable --- website/docs/plugin/log/writing.mdx | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/website/docs/plugin/log/writing.mdx b/website/docs/plugin/log/writing.mdx index 6e5bef1..e4da4e6 100644 --- a/website/docs/plugin/log/writing.mdx +++ b/website/docs/plugin/log/writing.mdx @@ -100,28 +100,28 @@ tflog.Trace(ctx, "executing API request", map[string]interface{}{ #### Multiple Log Fields -Loggers are transported using a `context.Context` type, so injecting a variable into a logger returns a new `context.Context` containing the modified logger. Subsequent calls to `tflog` with that logger will implicitly include the variable. +Loggers are transported using a `context.Context` type, so injecting a field into a logger returns a new `context.Context` containing the modified logger. Subsequent calls to `tflog` with that logger will implicitly include the field. Use [`tflog.SetField()`](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog#SetField) to attach fields to a logger. ```go -// overwrite logger to include new `url` variable +// overwrite logger to include new `url` field ctx = tflog.SetField(ctx, "url", "https://www.example.com/my/endpoint") -// will include the `url` variable +// will include the `url` field tflog.Debug(ctx, "Calling API") ``` You can also conditionally attach the fields by creating a new context and injecting it into the logger. ```go -// create new logger that includes `url` variable +// create new logger that includes `url` field apiContext := tflog.SetField(ctx, "url", "https://www.example.com/my/endpoint") -// will not include the `url` variable +// will not include the `url` field tflog.Debug(ctx, "Calling database") -// will include the `url` variable +// will include the `url` field tflog.Debug(apiContext, "Calling API") ``` @@ -145,7 +145,7 @@ Optionally, specify a [log level](#log-levels) for the subsystem. ctx = tflog.NewSubsystem(ctx, "my-subsystem", hclog.Debug) ``` -You can also create an environment variable to control the logging level instead of hardcoding it into the subsystem. +You can also create an environment field to control the logging level instead of hardcoding it into the subsystem. ```go // read the level from TF_LOG_PROVIDER_MYPROVIDER_CLIENT @@ -175,23 +175,23 @@ tflog.SubsystemDebug(ctx, "my-subsystem", "writing to a subsystem", map[string]i Use [`tflog.SubsystemSetField()`](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log/tflog#SubsystemSetField) to attach fields to a specific subsystem. ```go -// overwrite logger to include new `url` variable +// overwrite logger to include new `url` field ctx = tflog.SubsystemSetField(ctx, "my-subsystem", "url", "https://www.example.com/my/endpoint") -// will include the `url` variable +// will include the `url` field tflog.SubsystemDebug(ctx, "my-subsystem", "Calling API") ``` You can also conditionally attach fields by creating a new context and injecting it into the logger. ```go -// create new logger that includes `url` variable +// create new logger that includes `url` field apiContext := tflog.SubsystemSetField(ctx, "my-subsystem", "url", "https://www.example.com/my/endpoint") -// will not include the `url` variable +// will not include the `url` field tflog.SubsystemDebug(ctx, "my-subsystem", "Calling database") -// will include the `url` variable +// will include the `url` field tflog.SubsystemDebug(apiContext, "my-subsystem", "Calling API") ```