From c55edc15f531c98ccba3efe12ee0793b067a6b02 Mon Sep 17 00:00:00 2001 From: Graham Davison Date: Fri, 4 Aug 2023 13:18:27 -0700 Subject: [PATCH 1/6] Renames `logging.Logger` to `logging.TfLogger` --- aws_config.go | 4 +- logging/logger.go | 54 +++------------------- logging/tf_logger.go | 69 ++++++++++++++++++++++++++++ logging/tf_logger_test.go | 96 +++++++++++++++++++++++++++++++++++++++ v2/awsv1shim/session.go | 2 +- 5 files changed, 174 insertions(+), 51 deletions(-) create mode 100644 logging/tf_logger.go create mode 100644 logging/tf_logger_test.go diff --git a/aws_config.go b/aws_config.go index 9092525d..20eb96b6 100644 --- a/aws_config.go +++ b/aws_config.go @@ -40,7 +40,7 @@ func GetAwsConfig(ctx context.Context, c *Config) (context.Context, aws.Config, var diags diag.Diagnostics ctx = configCommonLogging(ctx) - baseCtx, logger := logging.New(ctx, loggerName) + baseCtx, logger := logging.NewTfLogger(ctx, loggerName) baseCtx = logging.RegisterLogger(baseCtx, logger) logger.Trace(baseCtx, "Resolving AWS configuration") @@ -210,7 +210,7 @@ func (r *networkErrorShortcutter) RetryDelay(attempt int, err error) (time.Durat func GetAwsAccountIDAndPartition(ctx context.Context, awsConfig aws.Config, c *Config) (string, string, diag.Diagnostics) { var diags diag.Diagnostics ctx = configCommonLogging(ctx) - ctx, logger := logging.New(ctx, loggerName) + ctx, logger := logging.NewTfLogger(ctx, loggerName) ctx = logging.RegisterLogger(ctx, logger) if !c.SkipCredsValidation { diff --git a/logging/logger.go b/logging/logger.go index f3c7a883..22e5405d 100644 --- a/logging/logger.go +++ b/logging/logger.go @@ -5,55 +5,13 @@ package logging import ( "context" - - "github.com/hashicorp/terraform-plugin-log/tflog" ) -func New(ctx context.Context, name string) (context.Context, TfLogger) { - ctx = tflog.NewSubsystem(ctx, name, tflog.WithRootFields()) - logger := TfLogger(name) - - return ctx, logger -} - -type TfLogger string - -func (l TfLogger) Warn(ctx context.Context, msg string, fields ...map[string]any) { - if l == "" { - tflog.Warn(ctx, msg, fields...) - } else { - tflog.SubsystemWarn(ctx, string(l), msg, fields...) - } -} - -func (l TfLogger) Info(ctx context.Context, msg string, fields ...map[string]any) { - if l == "" { - tflog.Info(ctx, msg, fields...) - } else { - tflog.SubsystemInfo(ctx, string(l), msg, fields...) - } -} - -func (l TfLogger) Debug(ctx context.Context, msg string, fields ...map[string]any) { - if l == "" { - tflog.Debug(ctx, msg, fields...) - } else { - tflog.SubsystemDebug(ctx, string(l), msg, fields...) - } -} - -func (l TfLogger) Trace(ctx context.Context, msg string, fields ...map[string]any) { - if l == "" { - tflog.Trace(ctx, msg, fields...) - } else { - tflog.SubsystemTrace(ctx, string(l), msg, fields...) - } -} +type Logger interface { + Warn(ctx context.Context, msg string, fields ...map[string]any) + Info(ctx context.Context, msg string, fields ...map[string]any) + Debug(ctx context.Context, msg string, fields ...map[string]any) + Trace(ctx context.Context, msg string, fields ...map[string]any) -func (l TfLogger) SetField(ctx context.Context, key string, value any) context.Context { - if l == "" { - return tflog.SetField(ctx, key, value) - } else { - return tflog.SubsystemSetField(ctx, string(l), key, value) - } + SetField(ctx context.Context, key string, value any) context.Context } diff --git a/logging/tf_logger.go b/logging/tf_logger.go new file mode 100644 index 00000000..380ecdf5 --- /dev/null +++ b/logging/tf_logger.go @@ -0,0 +1,69 @@ +// Copyright (c) HashiCorp, Inc. +// SPDX-License-Identifier: MPL-2.0 + +package logging + +import ( + "context" + + "github.com/hashicorp/terraform-plugin-log/tflog" +) + +func NewTfLogger(ctx context.Context, name string) (context.Context, TfLogger) { + ctx = tflog.NewSubsystem(ctx, name, tflog.WithRootFields()) + logger := TfLogger(name) + + return ctx, logger +} + +type TfLogger string + +var _ Logger = TfLogger("") + +func (l TfLogger) Warn(ctx context.Context, msg string, fields ...map[string]any) { + if l == "" { + tflog.Warn(ctx, msg, fields...) + } else { + tflog.SubsystemWarn(ctx, string(l), msg, fields...) + } +} + +func (l TfLogger) Info(ctx context.Context, msg string, fields ...map[string]any) { + if l == "" { + tflog.Info(ctx, msg, fields...) + } else { + tflog.SubsystemInfo(ctx, string(l), msg, fields...) + } +} + +func (l TfLogger) Debug(ctx context.Context, msg string, fields ...map[string]any) { + if l == "" { + tflog.Debug(ctx, msg, fields...) + } else { + tflog.SubsystemDebug(ctx, string(l), msg, fields...) + } +} + +func (l TfLogger) Trace(ctx context.Context, msg string, fields ...map[string]any) { + if l == "" { + tflog.Trace(ctx, msg, fields...) + } else { + tflog.SubsystemTrace(ctx, string(l), msg, fields...) + } +} + +func (l TfLogger) SetField(ctx context.Context, key string, value any) context.Context { + if l == "" { + return tflog.SetField(ctx, key, value) + } else { + return tflog.SubsystemSetField(ctx, string(l), key, value) + } +} + +// func (l TfLogger) MaskAllFieldValuesRegexes(ctx context.Context, expressions ...*regexp.Regexp) context.Context { +// if l == "" { +// return tflog.MaskAllFieldValuesRegexes(ctx, expressions...) +// } else { +// return tflog.SubsystemMaskAllFieldValuesRegexes(ctx, string(l), expressions...) +// } +// } diff --git a/logging/tf_logger_test.go b/logging/tf_logger_test.go new file mode 100644 index 00000000..591a7949 --- /dev/null +++ b/logging/tf_logger_test.go @@ -0,0 +1,96 @@ +// Copyright (c) HashiCorp, Inc. +// SPDX-License-Identifier: MPL-2.0 + +package logging + +import ( + "bytes" + "context" + "fmt" + "testing" + + "github.com/hashicorp/terraform-plugin-log/tflogtest" +) + +func TestTfLoggerWarn(t *testing.T) { + var buf bytes.Buffer + ctx := tflogtest.RootLogger(context.Background(), &buf) + + loggerName := "test" + expectedModule := fmt.Sprintf("provider.%s", loggerName) + ctx, logger := NewTfLogger(ctx, loggerName) + + logger.Warn(ctx, "message", map[string]any{ + "one": int(1), + "two": "two", + }) + + lines, err := tflogtest.MultilineJSONDecode(&buf) + if err != nil { + t.Fatalf("decoding log lines: %s", err) + } + + if l := len(lines); l != 1 { + t.Fatalf("expected 1 log entry, got %d\n%v", l, lines) + } + + line := lines[0] + if a, e := line["@level"], "warn"; a != e { + t.Errorf("expected module %q, got %q", e, a) + } + if a, e := line["@module"], expectedModule; a != e { + t.Errorf("expected module %q, got %q", e, a) + } + if a, e := line["@message"], "message"; a != e { + t.Errorf("expected message %q, got %q", e, a) + } + if a, e := line["one"], float64(1); a != e { + t.Errorf("expected field \"one\" %v, got %v", e, a) + } + if a, e := line["two"], "two"; a != e { + t.Errorf("expected field \"two\" %q, got %q", e, a) + } +} + +func TestTfLoggerSetField(t *testing.T) { + var buf bytes.Buffer + ctx := tflogtest.RootLogger(context.Background(), &buf) + + loggerName := "test" + ctx, logger := NewTfLogger(ctx, loggerName) + + ctxWithField := logger.SetField(ctx, "key", "value") + + logger.Warn(ctxWithField, "first") + logger.Warn(ctxWithField, "second", map[string]any{ + "key": "other value", + }) + + lines, err := tflogtest.MultilineJSONDecode(&buf) + if err != nil { + t.Fatalf("ctxWithField: decoding log lines: %s", err) + } + + line := lines[0] + if a, e := line["key"], "value"; a != e { + t.Errorf("expected field \"key\" %q, got %q", e, a) + } + + line = lines[1] + if a, e := line["key"], "other value"; a != e { + t.Errorf("expected field \"key\" %q, got %q", e, a) + } + + // logger.SetField does not affect the original context + logger.Warn(ctx, "no fields") + + lines, err = tflogtest.MultilineJSONDecode(&buf) + if err != nil { + t.Fatalf("ctx: decoding log lines: %s", err) + } + + line = lines[0] + if val, ok := line["key"]; ok { + t.Errorf("expected field \"key\" to not be set, got %q", val) + } +} diff --git a/v2/awsv1shim/session.go b/v2/awsv1shim/session.go index 18cc6072..37d005b2 100644 --- a/v2/awsv1shim/session.go +++ b/v2/awsv1shim/session.go @@ -83,7 +83,7 @@ func GetSession(ctx context.Context, awsC *awsv2.Config, c *awsbase.Config) (*se var diags diag.Diagnostics // var loggerFactory tfLoggerFactory - ctx, logger := logging.New(ctx, loggerName) + ctx, logger := logging.NewTfLogger(ctx, loggerName) ctx = logging.RegisterLogger(ctx, logger) options, err := getSessionOptions(ctx, awsC, c) From 21a48aae23c60ea3406462b83f9f0949851d3d9a Mon Sep 17 00:00:00 2001 From: Graham Davison Date: Fri, 4 Aug 2023 14:55:42 -0700 Subject: [PATCH 2/6] Adds test for masking of default logger --- aws_config_test.go | 58 ++++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 56 insertions(+), 2 deletions(-) diff --git a/aws_config_test.go b/aws_config_test.go index fb41c7b4..3afc2de6 100644 --- a/aws_config_test.go +++ b/aws_config_test.go @@ -34,6 +34,7 @@ import ( "github.com/hashicorp/aws-sdk-go-base/v2/mockdata" "github.com/hashicorp/aws-sdk-go-base/v2/servicemocks" "github.com/hashicorp/aws-sdk-go-base/v2/useragent" + "github.com/hashicorp/terraform-plugin-log/tflog" "github.com/hashicorp/terraform-plugin-log/tflogtest" ) @@ -3411,9 +3412,10 @@ func (r *withNoDelay) RetryDelay(attempt int, err error) (time.Duration, error) return 0 * time.Second, nil } -func TestLogger(t *testing.T) { +func TestLogger_TfLog(t *testing.T) { + ctx := context.Background() var buf bytes.Buffer - ctx := tflogtest.RootLogger(context.Background(), &buf) + ctx = tflogtest.RootLogger(ctx, &buf) oldEnv := servicemocks.InitSessionTestEnv() defer servicemocks.PopEnv(oldEnv) @@ -3442,6 +3444,9 @@ func TestLogger(t *testing.T) { t.Fatalf("GetAwsConfig: decoding log lines: %s", err) } + if len(lines) == 0 { + t.Fatalf("expected log entries, had none") + } for i, line := range lines { if a, e := line["@module"], expectedName; a != e { t.Errorf("GetAwsConfig: line %d: expected module %q, got %q", i+1, e, a) @@ -3458,9 +3463,58 @@ func TestLogger(t *testing.T) { t.Fatalf("GetAwsAccountIDAndPartition: decoding log lines: %s", err) } + if len(lines) == 0 { + t.Fatalf("expected log entries, had none") + } for i, line := range lines { if a, e := line["@module"], expectedName; a != e { t.Errorf("GetAwsAccountIDAndPartition: line %d: expected module %q, got %q", i+1, e, a) } } } + +func TestLoggerDefaultMasking_TfLog(t *testing.T) { + ctx := context.Background() + var buf bytes.Buffer + ctx = tflogtest.RootLogger(ctx, &buf) + + oldEnv := servicemocks.InitSessionTestEnv() + defer servicemocks.PopEnv(oldEnv) + + config := &Config{ + AccessKey: servicemocks.MockStaticAccessKey, + Region: "us-east-1", + SecretKey: servicemocks.MockStaticSecretKey, + } + + ts := servicemocks.MockAwsApiServer("STS", []*servicemocks.MockEndpoint{ + servicemocks.MockStsGetCallerIdentityValidEndpoint, + }) + defer ts.Close() + config.StsEndpoint = ts.URL + + ctx, _, diags := GetAwsConfig(ctx, config) + if diags.HasError() { + t.Fatalf("error in GetAwsConfig(): %v", diags) + } + + buf.Reset() + + tflog.Info(ctx, "message", map[string]any{ + "id": "AKIAI44QH8DHBEXAMPLE", + }) + + lines, err := tflogtest.MultilineJSONDecode(&buf) + if err != nil { + t.Fatalf("decoding log lines: %s", err) + } + + if l := len(lines); l != 1 { + t.Fatalf("expected 1 log entry, got %d", l) + } + + line := lines[0] + if a, e := line["id"], "***"; a != e { + t.Errorf("expected %q, got %q", e, a) + } +} From 2bb96b91f6978f0e3d52dfdb723f0d213357921d Mon Sep 17 00:00:00 2001 From: Graham Davison Date: Wed, 9 Aug 2023 13:02:06 -0700 Subject: [PATCH 3/6] Adds `HcLogger` --- aws_config.go | 8 ++- logging/context.go | 10 ++-- logging/hc_logger.go | 71 ++++++++++++++++++++++++++ logging/hc_logger_test.go | 52 +++++++++++++++++++ logging/logger.go | 2 + logging/logger_test.go | 97 ++++++++++++++++++++++++++++++++++++ logging/tf_logger.go | 14 ++++-- logging/tf_logger_test.go | 87 ++++---------------------------- v2/awsv1shim/session.go | 4 +- v2/awsv1shim/session_test.go | 1 + 10 files changed, 254 insertions(+), 92 deletions(-) create mode 100644 logging/hc_logger.go create mode 100644 logging/hc_logger_test.go create mode 100644 logging/logger_test.go diff --git a/aws_config.go b/aws_config.go index 20eb96b6..7f557c6d 100644 --- a/aws_config.go +++ b/aws_config.go @@ -38,9 +38,12 @@ func configCommonLogging(ctx context.Context) context.Context { func GetAwsConfig(ctx context.Context, c *Config) (context.Context, aws.Config, diag.Diagnostics) { var diags diag.Diagnostics + + ctx, tflogger := logging.NewTfLogger(ctx) + ctx = logging.RegisterLogger(ctx, tflogger) ctx = configCommonLogging(ctx) - baseCtx, logger := logging.NewTfLogger(ctx, loggerName) + baseCtx, logger := tflogger.SubLogger(ctx, loggerName) baseCtx = logging.RegisterLogger(baseCtx, logger) logger.Trace(baseCtx, "Resolving AWS configuration") @@ -210,7 +213,8 @@ func (r *networkErrorShortcutter) RetryDelay(attempt int, err error) (time.Durat func GetAwsAccountIDAndPartition(ctx context.Context, awsConfig aws.Config, c *Config) (string, string, diag.Diagnostics) { var diags diag.Diagnostics ctx = configCommonLogging(ctx) - ctx, logger := logging.NewTfLogger(ctx, loggerName) + ctx, tflogger := logging.NewTfLogger(ctx) + ctx, logger := tflogger.SubLogger(ctx, loggerName) ctx = logging.RegisterLogger(ctx, logger) if !c.SkipCredsValidation { diff --git a/logging/context.go b/logging/context.go index 8ff753a2..f6e3f735 100644 --- a/logging/context.go +++ b/logging/context.go @@ -11,14 +11,10 @@ type loggerKeyT string const loggerKey loggerKeyT = "logger-key" -func RegisterLogger(ctx context.Context, logger TfLogger) context.Context { +func RegisterLogger(ctx context.Context, logger Logger) context.Context { return context.WithValue(ctx, loggerKey, logger) } -func RetrieveLogger(ctx context.Context) TfLogger { - logger, ok := ctx.Value(loggerKey).(TfLogger) - if !ok { - return TfLogger("") - } - return logger +func RetrieveLogger(ctx context.Context) Logger { + return ctx.Value(loggerKey).(Logger) } diff --git a/logging/hc_logger.go b/logging/hc_logger.go new file mode 100644 index 00000000..d8ce74d3 --- /dev/null +++ b/logging/hc_logger.go @@ -0,0 +1,71 @@ +// Copyright (c) HashiCorp, Inc. +// SPDX-License-Identifier: MPL-2.0 + +package logging + +import ( + "context" + + "github.com/hashicorp/go-hclog" +) + +type HcLogger struct{} + +var _ Logger = HcLogger{} + +func NewHcLogger(ctx context.Context, logger hclog.Logger) (context.Context, HcLogger) { + ctx = hclog.WithContext(ctx, logger) + + return ctx, HcLogger{} +} + +func (l HcLogger) SubLogger(ctx context.Context, name string) (context.Context, Logger) { + logger := hclog.FromContext(ctx) + logger = logger.Named(name) + ctx = hclog.WithContext(ctx, logger) + + return ctx, HcLogger{} +} + +func (l HcLogger) Warn(ctx context.Context, msg string, fields ...map[string]any) { + logger := hclog.FromContext(ctx) + logger.Warn(msg, flattenFields(fields...)...) +} + +func (l HcLogger) Info(ctx context.Context, msg string, fields ...map[string]any) { + logger := hclog.FromContext(ctx) + logger.Info(msg, flattenFields(fields...)...) +} + +func (l HcLogger) Debug(ctx context.Context, msg string, fields ...map[string]any) { + logger := hclog.FromContext(ctx) + logger.Debug(msg, flattenFields(fields...)...) +} + +func (l HcLogger) Trace(ctx context.Context, msg string, fields ...map[string]any) { + logger := hclog.FromContext(ctx) + logger.Trace(msg, flattenFields(fields...)...) +} + +// TODO: how to handle duplicates +func flattenFields(fields ...map[string]any) []any { + var totalLen int + for _, m := range fields { + totalLen = len(m) + } + f := make([]any, 0, totalLen*2) //nolint:gomnd + + for _, m := range fields { + for k, v := range m { + f = append(f, k, v) + } + } + return f +} + +func (l HcLogger) SetField(ctx context.Context, key string, value any) context.Context { + logger := hclog.FromContext(ctx) + logger = logger.With(key, value) + ctx = hclog.WithContext(ctx, logger) + return ctx +} diff --git a/logging/hc_logger_test.go b/logging/hc_logger_test.go new file mode 100644 index 00000000..4602256a --- /dev/null +++ b/logging/hc_logger_test.go @@ -0,0 +1,52 @@ +// Copyright (c) HashiCorp, Inc. +// SPDX-License-Identifier: MPL-2.0 + +package logging + +import ( + "context" + "io" + "testing" + + "github.com/hashicorp/go-hclog" +) + +const hclogRootName = "hc-log-test" + +func TestHcLoggerWarn(t *testing.T) { + testLoggerWarn(t, hclogRootName, hcLoggerFactory) +} + +func TestHcLoggerSetField(t *testing.T) { + testLoggerSetField(t, hclogRootName, hcLoggerFactory) +} + +func hcLoggerFactory(ctx context.Context, name string, output io.Writer) (context.Context, Logger) { + hclogger := configureHcLogger(output) + + ctx, rootLogger := NewHcLogger(ctx, hclogger) + ctx, logger := rootLogger.SubLogger(ctx, name) + + return ctx, logger +} + +// configureHcLogger configures the default logger with settings suitable for testing: +// +// - Log level set to TRACE +// - Written to the io.Writer passed in, such as a bytes.Buffer +// - Log entries are in JSON format, and can be decoded using multilineJSONDecode +// - Caller information is not included +// - Timestamp is not included +func configureHcLogger(output io.Writer) hclog.Logger { + logger := hclog.NewInterceptLogger(&hclog.LoggerOptions{ + Name: hclogRootName, + Level: hclog.Trace, + Output: output, + IndependentLevels: true, + JSONFormat: true, + IncludeLocation: false, + DisableTime: true, + }) + + return logger +} diff --git a/logging/logger.go b/logging/logger.go index 22e5405d..c6f21519 100644 --- a/logging/logger.go +++ b/logging/logger.go @@ -14,4 +14,6 @@ type Logger interface { Trace(ctx context.Context, msg string, fields ...map[string]any) SetField(ctx context.Context, key string, value any) context.Context + + SubLogger(ctx context.Context, name string) (context.Context, Logger) } diff --git a/logging/logger_test.go b/logging/logger_test.go new file mode 100644 index 00000000..dab7a4b9 --- /dev/null +++ b/logging/logger_test.go @@ -0,0 +1,97 @@ +// Copyright (c) HashiCorp, Inc. +// SPDX-License-Identifier: MPL-2.0 + +package logging + +import ( + "bytes" + "context" + "io" + "testing" + + "github.com/google/go-cmp/cmp" + "github.com/hashicorp/terraform-plugin-log/tflogtest" +) + +func testLoggerWarn(t *testing.T, rootName string, factory func(ctx context.Context, name string, output io.Writer) (context.Context, Logger)) { + t.Helper() + + loggerName := "test" + expectedModule := rootName + "." + loggerName + + var buf bytes.Buffer + ctx := context.Background() + ctx, logger := factory(ctx, loggerName, &buf) + + logger.Warn(ctx, "message", map[string]any{ + "one": int(1), + "two": "two", + }) + + lines, err := tflogtest.MultilineJSONDecode(&buf) + if err != nil { + t.Fatalf("decoding log lines: %s", err) + } + + expected := []map[string]any{ + { + "@level": "warn", + "@module": expectedModule, + "@message": "message", + "one": float64(1), + "two": "two", + }, + } + + if diff := cmp.Diff(expected, lines); diff != "" { + t.Errorf("unexpected logger output difference: %s", diff) + } +} + +func testLoggerSetField(t *testing.T, rootName string, factory func(ctx context.Context, name string, output io.Writer) (context.Context, Logger)) { + t.Helper() + + loggerName := "test" + expectedModule := rootName + "." + loggerName + + var buf bytes.Buffer + originalCtx := context.Background() + originalCtx, logger := factory(originalCtx, loggerName, &buf) + + newCtx := logger.SetField(originalCtx, "key", "value") + + logger.Warn(newCtx, "new logger") + logger.Warn(newCtx, "new logger", map[string]any{ + "key": "other value", + }) + logger.Warn(originalCtx, "original logger") + + lines, err := tflogtest.MultilineJSONDecode(&buf) + if err != nil { + t.Fatalf("ctxWithField: decoding log lines: %s", err) + } + + expected := []map[string]any{ + { + "@level": "warn", + "@module": expectedModule, + "@message": "new logger", + "key": "value", + }, + { + "@level": "warn", + "@module": expectedModule, + "@message": "new logger", + "key": "other value", + }, + { + "@level": "warn", + "@module": expectedModule, + "@message": "original logger", + }, + } + + if diff := cmp.Diff(expected, lines); diff != "" { + t.Errorf("unexpected logger output difference: %s", diff) + } +} diff --git a/logging/tf_logger.go b/logging/tf_logger.go index 380ecdf5..57a55e68 100644 --- a/logging/tf_logger.go +++ b/logging/tf_logger.go @@ -9,17 +9,21 @@ import ( "github.com/hashicorp/terraform-plugin-log/tflog" ) -func NewTfLogger(ctx context.Context, name string) (context.Context, TfLogger) { +type TfLogger string + +var _ Logger = TfLogger("") + +func NewTfLogger(ctx context.Context) (context.Context, TfLogger) { + return ctx, TfLogger("") +} + +func (l TfLogger) SubLogger(ctx context.Context, name string) (context.Context, Logger) { ctx = tflog.NewSubsystem(ctx, name, tflog.WithRootFields()) logger := TfLogger(name) return ctx, logger } -type TfLogger string - -var _ Logger = TfLogger("") - func (l TfLogger) Warn(ctx context.Context, msg string, fields ...map[string]any) { if l == "" { tflog.Warn(ctx, msg, fields...) diff --git a/logging/tf_logger_test.go b/logging/tf_logger_test.go index 591a7949..344e89d9 100644 --- a/logging/tf_logger_test.go +++ b/logging/tf_logger_test.go @@ -4,93 +4,28 @@ package logging import ( - "bytes" "context" - "fmt" + "io" "testing" "github.com/hashicorp/terraform-plugin-log/tflogtest" ) -func TestTfLoggerWarn(t *testing.T) { - var buf bytes.Buffer - ctx := tflogtest.RootLogger(context.Background(), &buf) - - loggerName := "test" - expectedModule := fmt.Sprintf("provider.%s", loggerName) - ctx, logger := NewTfLogger(ctx, loggerName) - - logger.Warn(ctx, "message", map[string]any{ - "one": int(1), - "two": "two", - }) - - lines, err := tflogtest.MultilineJSONDecode(&buf) - if err != nil { - t.Fatalf("decoding log lines: %s", err) - } +const tflogRootName = "provider" - if l := len(lines); l != 1 { - t.Fatalf("expected 1 log entry, got %d\n%v", l, lines) - } - - line := lines[0] - if a, e := line["@level"], "warn"; a != e { - t.Errorf("expected module %q, got %q", e, a) - } - if a, e := line["@module"], expectedModule; a != e { - t.Errorf("expected module %q, got %q", e, a) - } - if a, e := line["@message"], "message"; a != e { - t.Errorf("expected message %q, got %q", e, a) - } - if a, e := line["one"], float64(1); a != e { - t.Errorf("expected field \"one\" %v, got %v", e, a) - } - if a, e := line["two"], "two"; a != e { - t.Errorf("expected field \"two\" %q, got %q", e, a) - } +func TestTfLoggerWarn(t *testing.T) { + testLoggerWarn(t, tflogRootName, tfLoggerFactory) } func TestTfLoggerSetField(t *testing.T) { - var buf bytes.Buffer - ctx := tflogtest.RootLogger(context.Background(), &buf) - - loggerName := "test" - ctx, logger := NewTfLogger(ctx, loggerName) - - ctxWithField := logger.SetField(ctx, "key", "value") - - logger.Warn(ctxWithField, "first") - logger.Warn(ctxWithField, "second", map[string]any{ - "key": "other value", - }) - - lines, err := tflogtest.MultilineJSONDecode(&buf) - if err != nil { - t.Fatalf("ctxWithField: decoding log lines: %s", err) - } - - line := lines[0] - if a, e := line["key"], "value"; a != e { - t.Errorf("expected field \"key\" %q, got %q", e, a) - } - - line = lines[1] - if a, e := line["key"], "other value"; a != e { - t.Errorf("expected field \"key\" %q, got %q", e, a) - } + testLoggerSetField(t, tflogRootName, tfLoggerFactory) +} - // logger.SetField does not affect the original context - logger.Warn(ctx, "no fields") +func tfLoggerFactory(ctx context.Context, name string, output io.Writer) (context.Context, Logger) { + ctx = tflogtest.RootLogger(ctx, output) - lines, err = tflogtest.MultilineJSONDecode(&buf) - if err != nil { - t.Fatalf("ctx: decoding log lines: %s", err) - } + ctx, rootLogger := NewTfLogger(ctx) + ctx, logger := rootLogger.SubLogger(ctx, name) - line = lines[0] - if val, ok := line["key"]; ok { - t.Errorf("expected field \"key\" to not be set, got %q", val) - } + return ctx, logger } diff --git a/v2/awsv1shim/session.go b/v2/awsv1shim/session.go index 37d005b2..82b2f100 100644 --- a/v2/awsv1shim/session.go +++ b/v2/awsv1shim/session.go @@ -82,8 +82,8 @@ const loggerName string = "aws-base-v1" func GetSession(ctx context.Context, awsC *awsv2.Config, c *awsbase.Config) (*session.Session, diag.Diagnostics) { var diags diag.Diagnostics - // var loggerFactory tfLoggerFactory - ctx, logger := logging.NewTfLogger(ctx, loggerName) + ctx, tflogger := logging.NewTfLogger(ctx) + ctx, logger := tflogger.SubLogger(ctx, loggerName) ctx = logging.RegisterLogger(ctx, logger) options, err := getSessionOptions(ctx, awsC, c) diff --git a/v2/awsv1shim/session_test.go b/v2/awsv1shim/session_test.go index af9cb26c..aae5f7ed 100644 --- a/v2/awsv1shim/session_test.go +++ b/v2/awsv1shim/session_test.go @@ -2564,6 +2564,7 @@ func TestSessionRetryHandlers(t *testing.T) { request, _ := iamconn.GetUserRequest(&iam.GetUserInput{}) request.RetryCount = testcase.RetryCount request.Error = testcase.Error + request.SetContext(ctx) // Prevent the retryer from using the default retry delay retryer := request.Retryer.(client.DefaultRetryer) From a31076ec4bf55e7e9bd2c02d8e0f50bc0de09916 Mon Sep 17 00:00:00 2001 From: Graham Davison Date: Wed, 9 Aug 2023 14:18:28 -0700 Subject: [PATCH 4/6] Allows configuring logger --- aws_config.go | 17 +++++-- aws_config_test.go | 93 ++++++++++++++++++++++++++++++++++++ internal/config/config.go | 2 + logging/null_logger.go | 33 +++++++++++++ v2/awsv1shim/session.go | 7 ++- v2/awsv1shim/session_test.go | 4 ++ 6 files changed, 149 insertions(+), 7 deletions(-) create mode 100644 logging/null_logger.go diff --git a/aws_config.go b/aws_config.go index 7f557c6d..cbb696cc 100644 --- a/aws_config.go +++ b/aws_config.go @@ -39,11 +39,14 @@ func configCommonLogging(ctx context.Context) context.Context { func GetAwsConfig(ctx context.Context, c *Config) (context.Context, aws.Config, diag.Diagnostics) { var diags diag.Diagnostics - ctx, tflogger := logging.NewTfLogger(ctx) - ctx = logging.RegisterLogger(ctx, tflogger) + var logger logging.Logger = logging.NullLogger{} + if c.Logger != nil { + logger = c.Logger + } + ctx = logging.RegisterLogger(ctx, logger) ctx = configCommonLogging(ctx) - baseCtx, logger := tflogger.SubLogger(ctx, loggerName) + baseCtx, logger := logger.SubLogger(ctx, loggerName) baseCtx = logging.RegisterLogger(baseCtx, logger) logger.Trace(baseCtx, "Resolving AWS configuration") @@ -212,9 +215,13 @@ func (r *networkErrorShortcutter) RetryDelay(attempt int, err error) (time.Durat func GetAwsAccountIDAndPartition(ctx context.Context, awsConfig aws.Config, c *Config) (string, string, diag.Diagnostics) { var diags diag.Diagnostics + + var logger logging.Logger = logging.NullLogger{} + if c.Logger != nil { + logger = c.Logger + } ctx = configCommonLogging(ctx) - ctx, tflogger := logging.NewTfLogger(ctx) - ctx, logger := tflogger.SubLogger(ctx, loggerName) + ctx, logger = logger.SubLogger(ctx, loggerName) ctx = logging.RegisterLogger(ctx, logger) if !c.SkipCredsValidation { diff --git a/aws_config_test.go b/aws_config_test.go index 3afc2de6..92f4126c 100644 --- a/aws_config_test.go +++ b/aws_config_test.go @@ -8,6 +8,7 @@ import ( "context" "errors" "fmt" + "io" "net" "net/http" "os" @@ -31,9 +32,11 @@ import ( "github.com/hashicorp/aws-sdk-go-base/v2/internal/awsconfig" "github.com/hashicorp/aws-sdk-go-base/v2/internal/constants" "github.com/hashicorp/aws-sdk-go-base/v2/internal/test" + "github.com/hashicorp/aws-sdk-go-base/v2/logging" "github.com/hashicorp/aws-sdk-go-base/v2/mockdata" "github.com/hashicorp/aws-sdk-go-base/v2/servicemocks" "github.com/hashicorp/aws-sdk-go-base/v2/useragent" + "github.com/hashicorp/go-hclog" "github.com/hashicorp/terraform-plugin-log/tflog" "github.com/hashicorp/terraform-plugin-log/tflogtest" ) @@ -3420,8 +3423,11 @@ func TestLogger_TfLog(t *testing.T) { oldEnv := servicemocks.InitSessionTestEnv() defer servicemocks.PopEnv(oldEnv) + ctx, logger := logging.NewTfLogger(ctx) + config := &Config{ AccessKey: servicemocks.MockStaticAccessKey, + Logger: logger, Region: "us-east-1", SecretKey: servicemocks.MockStaticSecretKey, } @@ -3518,3 +3524,90 @@ func TestLoggerDefaultMasking_TfLog(t *testing.T) { t.Errorf("expected %q, got %q", e, a) } } + +func TestLogger_HcLog(t *testing.T) { + ctx := context.Background() + + rootName := "hc-log-test" + expectedName := rootName + "." + loggerName + + var buf bytes.Buffer + hclogger := configureHcLogger(rootName, &buf) + + oldEnv := servicemocks.InitSessionTestEnv() + defer servicemocks.PopEnv(oldEnv) + + ctx, logger := logging.NewHcLogger(ctx, hclogger) + + config := &Config{ + AccessKey: servicemocks.MockStaticAccessKey, + Logger: logger, + Region: "us-east-1", + SecretKey: servicemocks.MockStaticSecretKey, + } + + ts := servicemocks.MockAwsApiServer("STS", []*servicemocks.MockEndpoint{ + servicemocks.MockStsGetCallerIdentityValidEndpoint, + }) + defer ts.Close() + config.StsEndpoint = ts.URL + + ctx, awsConfig, diags := GetAwsConfig(ctx, config) + if diags.HasError() { + t.Fatalf("error in GetAwsConfig(): %v", diags) + } + + lines, err := tflogtest.MultilineJSONDecode(&buf) + if err != nil { + t.Fatalf("GetAwsConfig: decoding log lines: %s", err) + } + + if len(lines) == 0 { + t.Fatalf("expected log entries, had none") + } + for i, line := range lines { + if a, e := line["@module"], expectedName; a != e { + t.Errorf("GetAwsConfig: line %d: expected module %q, got %q", i+1, e, a) + } + } + + _, _, diags = GetAwsAccountIDAndPartition(ctx, awsConfig, config) + if diags.HasError() { + t.Fatalf("GetAwsAccountIDAndPartition: unexpected '%[1]T': %[1]s", err) + } + + lines, err = tflogtest.MultilineJSONDecode(&buf) + if err != nil { + t.Fatalf("GetAwsAccountIDAndPartition: decoding log lines: %s", err) + } + + if len(lines) == 0 { + t.Fatalf("expected log entries, had none") + } + for i, line := range lines { + if a, e := line["@module"], expectedName; a != e { + t.Errorf("GetAwsAccountIDAndPartition: line %d: expected module %q, got %q", i+1, e, a) + } + } +} + +// configureHcLogger configures the default logger with settings suitable for testing: +// +// - Log level set to TRACE +// - Written to the io.Writer passed in, such as a bytes.Buffer +// - Log entries are in JSON format, and can be decoded using multilineJSONDecode +// - Caller information is not included +// - Timestamp is not included +func configureHcLogger(name string, output io.Writer) hclog.Logger { + logger := hclog.NewInterceptLogger(&hclog.LoggerOptions{ + Name: name, + Level: hclog.Trace, + Output: output, + IndependentLevels: true, + JSONFormat: true, + IncludeLocation: false, + DisableTime: true, + }) + + return logger +} diff --git a/internal/config/config.go b/internal/config/config.go index 80aacde8..33eb0bd4 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -16,6 +16,7 @@ import ( awshttp "github.com/aws/aws-sdk-go-v2/aws/transport/http" "github.com/aws/aws-sdk-go-v2/feature/ec2/imds" "github.com/hashicorp/aws-sdk-go-base/v2/internal/expand" + "github.com/hashicorp/aws-sdk-go-base/v2/logging" ) type Config struct { @@ -33,6 +34,7 @@ type Config struct { HTTPProxy string IamEndpoint string Insecure bool + Logger logging.Logger MaxRetries int Profile string Region string diff --git a/logging/null_logger.go b/logging/null_logger.go new file mode 100644 index 00000000..ee703801 --- /dev/null +++ b/logging/null_logger.go @@ -0,0 +1,33 @@ +// Copyright (c) HashiCorp, Inc. +// SPDX-License-Identifier: MPL-2.0 + +package logging + +import ( + "context" +) + +type NullLogger struct { +} + +var _ Logger = NullLogger{} + +func (l NullLogger) SubLogger(ctx context.Context, name string) (context.Context, Logger) { + return ctx, l +} + +func (l NullLogger) Warn(ctx context.Context, msg string, fields ...map[string]any) { +} + +func (l NullLogger) Info(ctx context.Context, msg string, fields ...map[string]any) { +} + +func (l NullLogger) Debug(ctx context.Context, msg string, fields ...map[string]any) { +} + +func (l NullLogger) Trace(ctx context.Context, msg string, fields ...map[string]any) { +} + +func (l NullLogger) SetField(ctx context.Context, key string, value any) context.Context { + return ctx +} diff --git a/v2/awsv1shim/session.go b/v2/awsv1shim/session.go index 82b2f100..56e239ea 100644 --- a/v2/awsv1shim/session.go +++ b/v2/awsv1shim/session.go @@ -82,8 +82,11 @@ const loggerName string = "aws-base-v1" func GetSession(ctx context.Context, awsC *awsv2.Config, c *awsbase.Config) (*session.Session, diag.Diagnostics) { var diags diag.Diagnostics - ctx, tflogger := logging.NewTfLogger(ctx) - ctx, logger := tflogger.SubLogger(ctx, loggerName) + var logger logging.Logger = logging.NullLogger{} + if c.Logger != nil { + logger = c.Logger + } + ctx, logger = logger.SubLogger(ctx, loggerName) ctx = logging.RegisterLogger(ctx, logger) options, err := getSessionOptions(ctx, awsC, c) diff --git a/v2/awsv1shim/session_test.go b/v2/awsv1shim/session_test.go index aae5f7ed..b3b0b683 100644 --- a/v2/awsv1shim/session_test.go +++ b/v2/awsv1shim/session_test.go @@ -36,6 +36,7 @@ import ( "github.com/hashicorp/aws-sdk-go-base/v2/diag" "github.com/hashicorp/aws-sdk-go-base/v2/internal/constants" "github.com/hashicorp/aws-sdk-go-base/v2/internal/test" + "github.com/hashicorp/aws-sdk-go-base/v2/logging" "github.com/hashicorp/aws-sdk-go-base/v2/servicemocks" "github.com/hashicorp/aws-sdk-go-base/v2/useragent" "github.com/hashicorp/terraform-plugin-log/tflogtest" @@ -2600,8 +2601,11 @@ func TestLogger(t *testing.T) { oldEnv := servicemocks.InitSessionTestEnv() defer servicemocks.PopEnv(oldEnv) + ctx, logger := logging.NewTfLogger(ctx) + config := &awsbase.Config{ AccessKey: servicemocks.MockStaticAccessKey, + Logger: logger, Region: "us-east-1", SecretKey: servicemocks.MockStaticSecretKey, } From 58914ff2d8ed80339fb8b1c5e5e58f1cbb239d12 Mon Sep 17 00:00:00 2001 From: Graham Davison Date: Wed, 9 Aug 2023 16:33:49 -0700 Subject: [PATCH 5/6] Prevents panic when no logger is configured --- logging/context.go | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/logging/context.go b/logging/context.go index f6e3f735..0d18f3f8 100644 --- a/logging/context.go +++ b/logging/context.go @@ -16,5 +16,9 @@ func RegisterLogger(ctx context.Context, logger Logger) context.Context { } func RetrieveLogger(ctx context.Context) Logger { - return ctx.Value(loggerKey).(Logger) + logger, ok := ctx.Value(loggerKey).(Logger) + if !ok { + return NullLogger{} + } + return logger } From 072a66686887d9cd8e2ef0ac37e4504d500c5cd0 Mon Sep 17 00:00:00 2001 From: Graham Davison Date: Wed, 9 Aug 2023 16:44:12 -0700 Subject: [PATCH 6/6] `go mod tidy` --- go.mod | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/go.mod b/go.mod index 70692287..d673ca8b 100644 --- a/go.mod +++ b/go.mod @@ -11,6 +11,7 @@ require ( github.com/aws/aws-sdk-go-v2/service/sts v1.21.1 github.com/aws/smithy-go v1.14.0 github.com/google/go-cmp v0.5.9 + github.com/hashicorp/go-hclog v1.5.0 github.com/hashicorp/go-multierror v1.1.1 github.com/hashicorp/terraform-plugin-log v0.9.0 github.com/mitchellh/go-homedir v1.1.0 @@ -27,7 +28,6 @@ require ( github.com/aws/aws-sdk-go-v2/service/ssooidc v1.15.1 // indirect github.com/fatih/color v1.15.0 // indirect github.com/hashicorp/errwrap v1.1.0 // indirect - github.com/hashicorp/go-hclog v1.5.0 // indirect github.com/mattn/go-colorable v0.1.13 // indirect github.com/mattn/go-isatty v0.0.17 // indirect github.com/mitchellh/go-testing-interface v1.14.1 // indirect