Skip to content

Commit

Permalink
Build in log sink functionality.
Browse files Browse the repository at this point in the history
Starting to address #6. This is just the start of the work, but it gives
us something to build on.

Basically, what we're trying to do is build log sink functionality into
terraform-plugin-log. Normally, Terraform acts as a log sink, gathering
up logs from core and from all the plugins, filtering them
appropriately, and combining them into a single log output stream, and
deciding where to send that stream. However, when running acceptance
tests, the plugin is actually the longest-running process, and so this
model breaks down. Instead, we need to have the plugin act as the sink,
gathering the logs from core and the plugin and other plugins, combining
them into a single stream, filtering the stream, and deciding where to
output the stream.

Rather than implement this functionality multiple times in different
SDKs, it makes more sense to add it to the tfsdklog package and just
call it from the test frameworks.

There are a few parts to this. First, we need a new sink logger that all
other loggers are derived from. It should read environment variables to
determine what level of output is desired, what format of output is
desired, and where to send that output. Second, we should make all our
loggers be sub-loggers of that sink when the sink is set. Third, we
should make sure our sub-loggers can only log at levels equal to or
higher than the level of this new sink logger when it's set. And
finally, we should provide functionality to process hclog JSON output
(like from terraform when TF_LOG=json) and route it through this sink
logger, so we can combine the log output of the CLI and other providers
with the log output native to the process.

This commit falls short in a few places:

* sub-loggers aren't limited to equal-or-higher levels from the sink
  logger yet.
* none of this has been tested, even manually. It builds?
* we need to check that all the environment variables we need to be
  honoring are getting honored for the provider under test, the CLI, and
  the providers the CLI launches.

This depends on #10.
  • Loading branch information
paddycarver committed Sep 4, 2021
1 parent 49f4619 commit a65b7d5
Show file tree
Hide file tree
Showing 6 changed files with 324 additions and 18 deletions.
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}
}
31 changes: 31 additions & 0 deletions tfsdklog/cli.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,31 @@
package tfsdklog

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

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

const envLogCLI = "TF_LOG_CLI"

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.SetProviderSpaceRootLogger(ctx, logger)
}
if opts.Level == hclog.NoLevel {
opts.Level = hclog.Trace
}
Expand Down
96 changes: 96 additions & 0 deletions tfsdklog/sink.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,96 @@
package tfsdklog

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

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

const (
envLog = "TF_LOG"
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"}

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

0 comments on commit a65b7d5

Please sign in to comment.