tfprotov5/tf5server+tfprotov6/tf6server: Add downstream RPC request duration and response diagnostics logging (#203)

Reference: #183

Author: bflad

.changelog/203.txt

@@ -0,0 +1,7 @@
+```release-note:enhancement
+tfprotov5/tf5server: Added downstream RPC request duration and response diagnostics logging
+```
+
+```release-note:enhancement
+tfprotov6/tf6server: Added downstream RPC request duration and response diagnostics logging
+```

internal/logging/context.go

@@ -22,12 +22,19 @@ func InitContext(ctx context.Context, sdkOpts tfsdklog.Options, providerOpts tfl
 	ctx = tfsdklog.NewRootSDKLogger(ctx, append(tfsdklog.Options{
 		tfsdklog.WithLevelFromEnv(EnvTfLogSdk),
 	}, sdkOpts...)...)
+	ctx = ProtoSubsystemContext(ctx, sdkOpts)
+	ctx = tfsdklog.NewRootProviderLogger(ctx, providerOpts...)
+
+	return ctx
+}
+
+// ProtoSubsystemContext adds the proto subsystem to the SDK logger context.
+func ProtoSubsystemContext(ctx context.Context, sdkOpts tfsdklog.Options) context.Context {
 	ctx = tfsdklog.NewSubsystem(ctx, SubsystemProto, append(tfsdklog.Options{
 		// All calls are through the Protocol* helper functions
 		tfsdklog.WithAdditionalLocationOffset(1),
 		tfsdklog.WithLevelFromEnv(EnvTfLogSdkProto),
 	}, sdkOpts...)...)
-	ctx = tfsdklog.NewRootProviderLogger(ctx, providerOpts...)
 
 	return ctx
 }

internal/logging/keys.go

@@ -5,9 +5,30 @@ package logging
 // Practitioners or tooling reading logs may be depending on these keys, so be
 // conscious of that when changing them.
 const (
+	// Attribute of the diagnostic being logged.
+	KeyDiagnosticAttribute = "diagnostic_attribute"
+
+	// Number of the error diagnostics.
+	KeyDiagnosticErrorCount = "diagnostic_error_count"
+
+	// Severity of the diagnostic being logged.
+	KeyDiagnosticSeverity = "diagnostic_severity"
+
+	// Detail of the diagnostic being logged.
+	KeyDiagnosticDetail = "diagnostic_detail"
+
+	// Summary of the diagnostic being logged.
+	KeyDiagnosticSummary = "diagnostic_summary"
+
+	// Number of the warning diagnostics.
+	KeyDiagnosticWarningCount = "diagnostic_warning_count"
+
 	// Underlying error string
 	KeyError = "error"
 
+	// Duration in milliseconds for the RPC request
+	KeyRequestDurationMs = "tf_req_duration_ms"
+
 	// A unique ID for the RPC request
 	KeyRequestID = "tf_req_id"
 

internal/logging/protocol.go

@@ -16,6 +16,11 @@ func ProtocolError(ctx context.Context, msg string, additionalFields ...map[stri
 	tfsdklog.SubsystemError(ctx, SubsystemProto, msg, additionalFields...)
 }
 
+// ProtocolWarn emits a protocol subsystem log at WARN level.
+func ProtocolWarn(ctx context.Context, msg string, additionalFields ...map[string]interface{}) {
+	tfsdklog.SubsystemWarn(ctx, SubsystemProto, msg, additionalFields...)
+}
+
 // ProtocolTrace emits a protocol subsystem log at TRACE level.
 func ProtocolTrace(ctx context.Context, msg string, additionalFields ...map[string]interface{}) {
 	tfsdklog.SubsystemTrace(ctx, SubsystemProto, msg, additionalFields...)

tfprotov5/internal/diag/diagnostics.go

@@ -0,0 +1,82 @@
+package diag
+
+import (
+	"context"
+
+	"github.com/hashicorp/terraform-plugin-go/internal/logging"
+	"github.com/hashicorp/terraform-plugin-go/tfprotov5"
+)
+
+// Diagnostics is a collection of Diagnostic.
+type Diagnostics []*tfprotov5.Diagnostic
+
+// ErrorCount returns the number of error severity diagnostics.
+func (d Diagnostics) ErrorCount() int {
+	var result int
+
+	for _, diagnostic := range d {
+		if diagnostic == nil {
+			continue
+		}
+
+		if diagnostic.Severity != tfprotov5.DiagnosticSeverityError {
+			continue
+		}
+
+		result++
+	}
+
+	return result
+}
+
+// Log will log every diagnostic:
+//
+//    - Error severity at ERROR level
+//    - Warning severity at WARN level
+//    - Invalid/Unknown severity at WARN level
+//
+func (d Diagnostics) Log(ctx context.Context) {
+	for _, diagnostic := range d {
+		if diagnostic == nil {
+			continue
+		}
+
+		diagnosticFields := map[string]interface{}{
+			logging.KeyDiagnosticDetail:   diagnostic.Detail,
+			logging.KeyDiagnosticSeverity: diagnostic.Severity.String(),
+			logging.KeyDiagnosticSummary:  diagnostic.Summary,
+		}
+
+		if diagnostic.Attribute != nil {
+			diagnosticFields[logging.KeyDiagnosticAttribute] = diagnostic.Attribute.String()
+		}
+
+		switch diagnostic.Severity {
+		case tfprotov5.DiagnosticSeverityError:
+			logging.ProtocolError(ctx, "Response contains error diagnostic", diagnosticFields)
+		case tfprotov5.DiagnosticSeverityWarning:
+			logging.ProtocolWarn(ctx, "Response contains warning diagnostic", diagnosticFields)
+		default:
+			logging.ProtocolWarn(ctx, "Response contains unknown diagnostic", diagnosticFields)
+		}
+	}
+}
+
+// WarningCount returns the number of warning severity diagnostics.
+func (d Diagnostics) WarningCount() int {
+	var result int
+
+	for _, diagnostic := range d {
+		if diagnostic == nil {
+			continue
+		}
+
+		if diagnostic.Severity != tfprotov5.DiagnosticSeverityWarning {
+			continue
+		}
+
+		result++
+	}
+
+	return result
+}