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

Build in log sink functionality. #9

Merged
merged 5 commits into from
Sep 15, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
11 changes: 11 additions & 0 deletions .changelog/9.txt
Original file line number Diff line number Diff line change
@@ -0,0 +1,11 @@
```release-note:breaking-change
Provider log outputs now default to being named "provider" unless another name is provided.
```

```release-note:feature
Added a `tfsdklog.RegisterSink` function that will turn on a logging sink. When a logging sink is activated, all downstream provider and SDK loggers (i.e., all loggers created after `tfsdklog.RegisterSink` is called) will be sub-loggers of the sink. The sink respects the `TF_LOG` and `TF_LOG_PATH` environment variables, by default discards logs, and when `TF_LOG` is set writes to stderr. It is meant to replicate Terraform's log aggregation and filtering capabilities for test frameworks.
```

```release-note:feature
Added a `tfsdklog.PipeJSONLogs` function that can consume the JSON-formatted log output from Terraform and pipe it into the sink, allowing test frameworks to merge logs from the provider under test, the providers run by Terraform, and Terraform itself.
```
1 change: 1 addition & 0 deletions go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ module github.com/hashicorp/terraform-plugin-log
go 1.16

require (
github.com/google/go-cmp v0.5.6
github.com/hashicorp/go-hclog v0.16.1
github.com/stretchr/testify v1.3.0 // indirect
)
4 changes: 4 additions & 0 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,8 @@ github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c
github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
github.com/fatih/color v1.7.0 h1:DkWD4oS2D8LGGgTQ6IvwJJXSL5Vp2ffcQg58nFV38Ys=
github.com/fatih/color v1.7.0/go.mod h1:Zm6kSWBoL9eyXnKyktHP6abPY2pDugNf5KwzbycvMj4=
github.com/google/go-cmp v0.5.6 h1:BKbKCqvP6I+rmFHt06ZmyQtvB8xAkWdhFyr0ZUNZcxQ=
github.com/google/go-cmp v0.5.6/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
github.com/hashicorp/go-hclog v0.16.1 h1:IVQwpTGNRRIHafnTs2dQLIk4ENtneRIEEJWOVDqz99o=
github.com/hashicorp/go-hclog v0.16.1/go.mod h1:whpDNt7SSdeAju8AWKIWsul05p54N/39EeqMAyrmvFQ=
github.com/mattn/go-colorable v0.1.4 h1:snbPLB8fVfU9iwbbo30TPtbLRzwWu6aJS6Xh4eaaviA=
Expand All @@ -19,3 +21,5 @@ github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UV
golang.org/x/sys v0.0.0-20190222072716-a9d3bda3a223/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
golang.org/x/sys v0.0.0-20191008105621-543471e840be h1:QAcqgptGM8IQBC9K/RC4o+O9YmqEm0diQn9QmZw/0mU=
golang.org/x/sys v0.0.0-20191008105621-543471e840be/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543 h1:E7g+9GITq07hpfrRu66IVDexMakfv52eLZ2CXBWiKr4=
golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
12 changes: 6 additions & 6 deletions tflog/provider_example_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,7 @@ func ExampleWith() {
Trace(derivedCtx, "example log message")

// Output:
// {"@level":"trace","@message":"example log message","foo":123}
// {"@level":"trace","@message":"example log message","@module":"provider","foo":123}
}

