Build in log sink functionality.

.changelog/9.txt

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

go.mod

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

go.sum

@@ -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=
@@ -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=

tflog/provider_example_test.go

@@ -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() {
@@ -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() {
@@ -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() {
@@ -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() {
@@ -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() {
@@ -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}
 }

tflog/subsystem_example_test.go

@@ -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() {
@@ -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() {
@@ -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() {
@@ -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() {
@@ -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() {
@@ -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() {
@@ -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() {
@@ -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}
 }

tfsdklog/cli.go

@@ -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"
+
+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
+}

tfsdklog/sdk.go

@@ -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,
@@ -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
 	}

tfsdklog/sink.go

@@ -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.
+	//
+	// 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"}
+
+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
+}