tfsdk: Introduce internal/logging package (#291)

Similar to other terraform-plugin-* projects. Migrated all existing tfsdklog calls to a new framework subsystem so consumers can filter this project's logs. Additional subsystems may be added in the future.

internal/logging/context.go

@@ -0,0 +1,20 @@
+package logging
+
+import (
+	"context"
+
+	"github.com/hashicorp/terraform-plugin-log/tfsdklog"
+)
+
+// InitContext creates SDK logger contexts. The incoming context will
+// already have the root SDK logger and root provider logger setup from
+// terraform-plugin-go tf6server RPC handlers.
+func InitContext(ctx context.Context) context.Context {
+	ctx = tfsdklog.NewSubsystem(ctx, SubsystemFramework,
+		// All calls are through the Framework* helper functions
+		tfsdklog.WithAdditionalLocationOffset(1),
+		tfsdklog.WithLevelFromEnv(EnvTfLogSdkFramework),
+	)
+
+	return ctx
+}

internal/logging/environment_variables.go

@@ -0,0 +1,9 @@
+package logging
+
+// Environment variables.
+const (
+	// EnvTfLogSdkFramework is an environment variable that sets the logging
+	// level of SDK framework loggers. Infers root SDK logging level, if
+	// unset.
+	EnvTfLogSdkFramework = "TF_LOG_SDK_FRAMEWORK"
+)

internal/logging/framework.go

@@ -0,0 +1,32 @@
+package logging
+
+import (
+	"context"
+
+	"github.com/hashicorp/terraform-plugin-log/tfsdklog"
+)
+
+const (
+	// SubsystemFramework is the tfsdklog subsystem name for framework.
+	SubsystemFramework = "framework"
+)
+
+// FrameworkDebug emits a framework subsystem log at DEBUG level.
+func FrameworkDebug(ctx context.Context, msg string, additionalFields ...map[string]interface{}) {
+	tfsdklog.SubsystemDebug(ctx, SubsystemFramework, msg, additionalFields...)
+}
+
+// FrameworkError emits a framework subsystem log at ERROR level.
+func FrameworkError(ctx context.Context, msg string, additionalFields ...map[string]interface{}) {
+	tfsdklog.SubsystemError(ctx, SubsystemFramework, msg, additionalFields...)
+}
+
+// FrameworkTrace emits a framework subsystem log at TRACE level.
+func FrameworkTrace(ctx context.Context, msg string, additionalFields ...map[string]interface{}) {
+	tfsdklog.SubsystemTrace(ctx, SubsystemFramework, msg, additionalFields...)
+}
+
+// FrameworkWarn emits a framework subsystem log at WARN level.
+func FrameworkWarn(ctx context.Context, msg string, additionalFields ...map[string]interface{}) {
+	tfsdklog.SubsystemWarn(ctx, SubsystemFramework, msg, additionalFields...)
+}

internal/logging/keys.go

@@ -0,0 +1,23 @@
+package logging
+
+// Structured logging keys.
+//
+// Practitioners or tooling reading logs may be depending on these keys, so be
+// conscious of that when changing them.
+//
+// Refer to the terraform-plugin-go logging keys as well, which should be
+// equivalent to these when possible.
+const (
+	// Attribute path representation, which is typically in flatmap form such
+	// as parent.0.child in this project.
+	KeyAttributePath = "tf_attribute_path"
+
+	// The type of data source being operated on, such as "archive_file"
+	KeyDataSourceType = "tf_data_source_type"
+
+	// Underlying Go error string when logging an error.
+	KeyError = "error"
+
+	// The type of resource being operated on, such as "random_pet"
+	KeyResourceType = "tf_resource_type"
+)

tfsdk/attribute_plan_modification.go

@@ -7,8 +7,8 @@ import (
 
 	"github.com/hashicorp/terraform-plugin-framework/attr"
 	"github.com/hashicorp/terraform-plugin-framework/diag"
+	"github.com/hashicorp/terraform-plugin-framework/internal/logging"
 	"github.com/hashicorp/terraform-plugin-go/tftypes"
-	"github.com/hashicorp/terraform-plugin-log/tfsdklog"
 )
 
 // AttributePlanModifier represents a modifier for an attribute at plan time.
@@ -309,7 +309,7 @@ func (r RequiresReplaceIfModifier) Modify(ctx context.Context, req ModifyAttribu
 	if res {
 		resp.RequiresReplace = true
 	} else if resp.RequiresReplace {
-		tfsdklog.Debug(ctx, "Keeping previous attribute replacement requirement", map[string]interface{}{"attribute_path": req.AttributePath.String()})
+		logging.FrameworkDebug(ctx, "Keeping previous attribute replacement requirement", map[string]interface{}{logging.KeyAttributePath: req.AttributePath.String()})
 	}
 }
 

tfsdk/serve.go

@@ -8,11 +8,11 @@ import (
 	"sync"
 
 	"github.com/hashicorp/terraform-plugin-framework/diag"
+	"github.com/hashicorp/terraform-plugin-framework/internal/logging"
 	"github.com/hashicorp/terraform-plugin-framework/internal/proto6"
 	"github.com/hashicorp/terraform-plugin-go/tfprotov6"
 	"github.com/hashicorp/terraform-plugin-go/tfprotov6/tf6server"
 	"github.com/hashicorp/terraform-plugin-go/tftypes"
-	"github.com/hashicorp/terraform-plugin-log/tfsdklog"
 )
 
 var _ tfprotov6.ProviderServer = &server{}
@@ -187,6 +187,7 @@ func (s *server) getProviderSchema(ctx context.Context, resp *getProviderSchemaR
 	}
 	resource6Schemas := map[string]*tfprotov6.Schema{}
 	for k, v := range resourceSchemas {
+		logging.FrameworkTrace(ctx, "Found resource type", map[string]interface{}{logging.KeyResourceType: k})
 		schema, diags := v.GetSchema(ctx)
 		resp.Diagnostics.Append(diags...)
 		if resp.Diagnostics.HasError() {
@@ -211,6 +212,7 @@ func (s *server) getProviderSchema(ctx context.Context, resp *getProviderSchemaR
 	}
 	dataSource6Schemas := map[string]*tfprotov6.Schema{}
 	for k, v := range dataSourceSchemas {
+		logging.FrameworkTrace(ctx, "Found data source type", map[string]interface{}{logging.KeyDataSourceType: k})
 		schema, diags := v.GetSchema(ctx)
 		resp.Diagnostics.Append(diags...)
 		if resp.Diagnostics.HasError() {
@@ -689,27 +691,27 @@ func markComputedNilsAsUnknown(ctx context.Context, config tftypes.Value, resour
 		}
 		configVal, _, err := tftypes.WalkAttributePath(config, path)
 		if err != tftypes.ErrInvalidStep && err != nil {
-			tfsdklog.Error(ctx, "error walking attribute path", map[string]interface{}{"path": path})
+			logging.FrameworkError(ctx, "error walking attribute path", map[string]interface{}{logging.KeyAttributePath: path})
 			return val, err
 		} else if err != tftypes.ErrInvalidStep && !configVal.(tftypes.Value).IsNull() {
-			tfsdklog.Trace(ctx, "attribute not null in config, not marking unknown", map[string]interface{}{"path": path})
+			logging.FrameworkTrace(ctx, "attribute not null in config, not marking unknown", map[string]interface{}{logging.KeyAttributePath: path})
 			return val, nil
 		}
 		attribute, err := resourceSchema.AttributeAtPath(path)
 		if err != nil {
 			if errors.Is(err, ErrPathInsideAtomicAttribute) {
 				// ignore attributes/elements inside schema.Attributes, they have no schema of their own
-				tfsdklog.Trace(ctx, "attribute is a non-schema attribute, not marking unknown", map[string]interface{}{"path": path})
+				logging.FrameworkTrace(ctx, "attribute is a non-schema attribute, not marking unknown", map[string]interface{}{logging.KeyAttributePath: path})
 				return val, nil
 			}
-			tfsdklog.Error(ctx, "couldn't find attribute in resource schema", map[string]interface{}{"path": path})
+			logging.FrameworkError(ctx, "couldn't find attribute in resource schema", map[string]interface{}{logging.KeyAttributePath: path})
 			return tftypes.Value{}, fmt.Errorf("couldn't find attribute in resource schema: %w", err)
 		}
 		if !attribute.Computed {
-			tfsdklog.Trace(ctx, "attribute is not computed in schema, not marking unknown", map[string]interface{}{"path": path})
+			logging.FrameworkTrace(ctx, "attribute is not computed in schema, not marking unknown", map[string]interface{}{logging.KeyAttributePath: path})
 			return val, nil
 		}
-		tfsdklog.Debug(ctx, "marking computed attribute that is null in the config as unknown", map[string]interface{}{"path": path})
+		logging.FrameworkDebug(ctx, "marking computed attribute that is null in the config as unknown", map[string]interface{}{logging.KeyAttributePath: path})
 		return tftypes.NewValue(val.Type(), tftypes.UnknownValue), nil
 	}
 }
@@ -845,7 +847,7 @@ func (s *server) planResourceChange(ctx context.Context, req *tfprotov6.PlanReso
 	// We only do this if there's a plan to modify; otherwise, it
 	// represents a resource being deleted and there's no point.
 	if !plan.IsNull() && !plan.Equal(state) {
-		tfsdklog.Trace(ctx, "marking computed null values as unknown")
+		logging.FrameworkTrace(ctx, "marking computed null values as unknown")
 		modifiedPlan, err := tftypes.Transform(plan, markComputedNilsAsUnknown(ctx, config, resourceSchema))
 		if err != nil {
 			resp.Diagnostics.AddError(
@@ -855,7 +857,7 @@ func (s *server) planResourceChange(ctx context.Context, req *tfprotov6.PlanReso
 			return
 		}
 		if !plan.Equal(modifiedPlan) {
-			tfsdklog.Trace(ctx, "at least one value was changed to unknown")
+			logging.FrameworkTrace(ctx, "at least one value was changed to unknown")
 		}
 		plan = modifiedPlan
 	}
@@ -1033,7 +1035,7 @@ func normaliseRequiresReplace(ctx context.Context, rs []*tftypes.AttributePath)
 	j := 1
 	for i := 1; i < len(rs); i++ {
 		if rs[i].Equal(ret[j-1]) {
-			tfsdklog.Debug(ctx, "attribute found multiple times in RequiresReplace, removing duplicate", map[string]interface{}{"path": rs[i]})
+			logging.FrameworkDebug(ctx, "attribute found multiple times in RequiresReplace, removing duplicate", map[string]interface{}{logging.KeyAttributePath: rs[i]})
 			continue
 		}
 		ret[j] = rs[i]
@@ -1135,7 +1137,7 @@ func (s *server) applyResourceChange(ctx context.Context, req *tfprotov6.ApplyRe
 
 	switch {
 	case create && !update && !destroy:
-		tfsdklog.Trace(ctx, "running create")
+		logging.FrameworkTrace(ctx, "running create")
 		createReq := CreateResourceRequest{
 			Config: Config{
 				Schema: resourceSchema,
@@ -1188,7 +1190,7 @@ func (s *server) applyResourceChange(ctx context.Context, req *tfprotov6.ApplyRe
 		}
 		resp.NewState = &newState
 	case !create && update && !destroy:
-		tfsdklog.Trace(ctx, "running update")
+		logging.FrameworkTrace(ctx, "running update")
 		updateReq := UpdateResourceRequest{
 			Config: Config{
 				Schema: resourceSchema,
@@ -1245,7 +1247,7 @@ func (s *server) applyResourceChange(ctx context.Context, req *tfprotov6.ApplyRe
 		}
 		resp.NewState = &newState
 	case !create && !update && destroy:
-		tfsdklog.Trace(ctx, "running delete")
+		logging.FrameworkTrace(ctx, "running delete")
 		destroyReq := DeleteResourceRequest{
 			State: State{
 				Schema: resourceSchema,