tfsdk: Added logging for all framework handoffs to provider defined l…

…ogic (#300)

This will help practitioners and provider developers further understand when and where logic handoffs occur. In general, the framework and underlying terraform-plugin-go use the `DEBUG` log level for project code boundaries and major logic milestones while the `TRACE` log level is used for more lower level logic details.

.changelog/300.txt

@@ -0,0 +1,3 @@
+```release-note:enhancement
+tfsdk: Added `DEBUG` level logging for all framework handoffs to provider defined logic
+```

internal/logging/framework.go

@@ -30,3 +30,11 @@ func FrameworkTrace(ctx context.Context, msg string, additionalFields ...map[str
 func FrameworkWarn(ctx context.Context, msg string, additionalFields ...map[string]interface{}) {
 	tfsdklog.SubsystemWarn(ctx, SubsystemFramework, msg, additionalFields...)
 }
+
+// FrameworkWithAttributePath returns a new Context with KeyAttributePath set.
+// The attribute path is expected to be string, so the logging package does not
+// need to import path handling code.
+func FrameworkWithAttributePath(ctx context.Context, attributePath string) context.Context {
+	ctx = tfsdklog.SubsystemWith(ctx, SubsystemFramework, KeyAttributePath, attributePath)
+	return ctx
+}

internal/logging/keys.go

@@ -15,6 +15,10 @@ const (
 	// The type of data source being operated on, such as "archive_file"
 	KeyDataSourceType = "tf_data_source_type"
 
+	// Human readable string when calling a provider defined type that must
+	// implement the Description() method, such as validators.
+	KeyDescription = "description"
+
 	// Underlying Go error string when logging an error.
 	KeyError = "error"
 

tfsdk/attribute.go

@@ -7,6 +7,7 @@ import (
 	"sort"
 
 	"github.com/hashicorp/terraform-plugin-framework/attr"
+	"github.com/hashicorp/terraform-plugin-framework/internal/logging"
 	"github.com/hashicorp/terraform-plugin-framework/types"
 	"github.com/hashicorp/terraform-plugin-go/tfprotov6"
 	"github.com/hashicorp/terraform-plugin-go/tftypes"
@@ -269,6 +270,8 @@ func (a Attribute) tfprotov6SchemaAttribute(ctx context.Context, name string, pa
 
 // validate performs all Attribute validation.
 func (a Attribute) validate(ctx context.Context, req ValidateAttributeRequest, resp *ValidateAttributeResponse) {
+	ctx = logging.FrameworkWithAttributePath(ctx, req.AttributePath.String())
+
 	if !a.definesAttributes() && a.Type == nil {
 		resp.Diagnostics.AddAttributeError(
 			req.AttributePath,
@@ -309,7 +312,21 @@ func (a Attribute) validate(ctx context.Context, req ValidateAttributeRequest, r
 	req.AttributeConfig = attributeConfig
 
 	for _, validator := range a.Validators {
+		logging.FrameworkDebug(
+			ctx,
+			"Calling provider defined AttributeValidator",
+			map[string]interface{}{
+				logging.KeyDescription: validator.Description(ctx),
+			},
+		)
 		validator.Validate(ctx, req, resp)
+		logging.FrameworkDebug(
+			ctx,
+			"Called provider defined AttributeValidator",
+			map[string]interface{}{
+				logging.KeyDescription: validator.Description(ctx),
+			},
+		)
 	}
 
 	a.validateAttributes(ctx, req, resp)
@@ -486,6 +503,8 @@ func (a Attribute) validateAttributes(ctx context.Context, req ValidateAttribute
 
 // modifyPlan runs all AttributePlanModifiers
 func (a Attribute) modifyPlan(ctx context.Context, req ModifyAttributePlanRequest, resp *ModifySchemaPlanResponse) {
+	ctx = logging.FrameworkWithAttributePath(ctx, req.AttributePath.String())
+
 	attrConfig, diags := req.Config.getAttributeValue(ctx, req.AttributePath)
 	resp.Diagnostics.Append(diags...)
 
@@ -520,7 +539,21 @@ func (a Attribute) modifyPlan(ctx context.Context, req ModifyAttributePlanReques
 			RequiresReplace: requiresReplace,
 		}
 
+		logging.FrameworkDebug(
+			ctx,
+			"Calling provider defined AttributePlanModifier",
+			map[string]interface{}{
+				logging.KeyDescription: planModifier.Description(ctx),
+			},
+		)
 		planModifier.Modify(ctx, req, modifyResp)
+		logging.FrameworkDebug(
+			ctx,
+			"Called provider defined AttributePlanModifier",
+			map[string]interface{}{
+				logging.KeyDescription: planModifier.Description(ctx),
+			},
+		)
 
 		req.AttributePlan = modifyResp.AttributePlan
 		resp.Diagnostics.Append(modifyResp.Diagnostics...)

tfsdk/attribute_plan_modification.go

@@ -309,7 +309,7 @@ func (r RequiresReplaceIfModifier) Modify(ctx context.Context, req ModifyAttribu
 	if res {
 		resp.RequiresReplace = true
 	} else if resp.RequiresReplace {
-		logging.FrameworkDebug(ctx, "Keeping previous attribute replacement requirement", map[string]interface{}{logging.KeyAttributePath: req.AttributePath.String()})
+		logging.FrameworkDebug(ctx, "Keeping previous attribute replacement requirement")
 	}
 }
 

tfsdk/config.go

@@ -7,6 +7,7 @@ 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-framework/internal/reflect"
 	"github.com/hashicorp/terraform-plugin-go/tftypes"
 )
@@ -25,6 +26,8 @@ func (c Config) Get(ctx context.Context, target interface{}) diag.Diagnostics {
 // GetAttribute retrieves the attribute found at `path` and populates the
 // `target` with the value.
 func (c Config) GetAttribute(ctx context.Context, path *tftypes.AttributePath, target interface{}) diag.Diagnostics {
+	ctx = logging.FrameworkWithAttributePath(ctx, path.String())
+
 	attrValue, diags := c.getAttributeValue(ctx, path)
 
 	if diags.HasError() {
@@ -92,7 +95,10 @@ func (c Config) getAttributeValue(ctx context.Context, path *tftypes.AttributePa
 	// Reference: https://github.com/hashicorp/terraform-plugin-framework/issues/186
 
 	if attrTypeWithValidate, ok := attrType.(attr.TypeWithValidate); ok {
+		logging.FrameworkTrace(ctx, "Type implements TypeWithValidate")
+		logging.FrameworkDebug(ctx, "Calling provider defined Type Validate")
 		diags.Append(attrTypeWithValidate.Validate(ctx, tfValue, path)...)
+		logging.FrameworkDebug(ctx, "Called provider defined Type Validate")
 
 		if diags.HasError() {
 			return nil, diags

tfsdk/plan.go

@@ -7,6 +7,7 @@ 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-framework/internal/reflect"
 	"github.com/hashicorp/terraform-plugin-go/tftypes"
 )
@@ -25,6 +26,8 @@ func (p Plan) Get(ctx context.Context, target interface{}) diag.Diagnostics {
 // GetAttribute retrieves the attribute found at `path` and populates the
 // `target` with the value.
 func (p Plan) GetAttribute(ctx context.Context, path *tftypes.AttributePath, target interface{}) diag.Diagnostics {
+	ctx = logging.FrameworkWithAttributePath(ctx, path.String())
+
 	attrValue, diags := p.getAttributeValue(ctx, path)
 
 	if diags.HasError() {
@@ -92,7 +95,10 @@ func (p Plan) getAttributeValue(ctx context.Context, path *tftypes.AttributePath
 	// Reference: https://github.com/hashicorp/terraform-plugin-framework/issues/186
 
 	if attrTypeWithValidate, ok := attrType.(attr.TypeWithValidate); ok {
+		logging.FrameworkTrace(ctx, "Type implements TypeWithValidate")
+		logging.FrameworkDebug(ctx, "Calling provider defined Type Validate")
 		diags.Append(attrTypeWithValidate.Validate(ctx, tfValue, path)...)
+		logging.FrameworkDebug(ctx, "Called provider defined Type Validate")
 
 		if diags.HasError() {
 			return nil, diags
@@ -147,6 +153,8 @@ func (p *Plan) Set(ctx context.Context, val interface{}) diag.Diagnostics {
 func (p *Plan) SetAttribute(ctx context.Context, path *tftypes.AttributePath, val interface{}) diag.Diagnostics {
 	var diags diag.Diagnostics
 
+	ctx = logging.FrameworkWithAttributePath(ctx, path.String())
+
 	attrType, err := p.Schema.AttributeTypeAtPath(path)
 	if err != nil {
 		err = fmt.Errorf("error getting attribute type in schema: %w", err)
@@ -177,7 +185,10 @@ func (p *Plan) SetAttribute(ctx context.Context, path *tftypes.AttributePath, va
 	}
 
 	if attrTypeWithValidate, ok := attrType.(attr.TypeWithValidate); ok {
+		logging.FrameworkTrace(ctx, "Type implements TypeWithValidate")
+		logging.FrameworkDebug(ctx, "Calling provider defined Type Validate")
 		diags.Append(attrTypeWithValidate.Validate(ctx, tfVal, path)...)
+		logging.FrameworkDebug(ctx, "Called provider defined Type Validate")
 
 		if diags.HasError() {
 			return diags
@@ -306,7 +317,10 @@ func (p Plan) setAttributeTransformFunc(ctx context.Context, path *tftypes.Attri
 	}
 
 	if attrTypeWithValidate, ok := parentAttrType.(attr.TypeWithValidate); ok {
+		logging.FrameworkTrace(ctx, "Type implements TypeWithValidate")
+		logging.FrameworkDebug(ctx, "Calling provider defined Type Validate")
 		diags.Append(attrTypeWithValidate.Validate(ctx, parentValue, parentPath)...)
+		logging.FrameworkDebug(ctx, "Called provider defined Type Validate")
 
 		if diags.HasError() {
 			return nil, diags