Skip to content

Commit

Permalink
all: Replace various log.Printf calls with tfsdklog calls (#940)
Browse files Browse the repository at this point in the history 
Reference: #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.
  • Loading branch information
@bflad
bflad committed Apr 14, 2022
1 parent 466cbe5 commit 5d701f2
Show file tree
Hide file tree
Showing 9 changed files with 58 additions and 49 deletions.
3 changes: 1 addition & 2 deletions helper/resource/plugin.go
View file
Expand Up @@ -4,7 +4,6 @@ import (
"context"
"fmt"
"io/ioutil"
"log"
"os"
"strings"
"sync"
Expand Down Expand Up @@ -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")
Expand Down
8 changes: 4 additions & 4 deletions helper/schema/grpc_provider.go
View file
Expand Up @@ -75,19 +75,19 @@ 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 {
logging.HelperSchemaTrace(ctx, "Found resource type", map[string]interface{}{logging.KeyResourceType: typ})

resp.ResourceSchemas[typ] = &tfprotov5.Schema{
Version: int64(res.SchemaVersion),
Block: convert.ConfigSchemaToProto(res.CoreConfigSchema()),
Block: convert.ConfigSchemaToProto(ctx, res.CoreConfigSchema()),
}
}

Expand All @@ -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()),
}
}

Expand Down
2 changes: 1 addition & 1 deletion helper/schema/provider.go
View file
Expand Up @@ -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)
Expand Down
13 changes: 6 additions & 7 deletions helper/schema/resource.go
View file
Expand Up @@ -4,7 +4,6 @@ import (
"context"
"errors"
"fmt"
"log"
"strconv"

"github.com/hashicorp/go-cty/cty"
Expand Down Expand Up @@ -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

Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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})
}
}

Expand Down
11 changes: 6 additions & 5 deletions helper/schema/resource_diff_test.go
View file
@@ -1,6 +1,7 @@
package schema

import (
"context"
"fmt"
"reflect"
"sort"
Expand Down Expand Up @@ -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)
}
}
Expand All @@ -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)
}
}
Expand Down Expand Up @@ -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)
}
}
Expand Down Expand Up @@ -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)
}
}
Expand Down Expand Up @@ -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)
}
}
Expand Down
25 changes: 14 additions & 11 deletions helper/schema/schema.go
View file
Expand Up @@ -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
}
Expand All @@ -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
}
Expand All @@ -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
}
Expand All @@ -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
}
Expand Down Expand Up @@ -1087,6 +1087,7 @@ type resourceDiffer interface {
}

func (m schemaMap) diff(
ctx context.Context,
k string,
schema *Schema,
diff *terraform.InstanceDiff,
Expand All @@ -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)
}
Expand All @@ -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,
Expand All @@ -1136,6 +1137,7 @@ func (m schemaMap) diff(
}

func (m schemaMap) diffList(
ctx context.Context,
k string,
schema *Schema,
diff *terraform.InstanceDiff,
Expand Down Expand Up @@ -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
}
Expand All @@ -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
}
Expand Down Expand Up @@ -1375,6 +1377,7 @@ func (m schemaMap) diffMap(
}

func (m schemaMap) diffSet(
ctx context.Context,
k string,
schema *Schema,
diff *terraform.InstanceDiff,
Expand Down Expand Up @@ -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
}
Expand All @@ -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
}
Expand Down
5 changes: 5 additions & 0 deletions internal/logging/helper_schema.go
View file
Expand Up @@ -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...)
Expand Down

0 comments on commit 5d701f2

Please sign in to comment.