func ExampleTrace() {
Expand All @@ -50,7 +50,7 @@ func ExampleTrace() {
Trace(exampleCtx, "hello, world", "foo", 123, "colors", []string{"red", "blue", "green"})

// Output:
// {"@level":"trace","@message":"hello, world","colors":["red","blue","green"],"foo":123}
// {"@level":"trace","@message":"hello, world","@module":"provider","colors":["red","blue","green"],"foo":123}
}

func ExampleDebug() {
Expand All @@ -67,7 +67,7 @@ func ExampleDebug() {
Debug(exampleCtx, "hello, world", "foo", 123, "colors", []string{"red", "blue", "green"})

// Output:
// {"@level":"debug","@message":"hello, world","colors":["red","blue","green"],"foo":123}
// {"@level":"debug","@message":"hello, world","@module":"provider","colors":["red","blue","green"],"foo":123}
}

func ExampleInfo() {
Expand All @@ -84,7 +84,7 @@ func ExampleInfo() {
Info(exampleCtx, "hello, world", "foo", 123, "colors", []string{"red", "blue", "green"})

// Output:
// {"@level":"info","@message":"hello, world","colors":["red","blue","green"],"foo":123}
// {"@level":"info","@message":"hello, world","@module":"provider","colors":["red","blue","green"],"foo":123}
}

func ExampleWarn() {
Expand All @@ -101,7 +101,7 @@ func ExampleWarn() {
Warn(exampleCtx, "hello, world", "foo", 123, "colors", []string{"red", "blue", "green"})

// Output:
// {"@level":"warn","@message":"hello, world","colors":["red","blue","green"],"foo":123}
// {"@level":"warn","@message":"hello, world","@module":"provider","colors":["red","blue","green"],"foo":123}
}

func ExampleError() {
Expand All @@ -118,5 +118,5 @@ func ExampleError() {
Error(exampleCtx, "hello, world", "foo", 123, "colors", []string{"red", "blue", "green"})

// Output:
// {"@level":"error","@message":"hello, world","colors":["red","blue","green"],"foo":123}
// {"@level":"error","@message":"hello, world","@module":"provider","colors":["red","blue","green"],"foo":123}
}
18 changes: 9 additions & 9 deletions tflog/subsystem_example_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,7 @@ func ExampleNewSubsystem() {
SubsystemTrace(subCtx, "my-subsystem", "hello, world", "foo", 123)

// Output:
// {"@level":"trace","@message":"hello, world","@module":"my-subsystem","foo":123}
// {"@level":"trace","@message":"hello, world","@module":"provider.my-subsystem","foo":123}
}

func ExampleNewSubsystem_withLevel() {
Expand Down Expand Up @@ -56,8 +56,8 @@ func ExampleNewSubsystem_withLevel() {
SubsystemWarn(subCtx, "my-subsystem", "hello, world", "foo", 123)

// Output:
// {"@level":"trace","@message":"hello, world","foo":123}
// {"@level":"warn","@message":"hello, world","@module":"my-subsystem","foo":123}
// {"@level":"trace","@message":"hello, world","@module":"provider","foo":123}
// {"@level":"warn","@message":"hello, world","@module":"provider.my-subsystem","foo":123}
}

func ExampleSubsystemWith() {
Expand All @@ -83,7 +83,7 @@ func ExampleSubsystemWith() {
SubsystemTrace(derivedCtx, "my-subsystem", "example log message")

// Output:
// {"@level":"trace","@message":"example log message","@module":"my-subsystem","foo":123}
// {"@level":"trace","@message":"example log message","@module":"provider.my-subsystem","foo":123}
}

func ExampleSubsystemTrace() {
Expand All @@ -103,7 +103,7 @@ func ExampleSubsystemTrace() {
SubsystemTrace(exampleCtx, "my-subsystem", "hello, world", "foo", 123, "colors", []string{"red", "blue", "green"})

// Output:
// {"@level":"trace","@message":"hello, world","@module":"my-subsystem","colors":["red","blue","green"],"foo":123}
// {"@level":"trace","@message":"hello, world","@module":"provider.my-subsystem","colors":["red","blue","green"],"foo":123}
}

func ExampleSubsystemDebug() {
Expand All @@ -123,7 +123,7 @@ func ExampleSubsystemDebug() {
SubsystemDebug(exampleCtx, "my-subsystem", "hello, world", "foo", 123, "colors", []string{"red", "blue", "green"})

// Output:
// {"@level":"debug","@message":"hello, world","@module":"my-subsystem","colors":["red","blue","green"],"foo":123}
// {"@level":"debug","@message":"hello, world","@module":"provider.my-subsystem","colors":["red","blue","green"],"foo":123}
}

func ExampleSubsystemInfo() {
Expand All @@ -143,7 +143,7 @@ func ExampleSubsystemInfo() {
SubsystemInfo(exampleCtx, "my-subsystem", "hello, world", "foo", 123, "colors", []string{"red", "blue", "green"})

// Output:
// {"@level":"info","@message":"hello, world","@module":"my-subsystem","colors":["red","blue","green"],"foo":123}
// {"@level":"info","@message":"hello, world","@module":"provider.my-subsystem","colors":["red","blue","green"],"foo":123}
}

func ExampleSubsystemWarn() {
Expand All @@ -163,7 +163,7 @@ func ExampleSubsystemWarn() {
SubsystemWarn(exampleCtx, "my-subsystem", "hello, world", "foo", 123, "colors", []string{"red", "blue", "green"})

// Output:
// {"@level":"warn","@message":"hello, world","@module":"my-subsystem","colors":["red","blue","green"],"foo":123}
// {"@level":"warn","@message":"hello, world","@module":"provider.my-subsystem","colors":["red","blue","green"],"foo":123}
}

func ExampleSubsystemError() {
Expand All @@ -183,5 +183,5 @@ func ExampleSubsystemError() {
SubsystemError(exampleCtx, "my-subsystem", "hello, world", "foo", 123, "colors", []string{"red", "blue", "green"})

// Output:
// {"@level":"error","@message":"hello, world","@module":"my-subsystem","colors":["red","blue","green"],"foo":123}
// {"@level":"error","@message":"hello, world","@module":"provider.my-subsystem","colors":["red","blue","green"],"foo":123}
}
37 changes: 37 additions & 0 deletions tfsdklog/cli.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,37 @@
package tfsdklog

import (
"context"
"fmt"
"os"
"strings"

"github.com/hashicorp/go-hclog"
)

// envLogCLI is the environment variable that users can set to control the
// least-verbose level of logs that will be forwarded from the CLI. These logs
// are a combination of the logs for the Terraform binary _and_ for the
// provider binaries that are not under test.
//
// Valid values are TRACE, DEBUG, INFO, WARN, ERROR, and OFF.
const envLogCLI = "TF_LOG_CLI"
paddycarver marked this conversation as resolved.
Show resolved Hide resolved

func newCLILogger(ctx context.Context, commandID string) hclog.Logger {
sink := getSink(ctx)
if sink == nil {
return nil
}
l := sink.Named("terraform")
envLevel := strings.ToUpper(os.Getenv(envLog))
if envLevel != "" {
if isValidLogLevel(envLevel) {
l.SetLevel(hclog.LevelFromString(envLevel))
} else {
fmt.Fprintf(os.Stderr, "[WARN] Invalid log level for %s: %q. Defaulting to %s level. Valid levels are: %+v",
envLogCLI, envLevel, envLog, ValidLevels)
}
}
l = l.With("command_id", commandID)
return l
}
23 changes: 20 additions & 3 deletions tfsdklog/sdk.go
Original file line number Diff line number Diff line change
Expand Up @@ -11,12 +11,19 @@ import (
// configured with the passed options.
func NewRootSDKLogger(ctx context.Context, options ...logging.Option) context.Context {
opts := logging.ApplyLoggerOpts(options...)
if opts.Level == hclog.NoLevel {
opts.Level = hclog.Trace
}
if opts.Name == "" {
opts.Name = "sdk"
}
if sink := getSink(ctx); sink != nil {
logger := sink.Named(opts.Name)
if opts.Level != hclog.NoLevel {
logger.SetLevel(opts.Level)
}
return logging.SetSDKRootLogger(ctx, logger)
}
if opts.Level == hclog.NoLevel {
opts.Level = hclog.Trace
}
loggerOptions := &hclog.LoggerOptions{
Name: opts.Name,
Level: opts.Level,
Expand All @@ -34,6 +41,16 @@ func NewRootSDKLogger(ctx context.Context, options ...logging.Option) context.Co
// logger configured with the passed options.
func NewRootProviderLogger(ctx context.Context, options ...logging.Option) context.Context {
opts := logging.ApplyLoggerOpts(options...)
if opts.Name == "" {
opts.Name = "provider"
}
if sink := getSink(ctx); sink != nil {
logger := sink.Named(opts.Name)
if opts.Level != hclog.NoLevel {
logger.SetLevel(opts.Level)
}
return logging.SetProviderRootLogger(ctx, logger)
}
if opts.Level == hclog.NoLevel {
opts.Level = hclog.Trace
}
Expand Down
111 changes: 111 additions & 0 deletions tfsdklog/sink.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,111 @@
package tfsdklog

import (
"context"
"fmt"
"io"
"os"
"strings"
"syscall"

"github.com/hashicorp/go-hclog"
"github.com/hashicorp/terraform-plugin-log/internal/logging"
)

const (
// envLog is the environment variable that users can set to control the
// least-verbose level of logs that will be output during testing. If
// this environment variable is set, it will default to off. This is
// just the default; specific loggers and sub-loggers can set a lower
// or higher verbosity level without a problem right now. In theory,
// they should not be able to.
paddycarver marked this conversation as resolved.
Show resolved Hide resolved
//
// Valid values are TRACE, DEBUG, INFO, WARN, ERROR, and OFF. A special
// pseudo-value, JSON, will set the value to TRACE and output the
// results in their JSON format.
envLog = "TF_LOG"

// envLogFile is the environment variable that controls where log
// output is written during tests. By default, logs will be written to
// standard error. Setting this environment variable to another file
// path will write logs there instead during tests.
envLogFile = "TF_LOG_PATH"
)

var sink hclog.Logger

func init() {
sink = newSink()
}

// ValidLevels are the string representations of levels that can be set for
// loggers.
var ValidLevels = []string{"TRACE", "DEBUG", "INFO", "WARN", "ERROR", "OFF"}
bflad marked this conversation as resolved.
Show resolved Hide resolved

func getSink(ctx context.Context) hclog.Logger {
logger := ctx.Value(logging.SinkKey)
if logger == nil {
return nil
}
return logger.(hclog.Logger)
}

// RegisterSink sets up a logging sink, for use with test frameworks and other
// cases where plugin logs don't get routed through Terraform. This applies the
// same filtering and file output behaviors that Terraform does.
//
// RegisterSink should only ever be called by test frameworks, providers should
// never call it.
//
// RegisterSink must be called prior to any loggers being setup or instantiated.
func RegisterSink(ctx context.Context) context.Context {
return context.WithValue(ctx, logging.SinkKey, sink)
}

func newSink() hclog.Logger {
logOutput := io.Writer(os.Stderr)
var json bool
var logLevel hclog.Level

// if TF_LOG_PATH is set, output logs there
if logPath := os.Getenv(envLogFile); logPath != "" {
f, err := os.OpenFile(logPath, syscall.O_CREAT|syscall.O_RDWR|syscall.O_APPEND, 0666)
if err != nil {
fmt.Fprintf(os.Stderr, "Error opening log file: %v\n", err)
} else {
logOutput = f
}
}

// if TF_LOG is set, set the level
envLevel := strings.ToUpper(os.Getenv(envLog))
if envLevel == "" {
logLevel = hclog.Off
}
if envLevel == "JSON" {
logLevel = hclog.Trace
json = true
} else if isValidLogLevel(envLevel) {
logLevel = hclog.LevelFromString(envLevel)
} else {
fmt.Fprintf(os.Stderr, "[WARN] Invalid log level: %q. Defaulting to level: OFF. Valid levels are: %+v",
envLevel, ValidLevels)
}

return hclog.New(&hclog.LoggerOptions{
Level: logLevel,
Output: logOutput,
IndependentLevels: true,
JSONFormat: json,
})
}

func isValidLogLevel(level string) bool {
for _, l := range ValidLevels {
if level == string(l) {
return true
}
}

return false
}
Loading