diff --git a/.changelog/36.txt b/.changelog/36.txt new file mode 100644 index 0000000..579eb19 --- /dev/null +++ b/.changelog/36.txt @@ -0,0 +1,7 @@ +```release-note:enhancement +tflog: Added `WithAdditionalLocationOffset` function, which allows implementations to adjust the location offset when using helper functions +``` + +```release-note:enhancement +tfsdklog: Added `WithAdditionalLocationOffset` function, which allows implementations to adjust the location offset when using helper functions +``` diff --git a/internal/hclogutils/logger_options.go b/internal/hclogutils/logger_options.go new file mode 100644 index 0000000..a0ec34e --- /dev/null +++ b/internal/hclogutils/logger_options.go @@ -0,0 +1,29 @@ +package hclogutils + +import ( + "github.com/hashicorp/go-hclog" +) + +// LoggerOptionsCopy will safely copy LoggerOptions. Manually implemented +// to save importing a dependency such as github.com/mitchellh/copystructure. +func LoggerOptionsCopy(src *hclog.LoggerOptions) *hclog.LoggerOptions { + if src == nil { + return nil + } + + return &hclog.LoggerOptions{ + AdditionalLocationOffset: src.AdditionalLocationOffset, + Color: src.Color, + DisableTime: src.DisableTime, + Exclude: src.Exclude, + IncludeLocation: src.IncludeLocation, + IndependentLevels: src.IndependentLevels, + JSONFormat: src.JSONFormat, + Level: src.Level, + Mutex: src.Mutex, + Name: src.Name, + Output: src.Output, + TimeFormat: src.TimeFormat, + TimeFn: src.TimeFn, + } +} diff --git a/internal/loggertest/provider.go b/internal/loggertest/provider.go index db68484..35765f1 100644 --- a/internal/loggertest/provider.go +++ b/internal/loggertest/provider.go @@ -4,19 +4,27 @@ import ( "context" "io" - "github.com/hashicorp/go-hclog" "github.com/hashicorp/terraform-plugin-log/internal/logging" + "github.com/hashicorp/terraform-plugin-log/tfsdklog" ) func ProviderRoot(ctx context.Context, output io.Writer) context.Context { - loggerOptions := &hclog.LoggerOptions{ - DisableTime: true, - JSONFormat: true, - Level: hclog.Trace, - Output: output, - } - - ctx = logging.SetProviderRootLogger(ctx, hclog.New(loggerOptions)) + return tfsdklog.NewRootProviderLogger( + ctx, + logging.WithoutLocation(), + logging.WithoutTimestamp(), + logging.WithOutput(output), + ) +} - return ctx +// ProviderRootWithLocation is for testing code that affects go-hclog's caller +// information (location offset). Most testing code should avoid this, since +// correctly checking differences including the location is extra effort +// with little benefit. +func ProviderRootWithLocation(ctx context.Context, output io.Writer) context.Context { + return tfsdklog.NewRootProviderLogger( + ctx, + logging.WithoutTimestamp(), + logging.WithOutput(output), + ) } diff --git a/internal/loggertest/sdk.go b/internal/loggertest/sdk.go index 769cf75..f16da6e 100644 --- a/internal/loggertest/sdk.go +++ b/internal/loggertest/sdk.go @@ -4,19 +4,27 @@ import ( "context" "io" - "github.com/hashicorp/go-hclog" "github.com/hashicorp/terraform-plugin-log/internal/logging" + "github.com/hashicorp/terraform-plugin-log/tfsdklog" ) func SDKRoot(ctx context.Context, output io.Writer) context.Context { - loggerOptions := &hclog.LoggerOptions{ - DisableTime: true, - JSONFormat: true, - Level: hclog.Trace, - Output: output, - } - - ctx = logging.SetSDKRootLogger(ctx, hclog.New(loggerOptions)) + return tfsdklog.NewRootSDKLogger( + ctx, + logging.WithoutLocation(), + logging.WithoutTimestamp(), + logging.WithOutput(output), + ) +} - return ctx +// SDKRootWithLocation is for testing code that affects go-hclog's caller +// information (location offset). Most testing code should avoid this, since +// correctly checking differences including the location is extra effort +// with little benefit. +func SDKRootWithLocation(ctx context.Context, output io.Writer) context.Context { + return tfsdklog.NewRootSDKLogger( + ctx, + logging.WithoutTimestamp(), + logging.WithOutput(output), + ) } diff --git a/internal/logging/log.go b/internal/logging/log.go index 8c0ef20..3e847b4 100644 --- a/internal/logging/log.go +++ b/internal/logging/log.go @@ -5,6 +5,14 @@ import ( "os" ) +const ( + // Default provider root logger name. + DefaultProviderRootLoggerName string = "provider" + + // Default SDK root logger name. + DefaultSDKRootLoggerName string = "sdk" +) + // loggerKey defines context keys for locating loggers in context.Context // it's a private type to make sure no other packages can override the key type loggerKey string @@ -14,10 +22,22 @@ const ( // logger for writing logs from within provider code. ProviderRootLoggerKey loggerKey = "provider" + // ProviderRootLoggerOptionsKey is the loggerKey that will hold the root + // logger options when the root provider logger is created. This is to + // assist creating subsystem loggers, as most options cannot be fetched and + // a logger does not provide set methods for these options. + ProviderRootLoggerOptionsKey loggerKey = "provider-options" + // SDKRootLoggerKey is the loggerKey that will hold the root logger for // writing logs from with SDKs. SDKRootLoggerKey loggerKey = "sdk" + // SDKRootLoggerOptionsKey is the loggerKey that will hold the root + // logger options when the SDK provider logger is created. This is to + // assist creating subsystem loggers, as most options cannot be fetched and + // a logger does not provide set methods for these options. + SDKRootLoggerOptionsKey loggerKey = "sdk-options" + // SinkKey is the loggerKey that will hold the logging sink used for // test frameworks. SinkKey loggerKey = "" diff --git a/internal/logging/options.go b/internal/logging/options.go index fe1e076..bf8cc45 100644 --- a/internal/logging/options.go +++ b/internal/logging/options.go @@ -22,6 +22,11 @@ type LoggerOpts struct { // of the logging statement or not. IncludeLocation bool + // AdditionalLocationOffset is the number of additional stack levels to + // skip when finding the file and line information for the log line. + // Defaults to 1 to account for the tflog and tfsdklog logging functions. + AdditionalLocationOffset int + // Output dictates where logs are written to. Output should only ever // be set by tflog or tfsdklog, never by SDK authors or provider // developers. Where logs get written to is complex and delicate and @@ -37,14 +42,15 @@ type LoggerOpts struct { } // ApplyLoggerOpts generates a LoggerOpts out of a list of Option -// implementations. By default, IncludeLocation is true, IncludeTime is true, -// and Output is os.Stderr. +// implementations. By default, AdditionalLocationOffset is 1, IncludeLocation +// is true, IncludeTime is true, and Output is os.Stderr. func ApplyLoggerOpts(opts ...Option) LoggerOpts { // set some defaults l := LoggerOpts{ - IncludeLocation: true, - IncludeTime: true, - Output: os.Stderr, + AdditionalLocationOffset: 1, + IncludeLocation: true, + IncludeTime: true, + Output: os.Stderr, } for _, opt := range opts { l = opt(l) @@ -52,6 +58,18 @@ func ApplyLoggerOpts(opts ...Option) LoggerOpts { return l } +// WithAdditionalLocationOffset sets the WithAdditionalLocationOffset +// configuration option, allowing implementations to fix location information +// when implementing helper functions. The default offset of 1 is automatically +// added to the provided value to account for the tflog and tfsdk logging +// functions. +func WithAdditionalLocationOffset(additionalLocationOffset int) Option { + return func(l LoggerOpts) LoggerOpts { + l.AdditionalLocationOffset = additionalLocationOffset + 1 + return l + } +} + // WithOutput sets the Output configuration option, controlling where logs get // written to. This is mostly used for testing (to write to os.Stdout, so the // test framework can compare it against the example output) and as a helper @@ -63,6 +81,16 @@ func WithOutput(output io.Writer) Option { } } +// WithoutLocation disables the location included with logging statements. It +// should only ever be used to make log output deterministic when testing +// terraform-plugin-log. +func WithoutLocation() Option { + return func(l LoggerOpts) LoggerOpts { + l.IncludeLocation = false + return l + } +} + // WithoutTimestamp disables the timestamp included with logging statements. It // should only ever be used to make log output deterministic when testing // terraform-plugin-log. diff --git a/internal/logging/provider.go b/internal/logging/provider.go index 897393c..b40a12f 100644 --- a/internal/logging/provider.go +++ b/internal/logging/provider.go @@ -16,12 +16,41 @@ func GetProviderRootLogger(ctx context.Context) hclog.Logger { return logger.(hclog.Logger) } +// GetProviderRootLoggerOptions returns the root logger options used for +// creating the root provider logger. If the root logger has not been created +// or the options are not present, it will return nil. +func GetProviderRootLoggerOptions(ctx context.Context) *hclog.LoggerOptions { + if GetProviderRootLogger(ctx) == nil { + return nil + } + + loggerOptionsRaw := ctx.Value(ProviderRootLoggerOptionsKey) + + if loggerOptionsRaw == nil { + return nil + } + + loggerOptions, ok := loggerOptionsRaw.(*hclog.LoggerOptions) + + if !ok { + return nil + } + + return loggerOptions +} + // SetProviderRootLogger sets `logger` as the root logger used for writing // logs from a provider. func SetProviderRootLogger(ctx context.Context, logger hclog.Logger) context.Context { return context.WithValue(ctx, ProviderRootLoggerKey, logger) } +// SetProviderRootLoggerOptions sets `loggerOptions` as the root logger options +// used for creating the provider root logger. +func SetProviderRootLoggerOptions(ctx context.Context, loggerOptions *hclog.LoggerOptions) context.Context { + return context.WithValue(ctx, ProviderRootLoggerOptionsKey, loggerOptions) +} + // NewProviderSubsystemLoggerWarning is the text included in log output when a // subsystem is auto-generated by terraform-plugin-log because it was used // before the provider instantiated it. diff --git a/internal/logging/sdk.go b/internal/logging/sdk.go index 99c577a..3c6772b 100644 --- a/internal/logging/sdk.go +++ b/internal/logging/sdk.go @@ -16,12 +16,41 @@ func GetSDKRootLogger(ctx context.Context) hclog.Logger { return logger.(hclog.Logger) } +// GetSDKRootLoggerOptions returns the root logger options used for +// creating the root SDK logger. If the root logger has not been created or +// the options are not present, it will return nil. +func GetSDKRootLoggerOptions(ctx context.Context) *hclog.LoggerOptions { + if GetSDKRootLogger(ctx) == nil { + return nil + } + + loggerOptionsRaw := ctx.Value(SDKRootLoggerOptionsKey) + + if loggerOptionsRaw == nil { + return nil + } + + loggerOptions, ok := loggerOptionsRaw.(*hclog.LoggerOptions) + + if !ok { + return nil + } + + return loggerOptions +} + // SetSDKRootLogger sets `logger` as the root logger used for writing logs from // an SDK. func SetSDKRootLogger(ctx context.Context, logger hclog.Logger) context.Context { return context.WithValue(ctx, SDKRootLoggerKey, logger) } +// SetSDKRootLoggerOptions sets `loggerOptions` as the root logger options +// used for creating the SDK root logger. +func SetSDKRootLoggerOptions(ctx context.Context, loggerOptions *hclog.LoggerOptions) context.Context { + return context.WithValue(ctx, SDKRootLoggerOptionsKey, loggerOptions) +} + // NewSDKSubsystemLoggerWarning is the text included in log output when a // subsystem is auto-generated by terraform-plugin-log because it was used // before the SDK instantiated it. diff --git a/tflog/options.go b/tflog/options.go index 1b61eb5..9a00bc6 100644 --- a/tflog/options.go +++ b/tflog/options.go @@ -12,6 +12,14 @@ import ( // to NewSubsystem prior to calling it. type Options []logging.Option +// WithAdditionalLocationOffset returns an option that allowing implementations +// to fix location information when implementing helper functions. The default +// offset of 1 is automatically added to the provided value to account for the +// tflog logging functions. +func WithAdditionalLocationOffset(additionalLocationOffset int) logging.Option { + return logging.WithAdditionalLocationOffset(additionalLocationOffset) +} + // WithLevelFromEnv returns an option that will set the level of the logger // based on the string in an environment variable. The environment variable // checked will be `name` and `subsystems`, joined by _ and in all caps. diff --git a/tflog/options_test.go b/tflog/options_test.go new file mode 100644 index 0000000..cee5074 --- /dev/null +++ b/tflog/options_test.go @@ -0,0 +1,122 @@ +package tflog_test + +import ( + "bytes" + "context" + "strings" + "testing" + + "github.com/google/go-cmp/cmp" + "github.com/hashicorp/go-hclog" + "github.com/hashicorp/terraform-plugin-log/internal/loggertest" + "github.com/hashicorp/terraform-plugin-log/tflog" +) + +func testSubsystemTraceHelper(ctx context.Context, message string) { + tflog.SubsystemTrace(ctx, testSubsystem, message) +} + +func TestWithAdditionalLocationOffset(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + additionalLocationOffset int + logImpl func(context.Context) + expectedOutput []map[string]interface{} + }{ + "0-no-helper": { + additionalLocationOffset: 0, + logImpl: func(ctx context.Context) { + tflog.SubsystemTrace(ctx, testSubsystem, "test message") + }, + expectedOutput: []map[string]interface{}{ + { + // Caller line (number after colon) should match + // tflog.SubsystemTrace() line in test case implementation. + "@caller": "/tflog/options_test.go:30", + "@level": hclog.Trace.String(), + "@message": "test message", + "@module": testSubsystemModule, + }, + }, + }, + "0-one-helper": { + additionalLocationOffset: 0, + logImpl: func(ctx context.Context) { + testSubsystemTraceHelper(ctx, "test message") + }, + expectedOutput: []map[string]interface{}{ + { + // Caller line (number after colon) should match + // tflog.SubsystemTrace() line in testSubsystemTraceHelper + // function implementation. + "@caller": "/tflog/options_test.go:16", + "@level": hclog.Trace.String(), + "@message": "test message", + "@module": testSubsystemModule, + }, + }, + }, + "1-one-helper": { + additionalLocationOffset: 1, + logImpl: func(ctx context.Context) { + testSubsystemTraceHelper(ctx, "test message") + }, + expectedOutput: []map[string]interface{}{ + { + // Caller line (number after colon) should match + // testSubsystemTraceHelper() line in test case + // implementation. + "@caller": "/tflog/options_test.go:63", + "@level": hclog.Trace.String(), + "@message": "test message", + "@module": testSubsystemModule, + }, + }, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + var outputBuffer bytes.Buffer + + ctx := context.Background() + ctx = loggertest.ProviderRootWithLocation(ctx, &outputBuffer) + ctx = tflog.NewSubsystem(ctx, testSubsystem, tflog.WithAdditionalLocationOffset(testCase.additionalLocationOffset)) + + testCase.logImpl(ctx) + + got, err := loggertest.MultilineJSONDecode(&outputBuffer) + + if err != nil { + t.Fatalf("unable to read multiple line JSON: %s", err) + } + + // Strip non-deterministic caller information up to this package, e.g. + // /Users/example/src/github.com/hashicorp/terraform-plugin-log/tflog/... + for _, gotEntry := range got { + caller, ok := gotEntry["@caller"].(string) + + if !ok { + continue + } + + packageIndex := strings.Index(caller, "/tflog/") + + if packageIndex == -1 { + continue + } + + gotEntry["@caller"] = caller[packageIndex:] + } + + if diff := cmp.Diff(testCase.expectedOutput, got); diff != "" { + t.Errorf("unexpected output difference: %s", diff) + } + }) + } +} diff --git a/tflog/provider_test.go b/tflog/provider_test.go index b7ab91c..72af639 100644 --- a/tflog/provider_test.go +++ b/tflog/provider_test.go @@ -29,6 +29,7 @@ func TestWith(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", + "@module": "provider", "test-with-key": "test-with-value", }, }, @@ -40,6 +41,7 @@ func TestWith(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", + "@module": "provider", "unfielded-test-with-key": nil, }, }, @@ -59,6 +61,7 @@ func TestWith(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", + "@module": "provider", "test-log-key-1": "test-log-value-1", "test-log-key-2": "test-log-value-2", "test-log-key-3": "test-log-value-3", @@ -109,6 +112,7 @@ func TestTrace(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", + "@module": "provider", }, }, }, @@ -125,6 +129,7 @@ func TestTrace(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", + "@module": "provider", "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -149,6 +154,7 @@ func TestTrace(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", + "@module": "provider", "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -199,6 +205,7 @@ func TestDebug(t *testing.T) { { "@level": hclog.Debug.String(), "@message": "test message", + "@module": "provider", }, }, }, @@ -215,6 +222,7 @@ func TestDebug(t *testing.T) { { "@level": hclog.Debug.String(), "@message": "test message", + "@module": "provider", "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -239,6 +247,7 @@ func TestDebug(t *testing.T) { { "@level": hclog.Debug.String(), "@message": "test message", + "@module": "provider", "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -289,6 +298,7 @@ func TestInfo(t *testing.T) { { "@level": hclog.Info.String(), "@message": "test message", + "@module": "provider", }, }, }, @@ -305,6 +315,7 @@ func TestInfo(t *testing.T) { { "@level": hclog.Info.String(), "@message": "test message", + "@module": "provider", "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -329,6 +340,7 @@ func TestInfo(t *testing.T) { { "@level": hclog.Info.String(), "@message": "test message", + "@module": "provider", "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -379,6 +391,7 @@ func TestWarn(t *testing.T) { { "@level": hclog.Warn.String(), "@message": "test message", + "@module": "provider", }, }, }, @@ -395,6 +408,7 @@ func TestWarn(t *testing.T) { { "@level": hclog.Warn.String(), "@message": "test message", + "@module": "provider", "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -419,6 +433,7 @@ func TestWarn(t *testing.T) { { "@level": hclog.Warn.String(), "@message": "test message", + "@module": "provider", "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -469,6 +484,7 @@ func TestError(t *testing.T) { { "@level": hclog.Error.String(), "@message": "test message", + "@module": "provider", }, }, }, @@ -485,6 +501,7 @@ func TestError(t *testing.T) { { "@level": hclog.Error.String(), "@message": "test message", + "@module": "provider", "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -509,6 +526,7 @@ func TestError(t *testing.T) { { "@level": hclog.Error.String(), "@message": "test message", + "@module": "provider", "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", diff --git a/tflog/subsystem.go b/tflog/subsystem.go index 4da8df7..a37cfc3 100644 --- a/tflog/subsystem.go +++ b/tflog/subsystem.go @@ -18,9 +18,10 @@ import ( // at other times. // // The only Options supported for subsystems are the Options for setting the -// level of the logger. +// level and additional location offset of the logger. func NewSubsystem(ctx context.Context, subsystem string, options ...logging.Option) context.Context { logger := logging.GetProviderRootLogger(ctx) + if logger == nil { // this essentially should never happen in production // the root logger for provider code should be injected @@ -29,12 +30,40 @@ func NewSubsystem(ctx context.Context, subsystem string, options ...logging.Opti // so just making this a no-op is fine return ctx } - subLogger := logger.Named(subsystem) + + loggerOptions := logging.GetProviderRootLoggerOptions(ctx) opts := logging.ApplyLoggerOpts(options...) + + // On the off-chance that the logger options are not available, fallback + // to creating a named logger. This will preserve the root logger options, + // but cannot make changes beyond the level due to the hclog.Logger + // interface. + if loggerOptions == nil { + subLogger := logger.Named(subsystem) + + if opts.AdditionalLocationOffset != 1 { + logger.Warn("Unable to create logging subsystem with AdditionalLocationOffset due to missing root logger options") + } + + if opts.Level != hclog.NoLevel { + subLogger.SetLevel(opts.Level) + } + + return logging.SetProviderSubsystemLogger(ctx, subsystem, subLogger) + } + + subLoggerOptions := hclogutils.LoggerOptionsCopy(loggerOptions) + subLoggerOptions.Name = subLoggerOptions.Name + "." + subsystem + + if opts.AdditionalLocationOffset != 1 { + subLoggerOptions.AdditionalLocationOffset = opts.AdditionalLocationOffset + } + if opts.Level != hclog.NoLevel { - subLogger.SetLevel(opts.Level) + subLoggerOptions.Level = opts.Level } - return logging.SetProviderSubsystemLogger(ctx, subsystem, subLogger) + + return logging.SetProviderSubsystemLogger(ctx, subsystem, hclog.New(subLoggerOptions)) } // SubsystemWith returns a new context.Context that has a modified logger for diff --git a/tflog/subsystem_test.go b/tflog/subsystem_test.go index a352ab9..e64fd88 100644 --- a/tflog/subsystem_test.go +++ b/tflog/subsystem_test.go @@ -11,7 +11,10 @@ import ( "github.com/hashicorp/terraform-plugin-log/tflog" ) -const testSubsystem = "test_subsystem" +const ( + testSubsystem = "test_subsystem" + testSubsystemModule = "provider." + testSubsystem +) func TestSubsystemWith(t *testing.T) { t.Parallel() @@ -31,7 +34,7 @@ func TestSubsystemWith(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-with-key": "test-with-value", }, }, @@ -43,7 +46,7 @@ func TestSubsystemWith(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "unfielded-test-with-key": nil, }, }, @@ -63,7 +66,7 @@ func TestSubsystemWith(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-log-key-1": "test-log-value-1", "test-log-key-2": "test-log-value-2", "test-log-key-3": "test-log-value-3", @@ -115,7 +118,7 @@ func TestSubsystemTrace(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, }, }, }, @@ -132,7 +135,7 @@ func TestSubsystemTrace(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -157,7 +160,7 @@ func TestSubsystemTrace(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -209,7 +212,7 @@ func TestSubsystemDebug(t *testing.T) { { "@level": hclog.Debug.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, }, }, }, @@ -226,7 +229,7 @@ func TestSubsystemDebug(t *testing.T) { { "@level": hclog.Debug.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -251,7 +254,7 @@ func TestSubsystemDebug(t *testing.T) { { "@level": hclog.Debug.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -303,7 +306,7 @@ func TestSubsystemInfo(t *testing.T) { { "@level": hclog.Info.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, }, }, }, @@ -320,7 +323,7 @@ func TestSubsystemInfo(t *testing.T) { { "@level": hclog.Info.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -345,7 +348,7 @@ func TestSubsystemInfo(t *testing.T) { { "@level": hclog.Info.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -397,7 +400,7 @@ func TestSubsystemWarn(t *testing.T) { { "@level": hclog.Warn.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, }, }, }, @@ -414,7 +417,7 @@ func TestSubsystemWarn(t *testing.T) { { "@level": hclog.Warn.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -439,7 +442,7 @@ func TestSubsystemWarn(t *testing.T) { { "@level": hclog.Warn.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -491,7 +494,7 @@ func TestSubsystemError(t *testing.T) { { "@level": hclog.Error.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, }, }, }, @@ -508,7 +511,7 @@ func TestSubsystemError(t *testing.T) { { "@level": hclog.Error.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -533,7 +536,7 @@ func TestSubsystemError(t *testing.T) { { "@level": hclog.Error.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", diff --git a/tfsdklog/options.go b/tfsdklog/options.go index 2115bab..e36742e 100644 --- a/tfsdklog/options.go +++ b/tfsdklog/options.go @@ -13,6 +13,14 @@ import ( // them. type Options []logging.Option +// WithAdditionalLocationOffset returns an option that allowing implementations +// to fix location information when implementing helper functions. The default +// offset of 1 is automatically added to the provided value to account for the +// tfsdklog logging functions. +func WithAdditionalLocationOffset(additionalLocationOffset int) logging.Option { + return logging.WithAdditionalLocationOffset(additionalLocationOffset) +} + // WithLogName returns an option that will set the logger name explicitly to // `name`. This has no effect when used with NewSubsystem. func WithLogName(name string) logging.Option { diff --git a/tfsdklog/options_test.go b/tfsdklog/options_test.go new file mode 100644 index 0000000..34257f3 --- /dev/null +++ b/tfsdklog/options_test.go @@ -0,0 +1,122 @@ +package tfsdklog_test + +import ( + "bytes" + "context" + "strings" + "testing" + + "github.com/google/go-cmp/cmp" + "github.com/hashicorp/go-hclog" + "github.com/hashicorp/terraform-plugin-log/internal/loggertest" + "github.com/hashicorp/terraform-plugin-log/tfsdklog" +) + +func testSubsystemTraceHelper(ctx context.Context, message string) { + tfsdklog.SubsystemTrace(ctx, testSubsystem, message) +} + +func TestWithAdditionalLocationOffset(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + additionalLocationOffset int + logImpl func(context.Context) + expectedOutput []map[string]interface{} + }{ + "0-no-helper": { + additionalLocationOffset: 0, + logImpl: func(ctx context.Context) { + tfsdklog.SubsystemTrace(ctx, testSubsystem, "test message") + }, + expectedOutput: []map[string]interface{}{ + { + // Caller line (number after colon) should match + // tfsdklog.SubsystemTrace() line in test case implementation. + "@caller": "/tfsdklog/options_test.go:30", + "@level": hclog.Trace.String(), + "@message": "test message", + "@module": testSubsystemModule, + }, + }, + }, + "0-one-helper": { + additionalLocationOffset: 0, + logImpl: func(ctx context.Context) { + testSubsystemTraceHelper(ctx, "test message") + }, + expectedOutput: []map[string]interface{}{ + { + // Caller line (number after colon) should match + // tfsdklog.SubsystemTrace() line in testSubsystemTraceHelper + // function implementation. + "@caller": "/tfsdklog/options_test.go:16", + "@level": hclog.Trace.String(), + "@message": "test message", + "@module": testSubsystemModule, + }, + }, + }, + "1-one-helper": { + additionalLocationOffset: 1, + logImpl: func(ctx context.Context) { + testSubsystemTraceHelper(ctx, "test message") + }, + expectedOutput: []map[string]interface{}{ + { + // Caller line (number after colon) should match + // testSubsystemTraceHelper() line in test case + // implementation. + "@caller": "/tfsdklog/options_test.go:63", + "@level": hclog.Trace.String(), + "@message": "test message", + "@module": testSubsystemModule, + }, + }, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + var outputBuffer bytes.Buffer + + ctx := context.Background() + ctx = loggertest.SDKRootWithLocation(ctx, &outputBuffer) + ctx = tfsdklog.NewSubsystem(ctx, testSubsystem, tfsdklog.WithAdditionalLocationOffset(testCase.additionalLocationOffset)) + + testCase.logImpl(ctx) + + got, err := loggertest.MultilineJSONDecode(&outputBuffer) + + if err != nil { + t.Fatalf("unable to read multiple line JSON: %s", err) + } + + // Strip non-deterministic caller information up to this package, e.g. + // /Users/example/src/github.com/hashicorp/terraform-plugin-log/tfsdklog/... + for _, gotEntry := range got { + caller, ok := gotEntry["@caller"].(string) + + if !ok { + continue + } + + packageIndex := strings.Index(caller, "/tfsdklog/") + + if packageIndex == -1 { + continue + } + + gotEntry["@caller"] = caller[packageIndex:] + } + + if diff := cmp.Diff(testCase.expectedOutput, got); diff != "" { + t.Errorf("unexpected output difference: %s", diff) + } + }) + } +} diff --git a/tfsdklog/sdk.go b/tfsdklog/sdk.go index b056a3e..28af43c 100644 --- a/tfsdklog/sdk.go +++ b/tfsdklog/sdk.go @@ -13,7 +13,7 @@ import ( func NewRootSDKLogger(ctx context.Context, options ...logging.Option) context.Context { opts := logging.ApplyLoggerOpts(options...) if opts.Name == "" { - opts.Name = "sdk" + opts.Name = logging.DefaultSDKRootLoggerName } if sink := getSink(ctx); sink != nil { logger := sink.Named(opts.Name) @@ -33,9 +33,13 @@ func NewRootSDKLogger(ctx context.Context, options ...logging.Option) context.Co IncludeLocation: opts.IncludeLocation, DisableTime: !opts.IncludeTime, Output: opts.Output, - AdditionalLocationOffset: 1, + AdditionalLocationOffset: opts.AdditionalLocationOffset, } - return logging.SetSDKRootLogger(ctx, hclog.New(loggerOptions)) + + ctx = logging.SetSDKRootLogger(ctx, hclog.New(loggerOptions)) + ctx = logging.SetSDKRootLoggerOptions(ctx, loggerOptions) + + return ctx } // NewRootProviderLogger returns a new context.Context that contains a provider @@ -43,7 +47,7 @@ func NewRootSDKLogger(ctx context.Context, options ...logging.Option) context.Co func NewRootProviderLogger(ctx context.Context, options ...logging.Option) context.Context { opts := logging.ApplyLoggerOpts(options...) if opts.Name == "" { - opts.Name = "provider" + opts.Name = logging.DefaultProviderRootLoggerName } if sink := getSink(ctx); sink != nil { logger := sink.Named(opts.Name) @@ -63,9 +67,13 @@ func NewRootProviderLogger(ctx context.Context, options ...logging.Option) conte IncludeLocation: opts.IncludeLocation, DisableTime: !opts.IncludeTime, Output: opts.Output, - AdditionalLocationOffset: 1, + AdditionalLocationOffset: opts.AdditionalLocationOffset, } - return logging.SetProviderRootLogger(ctx, hclog.New(loggerOptions)) + + ctx = logging.SetProviderRootLogger(ctx, hclog.New(loggerOptions)) + ctx = logging.SetProviderRootLoggerOptions(ctx, loggerOptions) + + return ctx } // With returns a new context.Context that has a modified logger in it which diff --git a/tfsdklog/sdk_test.go b/tfsdklog/sdk_test.go index d9c2542..1c1c21c 100644 --- a/tfsdklog/sdk_test.go +++ b/tfsdklog/sdk_test.go @@ -29,6 +29,7 @@ func TestWith(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", + "@module": "sdk", "test-with-key": "test-with-value", }, }, @@ -40,6 +41,7 @@ func TestWith(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", + "@module": "sdk", "unfielded-test-with-key": nil, }, }, @@ -59,6 +61,7 @@ func TestWith(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", + "@module": "sdk", "test-log-key-1": "test-log-value-1", "test-log-key-2": "test-log-value-2", "test-log-key-3": "test-log-value-3", @@ -109,6 +112,7 @@ func TestTrace(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", + "@module": "sdk", }, }, }, @@ -125,6 +129,7 @@ func TestTrace(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", + "@module": "sdk", "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -149,6 +154,7 @@ func TestTrace(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", + "@module": "sdk", "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -199,6 +205,7 @@ func TestDebug(t *testing.T) { { "@level": hclog.Debug.String(), "@message": "test message", + "@module": "sdk", }, }, }, @@ -215,6 +222,7 @@ func TestDebug(t *testing.T) { { "@level": hclog.Debug.String(), "@message": "test message", + "@module": "sdk", "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -239,6 +247,7 @@ func TestDebug(t *testing.T) { { "@level": hclog.Debug.String(), "@message": "test message", + "@module": "sdk", "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -289,6 +298,7 @@ func TestInfo(t *testing.T) { { "@level": hclog.Info.String(), "@message": "test message", + "@module": "sdk", }, }, }, @@ -305,6 +315,7 @@ func TestInfo(t *testing.T) { { "@level": hclog.Info.String(), "@message": "test message", + "@module": "sdk", "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -329,6 +340,7 @@ func TestInfo(t *testing.T) { { "@level": hclog.Info.String(), "@message": "test message", + "@module": "sdk", "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -379,6 +391,7 @@ func TestWarn(t *testing.T) { { "@level": hclog.Warn.String(), "@message": "test message", + "@module": "sdk", }, }, }, @@ -395,6 +408,7 @@ func TestWarn(t *testing.T) { { "@level": hclog.Warn.String(), "@message": "test message", + "@module": "sdk", "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -419,6 +433,7 @@ func TestWarn(t *testing.T) { { "@level": hclog.Warn.String(), "@message": "test message", + "@module": "sdk", "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -469,6 +484,7 @@ func TestError(t *testing.T) { { "@level": hclog.Error.String(), "@message": "test message", + "@module": "sdk", }, }, }, @@ -485,6 +501,7 @@ func TestError(t *testing.T) { { "@level": hclog.Error.String(), "@message": "test message", + "@module": "sdk", "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -509,6 +526,7 @@ func TestError(t *testing.T) { { "@level": hclog.Error.String(), "@message": "test message", + "@module": "sdk", "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", diff --git a/tfsdklog/subsystem.go b/tfsdklog/subsystem.go index 5d80ed5..b07bacb 100644 --- a/tfsdklog/subsystem.go +++ b/tfsdklog/subsystem.go @@ -18,9 +18,10 @@ import ( // at other times. // // The only Options supported for subsystems are the Options for setting the -// level of the logger. +// level and additional location offset of the logger. func NewSubsystem(ctx context.Context, subsystem string, options ...logging.Option) context.Context { logger := logging.GetSDKRootLogger(ctx) + if logger == nil { // this essentially should never happen in production // the root logger for provider code should be injected @@ -29,12 +30,40 @@ func NewSubsystem(ctx context.Context, subsystem string, options ...logging.Opti // so just making this a no-op is fine return ctx } - subLogger := logger.Named(subsystem) + + loggerOptions := logging.GetSDKRootLoggerOptions(ctx) opts := logging.ApplyLoggerOpts(options...) + + // On the off-chance that the logger options are not available, fallback + // to creating a named logger. This will preserve the root logger options, + // but cannot make changes beyond the level due to the hclog.Logger + // interface. + if loggerOptions == nil { + subLogger := logger.Named(subsystem) + + if opts.AdditionalLocationOffset != 1 { + logger.Warn("Unable to create logging subsystem with AdditionalLocationOffset due to missing root logger options") + } + + if opts.Level != hclog.NoLevel { + subLogger.SetLevel(opts.Level) + } + + return logging.SetSDKSubsystemLogger(ctx, subsystem, subLogger) + } + + subLoggerOptions := hclogutils.LoggerOptionsCopy(loggerOptions) + subLoggerOptions.Name = subLoggerOptions.Name + "." + subsystem + + if opts.AdditionalLocationOffset != 1 { + subLoggerOptions.AdditionalLocationOffset = opts.AdditionalLocationOffset + } + if opts.Level != hclog.NoLevel { - subLogger.SetLevel(opts.Level) + subLoggerOptions.Level = opts.Level } - return logging.SetSDKSubsystemLogger(ctx, subsystem, subLogger) + + return logging.SetSDKSubsystemLogger(ctx, subsystem, hclog.New(subLoggerOptions)) } // SubsystemWith returns a new context.Context that has a modified logger for diff --git a/tfsdklog/subsystem_test.go b/tfsdklog/subsystem_test.go index 0f6b13e..0b374c1 100644 --- a/tfsdklog/subsystem_test.go +++ b/tfsdklog/subsystem_test.go @@ -11,7 +11,10 @@ import ( "github.com/hashicorp/terraform-plugin-log/tfsdklog" ) -const testSubsystem = "test_subsystem" +const ( + testSubsystem = "test_subsystem" + testSubsystemModule = "sdk." + testSubsystem +) func TestSubsystemWith(t *testing.T) { t.Parallel() @@ -31,7 +34,7 @@ func TestSubsystemWith(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-with-key": "test-with-value", }, }, @@ -43,7 +46,7 @@ func TestSubsystemWith(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "unfielded-test-with-key": nil, }, }, @@ -63,7 +66,7 @@ func TestSubsystemWith(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-log-key-1": "test-log-value-1", "test-log-key-2": "test-log-value-2", "test-log-key-3": "test-log-value-3", @@ -115,7 +118,7 @@ func TestSubsystemTrace(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, }, }, }, @@ -132,7 +135,7 @@ func TestSubsystemTrace(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -157,7 +160,7 @@ func TestSubsystemTrace(t *testing.T) { { "@level": hclog.Trace.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -209,7 +212,7 @@ func TestSubsystemDebug(t *testing.T) { { "@level": hclog.Debug.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, }, }, }, @@ -226,7 +229,7 @@ func TestSubsystemDebug(t *testing.T) { { "@level": hclog.Debug.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -251,7 +254,7 @@ func TestSubsystemDebug(t *testing.T) { { "@level": hclog.Debug.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -303,7 +306,7 @@ func TestSubsystemInfo(t *testing.T) { { "@level": hclog.Info.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, }, }, }, @@ -320,7 +323,7 @@ func TestSubsystemInfo(t *testing.T) { { "@level": hclog.Info.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -345,7 +348,7 @@ func TestSubsystemInfo(t *testing.T) { { "@level": hclog.Info.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -397,7 +400,7 @@ func TestSubsystemWarn(t *testing.T) { { "@level": hclog.Warn.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, }, }, }, @@ -414,7 +417,7 @@ func TestSubsystemWarn(t *testing.T) { { "@level": hclog.Warn.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -439,7 +442,7 @@ func TestSubsystemWarn(t *testing.T) { { "@level": hclog.Warn.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1", @@ -491,7 +494,7 @@ func TestSubsystemError(t *testing.T) { { "@level": hclog.Error.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, }, }, }, @@ -508,7 +511,7 @@ func TestSubsystemError(t *testing.T) { { "@level": hclog.Error.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1", "test-key-2": "test-value-2", "test-key-3": "test-value-3", @@ -533,7 +536,7 @@ func TestSubsystemError(t *testing.T) { { "@level": hclog.Error.String(), "@message": "test message", - "@module": testSubsystem, + "@module": testSubsystemModule, "test-key-1": "test-value-1-map2", "test-key-2": "test-value-2-map1", "test-key-3": "test-value-3-map1",