Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

website: Add tflog requirements section and legacy logging section #80

Merged
merged 3 commits into from Jul 15, 2022
Merged
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
175 changes: 134 additions & 41 deletions website/docs/plugin/log/writing.mdx
Expand Up @@ -6,66 +6,76 @@ 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).

!> **Warning:** Do not use `fmt.Println` and similar methods to log. They will silently fail, making the output unavailable.
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

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

## Log Levels
Follow the [legacy logging](#legacy-logging) instructions to write logs with older versions.

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

### Error
### 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 fields to set your provider to write only logs of type `Warn` during a Terraform run.

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

```go
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.

```go
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.

```go
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.

```go
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.

Expand All @@ -88,38 +98,38 @@ 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.
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 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
ctx = tflog.With(ctx, "url", "https://www.example.com/my/endpoint")
// 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 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
apiContext := tflog.With(ctx, "url", "https://www.example.com/my/endpoint")
// 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")
```

## 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.
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
#### Create Subsystems

To create a new subsystem, pass context and the subsystem name to the `NewSubsystem()` method.

Expand All @@ -135,17 +145,17 @@ 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
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):
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.
Expand All @@ -162,25 +172,108 @@ 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
ctx = tflog.SubsystemWith(ctx, "my-subsystem", "url", "https://www.example.com/my/endpoint")
// 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 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
apiContext := tflog.SubsystemWith(ctx, "my-subsystem", "url", "https://www.example.com/my/endpoint")
// 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")
```

## 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 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:

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