From 3dd1bf9e692496d9ccdbc83fc78ead90bc5924ac Mon Sep 17 00:00:00 2001 From: Brian Flad Date: Wed, 13 Apr 2022 09:03:51 -0400 Subject: [PATCH] all: Replace various log.Printf calls with tfsdklog calls Reference: https://github.com/hashicorp/terraform-plugin-sdk/issues/863 By default, the standard library `log` package will include the short timestamp and date flags, which when output will prefix any messaging, e.g. ```text # From log.Printf("[DEBUG] Test message") 2022/01/26 16:25:33 [DEBUG] Test message ``` When a provider is running in production and the log output is being sent across the go-plugin boundary, Terraform CLI generally expects a hc-log formatted entry (square bracket log level prefixed message) or will output the raw message. So in many cases, this class of logging shows up in production logs as the raw message and the log level is not recognized, which is confusing for practitioners and provider developers: ```text 2022-01-26T16:25:33.123-0800 [INFO] provider.terraform-provider-example_v9.9.9_x5: 2022/01/26 16:25:33 [DEBUG] Test Message: timestamp=2022-01-26T16:25:33.123-0800 ``` Setting the `log` package default logger to not include those flags via `log.SetFlags(0)` early in the SDK lifecycle may represent a breaking change for any providers depending on the current behavior, so this easier class of fix is not acceptable. Now that this SDK implements the `tfsdklog` package, logging can be converted to that style, which fixes the above issue and these messages will now also include all the gathered logging context up to the call such as the RPC name and a request UUID. There are quite a few other `log.Printf()` calls across the project, however they are non-trivial to update as: * The logging context is not present or not guaranteed to be present (as is the case with `(helper/resource.StateChangeConf).WaitContext()`) * The functions/methods are exported, so changing the signature is an unacceptable change * The functions/methods while unexported are eventually surfaced via an exported type/function, so it could indirectly require breaking changes Given that `helper/resource.StateChangeConf`, which also underlies `helper/resource.Retry*` functionality, is quite common across provider usage, a separate custom logging solution may be introduced there as a separate change. --- helper/resource/plugin.go | 3 +-- helper/schema/grpc_provider.go | 8 +++--- helper/schema/provider.go | 2 +- helper/schema/resource.go | 13 +++++----- helper/schema/resource_diff_test.go | 11 ++++---- helper/schema/schema.go | 25 ++++++++++-------- internal/logging/helper_schema.go | 5 ++++ internal/plugin/convert/schema.go | 35 +++++++++++++------------- internal/plugin/convert/schema_test.go | 5 ++-- 9 files changed, 58 insertions(+), 49 deletions(-) diff --git a/helper/resource/plugin.go b/helper/resource/plugin.go index b1c26d11e00..d9bc172ea9a 100644 --- a/helper/resource/plugin.go +++ b/helper/resource/plugin.go @@ -4,7 +4,6 @@ import ( "context" "fmt" "io/ioutil" - "log" "os" "strings" "sync" @@ -330,7 +329,7 @@ func runProviderCommand(ctx context.Context, t testing.T, f func() error, wd *pl // started. err := f() if err != nil { - log.Printf("[WARN] Got error running Terraform: %s", err) + logging.HelperResourceWarn(ctx, "Error running Terraform CLI command", map[string]interface{}{logging.KeyError: err}) } logging.HelperResourceTrace(ctx, "Called wrapped Terraform CLI command") diff --git a/helper/schema/grpc_provider.go b/helper/schema/grpc_provider.go index 8ab3fb98ef2..ec3ed07c102 100644 --- a/helper/schema/grpc_provider.go +++ b/helper/schema/grpc_provider.go @@ -75,11 +75,11 @@ func (s *GRPCProviderServer) GetProviderSchema(ctx context.Context, req *tfproto } resp.Provider = &tfprotov5.Schema{ - Block: convert.ConfigSchemaToProto(s.getProviderSchemaBlock()), + Block: convert.ConfigSchemaToProto(ctx, s.getProviderSchemaBlock()), } resp.ProviderMeta = &tfprotov5.Schema{ - Block: convert.ConfigSchemaToProto(s.getProviderMetaSchemaBlock()), + Block: convert.ConfigSchemaToProto(ctx, s.getProviderMetaSchemaBlock()), } for typ, res := range s.provider.ResourcesMap { @@ -87,7 +87,7 @@ func (s *GRPCProviderServer) GetProviderSchema(ctx context.Context, req *tfproto resp.ResourceSchemas[typ] = &tfprotov5.Schema{ Version: int64(res.SchemaVersion), - Block: convert.ConfigSchemaToProto(res.CoreConfigSchema()), + Block: convert.ConfigSchemaToProto(ctx, res.CoreConfigSchema()), } } @@ -96,7 +96,7 @@ func (s *GRPCProviderServer) GetProviderSchema(ctx context.Context, req *tfproto resp.DataSourceSchemas[typ] = &tfprotov5.Schema{ Version: int64(dat.SchemaVersion), - Block: convert.ConfigSchemaToProto(dat.CoreConfigSchema()), + Block: convert.ConfigSchemaToProto(ctx, dat.CoreConfigSchema()), } } diff --git a/helper/schema/provider.go b/helper/schema/provider.go index b21e1067730..91a21b38908 100644 --- a/helper/schema/provider.go +++ b/helper/schema/provider.go @@ -266,7 +266,7 @@ func (p *Provider) Configure(ctx context.Context, c *terraform.ResourceConfig) d } if p.configured { - log.Printf("[WARN] Previously configured provider being re-configured. This can cause issues in concurrent testing if the configurations are not equal.") + logging.HelperSchemaWarn(ctx, "Previously configured provider being re-configured. This can cause issues in concurrent testing if the configurations are not equal.") } sm := schemaMap(p.Schema) diff --git a/helper/schema/resource.go b/helper/schema/resource.go index 136ed036d7d..5b40bec8964 100644 --- a/helper/schema/resource.go +++ b/helper/schema/resource.go @@ -4,7 +4,6 @@ import ( "context" "errors" "fmt" - "log" "strconv" "github.com/hashicorp/go-cty/cty" @@ -779,16 +778,16 @@ func (r *Resource) Apply( rt := ResourceTimeout{} if _, ok := d.Meta[TimeoutKey]; ok { if err := rt.DiffDecode(d); err != nil { - log.Printf("[ERR] Error decoding ResourceTimeout: %s", err) + logging.HelperSchemaError(ctx, "Error decoding ResourceTimeout", map[string]interface{}{logging.KeyError: err}) } } else if s != nil { if _, ok := s.Meta[TimeoutKey]; ok { if err := rt.StateDecode(s); err != nil { - log.Printf("[ERR] Error decoding ResourceTimeout: %s", err) + logging.HelperSchemaError(ctx, "Error decoding ResourceTimeout", map[string]interface{}{logging.KeyError: err}) } } } else { - log.Printf("[DEBUG] No meta timeoutkey found in Apply()") + logging.HelperSchemaDebug(ctx, "No meta timeoutkey found in Apply()") } data.timeouts = &rt @@ -873,10 +872,10 @@ func (r *Resource) Diff( if instanceDiff != nil { if err := t.DiffEncode(instanceDiff); err != nil { - log.Printf("[ERR] Error encoding timeout to instance diff: %s", err) + logging.HelperSchemaError(ctx, "Error encoding timeout to instance diff", map[string]interface{}{logging.KeyError: err}) } } else { - log.Printf("[DEBUG] Instance Diff is nil in Diff()") + logging.HelperSchemaDebug(ctx, "Instance Diff is nil in Diff()") } return instanceDiff, err @@ -972,7 +971,7 @@ func (r *Resource) RefreshWithoutUpgrade( rt := ResourceTimeout{} if _, ok := s.Meta[TimeoutKey]; ok { if err := rt.StateDecode(s); err != nil { - log.Printf("[ERR] Error decoding ResourceTimeout: %s", err) + logging.HelperSchemaError(ctx, "Error decoding ResourceTimeout", map[string]interface{}{logging.KeyError: err}) } } diff --git a/helper/schema/resource_diff_test.go b/helper/schema/resource_diff_test.go index cdc5a36f84d..edd9df1cfb4 100644 --- a/helper/schema/resource_diff_test.go +++ b/helper/schema/resource_diff_test.go @@ -1,6 +1,7 @@ package schema import ( + "context" "fmt" "reflect" "sort" @@ -649,7 +650,7 @@ func TestSetNew(t *testing.T) { return } for _, k := range d.UpdatedKeys() { - if err := m.diff(k, m[k], tc.Diff, d, false); err != nil { + if err := m.diff(context.Background(), k, m[k], tc.Diff, d, false); err != nil { t.Fatalf("bad: %s", err) } } @@ -676,7 +677,7 @@ func TestSetNewComputed(t *testing.T) { return } for _, k := range d.UpdatedKeys() { - if err := m.diff(k, m[k], tc.Diff, d, false); err != nil { + if err := m.diff(context.Background(), k, m[k], tc.Diff, d, false); err != nil { t.Fatalf("bad: %s", err) } } @@ -945,7 +946,7 @@ func TestForceNew(t *testing.T) { return } for _, k := range d.UpdatedKeys() { - if err := m.diff(k, m[k], tc.Diff, d, false); err != nil { + if err := m.diff(context.Background(), k, m[k], tc.Diff, d, false); err != nil { t.Fatalf("bad: %s", err) } } @@ -1194,7 +1195,7 @@ func TestClear(t *testing.T) { return } for _, k := range d.UpdatedKeys() { - if err := m.diff(k, m[k], tc.Diff, d, false); err != nil { + if err := m.diff(context.Background(), k, m[k], tc.Diff, d, false); err != nil { t.Fatalf("bad: %s", err) } } @@ -1436,7 +1437,7 @@ func TestGetChangedKeysPrefix(t *testing.T) { keys := d.GetChangedKeysPrefix(tc.Key) for _, k := range d.UpdatedKeys() { - if err := m.diff(k, m[k], tc.Diff, d, false); err != nil { + if err := m.diff(context.Background(), k, m[k], tc.Diff, d, false); err != nil { t.Fatalf("bad: %s", err) } } diff --git a/helper/schema/schema.go b/helper/schema/schema.go index fdd080a9737..7cbd5858917 100644 --- a/helper/schema/schema.go +++ b/helper/schema/schema.go @@ -654,7 +654,7 @@ func (m schemaMap) Diff( } for k, schema := range m { - err := m.diff(k, schema, result, d, false) + err := m.diff(ctx, k, schema, result, d, false) if err != nil { return nil, err } @@ -681,7 +681,7 @@ func (m schemaMap) Diff( return nil, err } for _, k := range rd.UpdatedKeys() { - err := m.diff(k, mc[k], result, rd, false) + err := m.diff(ctx, k, mc[k], result, rd, false) if err != nil { return nil, err } @@ -708,7 +708,7 @@ func (m schemaMap) Diff( // Perform the diff again for k, schema := range m { - err := m.diff(k, schema, result2, d, false) + err := m.diff(ctx, k, schema, result2, d, false) if err != nil { return nil, err } @@ -722,7 +722,7 @@ func (m schemaMap) Diff( return nil, err } for _, k := range rd.UpdatedKeys() { - err := m.diff(k, mc[k], result2, rd, false) + err := m.diff(ctx, k, mc[k], result2, rd, false) if err != nil { return nil, err } @@ -1087,6 +1087,7 @@ type resourceDiffer interface { } func (m schemaMap) diff( + ctx context.Context, k string, schema *Schema, diff *terraform.InstanceDiff, @@ -1101,11 +1102,11 @@ func (m schemaMap) diff( case TypeBool, TypeInt, TypeFloat, TypeString: err = m.diffString(k, schema, unsupressedDiff, d, all) case TypeList: - err = m.diffList(k, schema, unsupressedDiff, d, all) + err = m.diffList(ctx, k, schema, unsupressedDiff, d, all) case TypeMap: err = m.diffMap(k, schema, unsupressedDiff, d, all) case TypeSet: - err = m.diffSet(k, schema, unsupressedDiff, d, all) + err = m.diffSet(ctx, k, schema, unsupressedDiff, d, all) default: err = fmt.Errorf("%s: unknown type %#v", k, schema.Type) } @@ -1122,7 +1123,7 @@ func (m schemaMap) diff( continue } - log.Printf("[DEBUG] ignoring change of %q due to DiffSuppressFunc", attrK) + logging.HelperSchemaDebug(ctx, "Ignoring change due to DiffSuppressFunc", map[string]interface{}{logging.KeyAttributePath: attrK}) attrV = &terraform.ResourceAttrDiff{ Old: attrV.Old, New: attrV.Old, @@ -1136,6 +1137,7 @@ func (m schemaMap) diff( } func (m schemaMap) diffList( + ctx context.Context, k string, schema *Schema, diff *terraform.InstanceDiff, @@ -1234,7 +1236,7 @@ func (m schemaMap) diffList( for i := 0; i < maxLen; i++ { for k2, schema := range t.Schema { subK := fmt.Sprintf("%s.%d.%s", k, i, k2) - err := m.diff(subK, schema, diff, d, all) + err := m.diff(ctx, subK, schema, diff, d, all) if err != nil { return err } @@ -1250,7 +1252,7 @@ func (m schemaMap) diffList( // just diff each. for i := 0; i < maxLen; i++ { subK := fmt.Sprintf("%s.%d", k, i) - err := m.diff(subK, &t2, diff, d, all) + err := m.diff(ctx, subK, &t2, diff, d, all) if err != nil { return err } @@ -1375,6 +1377,7 @@ func (m schemaMap) diffMap( } func (m schemaMap) diffSet( + ctx context.Context, k string, schema *Schema, diff *terraform.InstanceDiff, @@ -1480,7 +1483,7 @@ func (m schemaMap) diffSet( // This is a complex resource for k2, schema := range t.Schema { subK := fmt.Sprintf("%s.%s.%s", k, code, k2) - err := m.diff(subK, schema, diff, d, true) + err := m.diff(ctx, subK, schema, diff, d, true) if err != nil { return err } @@ -1494,7 +1497,7 @@ func (m schemaMap) diffSet( // This is just a primitive element, so go through each and // just diff each. subK := fmt.Sprintf("%s.%s", k, code) - err := m.diff(subK, &t2, diff, d, true) + err := m.diff(ctx, subK, &t2, diff, d, true) if err != nil { return err } diff --git a/internal/logging/helper_schema.go b/internal/logging/helper_schema.go index adbdac798b7..b2fe71d15d6 100644 --- a/internal/logging/helper_schema.go +++ b/internal/logging/helper_schema.go @@ -16,6 +16,11 @@ func HelperSchemaDebug(ctx context.Context, msg string, additionalFields ...map[ tfsdklog.SubsystemDebug(ctx, SubsystemHelperSchema, msg, additionalFields...) } +// HelperSchemaError emits a helper/schema subsystem log at ERROR level. +func HelperSchemaError(ctx context.Context, msg string, additionalFields ...map[string]interface{}) { + tfsdklog.SubsystemError(ctx, SubsystemHelperSchema, msg, additionalFields...) +} + // HelperSchemaTrace emits a helper/schema subsystem log at TRACE level. func HelperSchemaTrace(ctx context.Context, msg string, additionalFields ...map[string]interface{}) { tfsdklog.SubsystemTrace(ctx, SubsystemHelperSchema, msg, additionalFields...) diff --git a/internal/plugin/convert/schema.go b/internal/plugin/convert/schema.go index c5dbf5b8fde..07d0b89783c 100644 --- a/internal/plugin/convert/schema.go +++ b/internal/plugin/convert/schema.go @@ -1,8 +1,8 @@ package convert import ( + "context" "fmt" - "log" "reflect" "sort" @@ -10,6 +10,7 @@ import ( "github.com/hashicorp/terraform-plugin-go/tfprotov5" "github.com/hashicorp/terraform-plugin-go/tftypes" "github.com/hashicorp/terraform-plugin-sdk/v2/internal/configs/configschema" + "github.com/hashicorp/terraform-plugin-sdk/v2/internal/logging" ) func tftypeFromCtyType(in cty.Type) (tftypes.Type, error) { @@ -128,10 +129,10 @@ func ctyTypeFromTFType(in tftypes.Type) (cty.Type, error) { // ConfigSchemaToProto takes a *configschema.Block and converts it to a // tfprotov5.SchemaBlock for a grpc response. -func ConfigSchemaToProto(b *configschema.Block) *tfprotov5.SchemaBlock { +func ConfigSchemaToProto(ctx context.Context, b *configschema.Block) *tfprotov5.SchemaBlock { block := &tfprotov5.SchemaBlock{ Description: b.Description, - DescriptionKind: protoStringKind(b.DescriptionKind), + DescriptionKind: protoStringKind(ctx, b.DescriptionKind), Deprecated: b.Deprecated, } @@ -141,7 +142,7 @@ func ConfigSchemaToProto(b *configschema.Block) *tfprotov5.SchemaBlock { attr := &tfprotov5.SchemaAttribute{ Name: name, Description: a.Description, - DescriptionKind: protoStringKind(a.DescriptionKind), + DescriptionKind: protoStringKind(ctx, a.DescriptionKind), Optional: a.Optional, Computed: a.Computed, Required: a.Required, @@ -160,16 +161,16 @@ func ConfigSchemaToProto(b *configschema.Block) *tfprotov5.SchemaBlock { for _, name := range sortedKeys(b.BlockTypes) { b := b.BlockTypes[name] - block.BlockTypes = append(block.BlockTypes, protoSchemaNestedBlock(name, b)) + block.BlockTypes = append(block.BlockTypes, protoSchemaNestedBlock(ctx, name, b)) } return block } -func protoStringKind(k configschema.StringKind) tfprotov5.StringKind { +func protoStringKind(ctx context.Context, k configschema.StringKind) tfprotov5.StringKind { switch k { default: - log.Printf("[TRACE] unexpected configschema.StringKind: %d", k) + logging.HelperSchemaTrace(ctx, fmt.Sprintf("Unexpected configschema.StringKind: %d", k)) return tfprotov5.StringKindPlain case configschema.StringPlain: return tfprotov5.StringKindPlain @@ -178,7 +179,7 @@ func protoStringKind(k configschema.StringKind) tfprotov5.StringKind { } } -func protoSchemaNestedBlock(name string, b *configschema.NestedBlock) *tfprotov5.SchemaNestedBlock { +func protoSchemaNestedBlock(ctx context.Context, name string, b *configschema.NestedBlock) *tfprotov5.SchemaNestedBlock { var nesting tfprotov5.SchemaNestedBlockNestingMode switch b.Nesting { case configschema.NestingSingle: @@ -196,7 +197,7 @@ func protoSchemaNestedBlock(name string, b *configschema.NestedBlock) *tfprotov5 } return &tfprotov5.SchemaNestedBlock{ TypeName: name, - Block: ConfigSchemaToProto(&b.Block), + Block: ConfigSchemaToProto(ctx, &b.Block), Nesting: nesting, MinItems: int64(b.MinItems), MaxItems: int64(b.MaxItems), @@ -205,20 +206,20 @@ func protoSchemaNestedBlock(name string, b *configschema.NestedBlock) *tfprotov5 // ProtoToConfigSchema takes the GetSchema_Block from a grpc response and converts it // to a terraform *configschema.Block. -func ProtoToConfigSchema(b *tfprotov5.SchemaBlock) *configschema.Block { +func ProtoToConfigSchema(ctx context.Context, b *tfprotov5.SchemaBlock) *configschema.Block { block := &configschema.Block{ Attributes: make(map[string]*configschema.Attribute), BlockTypes: make(map[string]*configschema.NestedBlock), Description: b.Description, - DescriptionKind: schemaStringKind(b.DescriptionKind), + DescriptionKind: schemaStringKind(ctx, b.DescriptionKind), Deprecated: b.Deprecated, } for _, a := range b.Attributes { attr := &configschema.Attribute{ Description: a.Description, - DescriptionKind: schemaStringKind(a.DescriptionKind), + DescriptionKind: schemaStringKind(ctx, a.DescriptionKind), Required: a.Required, Optional: a.Optional, Computed: a.Computed, @@ -236,16 +237,16 @@ func ProtoToConfigSchema(b *tfprotov5.SchemaBlock) *configschema.Block { } for _, b := range b.BlockTypes { - block.BlockTypes[b.TypeName] = schemaNestedBlock(b) + block.BlockTypes[b.TypeName] = schemaNestedBlock(ctx, b) } return block } -func schemaStringKind(k tfprotov5.StringKind) configschema.StringKind { +func schemaStringKind(ctx context.Context, k tfprotov5.StringKind) configschema.StringKind { switch k { default: - log.Printf("[TRACE] unexpected tfprotov5.StringKind: %d", k) + logging.HelperSchemaTrace(ctx, fmt.Sprintf("Unexpected tfprotov5.StringKind: %d", k)) return configschema.StringPlain case tfprotov5.StringKindPlain: return configschema.StringPlain @@ -254,7 +255,7 @@ func schemaStringKind(k tfprotov5.StringKind) configschema.StringKind { } } -func schemaNestedBlock(b *tfprotov5.SchemaNestedBlock) *configschema.NestedBlock { +func schemaNestedBlock(ctx context.Context, b *tfprotov5.SchemaNestedBlock) *configschema.NestedBlock { var nesting configschema.NestingMode switch b.Nesting { case tfprotov5.SchemaNestedBlockNestingModeSingle: @@ -278,7 +279,7 @@ func schemaNestedBlock(b *tfprotov5.SchemaNestedBlock) *configschema.NestedBlock MaxItems: int(b.MaxItems), } - nested := ProtoToConfigSchema(b.Block) + nested := ProtoToConfigSchema(ctx, b.Block) nb.Block = *nested return nb } diff --git a/internal/plugin/convert/schema_test.go b/internal/plugin/convert/schema_test.go index c782bc14d3c..e3736fb01b7 100644 --- a/internal/plugin/convert/schema_test.go +++ b/internal/plugin/convert/schema_test.go @@ -1,6 +1,7 @@ package convert import ( + "context" "testing" "github.com/google/go-cmp/cmp" @@ -186,7 +187,7 @@ func TestConvertSchemaBlocks(t *testing.T) { for name, tc := range tests { t.Run(name, func(t *testing.T) { - converted := ProtoToConfigSchema(tc.Block) + converted := ProtoToConfigSchema(context.Background(), tc.Block) if !cmp.Equal(converted, tc.Want, typeComparer, valueComparer, equateEmpty) { t.Fatal(cmp.Diff(converted, tc.Want, typeComparer, valueComparer, equateEmpty)) } @@ -362,7 +363,7 @@ func TestConvertProtoSchemaBlocks(t *testing.T) { for name, tc := range tests { t.Run(name, func(t *testing.T) { - converted := ConfigSchemaToProto(tc.Block) + converted := ConfigSchemaToProto(context.Background(), tc.Block) if !cmp.Equal(converted, tc.Want, typeComparer, equateEmpty) { t.Fatal(cmp.Diff(converted, tc.Want, typeComparer, equateEmpty)) }