From e4b1fd9fe82489cd34600612ce955832957077df Mon Sep 17 00:00:00 2001 From: Brian Flad Date: Tue, 5 Jul 2022 14:10:25 -0400 Subject: [PATCH] tfprotov5/tf5server+tfprotov6/tf6server: Add downstream RPC request duration and response diagnostics logging (#203) Reference: https://github.com/hashicorp/terraform-plugin-go/issues/183 --- .changelog/203.txt | 7 + internal/logging/context.go | 9 +- internal/logging/keys.go | 21 + internal/logging/protocol.go | 5 + tfprotov5/internal/diag/diagnostics.go | 82 +++ tfprotov5/internal/diag/diagnostics_test.go | 600 ++++++++++++++++++ tfprotov5/internal/diag/doc.go | 3 + .../internal/tf5serverlogging/context_keys.go | 8 + tfprotov5/internal/tf5serverlogging/doc.go | 3 + .../tf5serverlogging/downstream_request.go | 40 ++ .../downstream_request_test.go | 202 ++++++ tfprotov5/tf5server/server.go | 49 +- tfprotov6/internal/diag/diagnostics.go | 82 +++ tfprotov6/internal/diag/diagnostics_test.go | 600 ++++++++++++++++++ tfprotov6/internal/diag/doc.go | 3 + .../internal/tf6serverlogging/context_keys.go | 8 + tfprotov6/internal/tf6serverlogging/doc.go | 3 + .../tf6serverlogging/downstream_request.go | 40 ++ .../downstream_request_test.go | 202 ++++++ tfprotov6/tf6server/server.go | 49 +- 20 files changed, 1967 insertions(+), 49 deletions(-) create mode 100644 .changelog/203.txt create mode 100644 tfprotov5/internal/diag/diagnostics.go create mode 100644 tfprotov5/internal/diag/diagnostics_test.go create mode 100644 tfprotov5/internal/diag/doc.go create mode 100644 tfprotov5/internal/tf5serverlogging/context_keys.go create mode 100644 tfprotov5/internal/tf5serverlogging/doc.go create mode 100644 tfprotov5/internal/tf5serverlogging/downstream_request.go create mode 100644 tfprotov5/internal/tf5serverlogging/downstream_request_test.go create mode 100644 tfprotov6/internal/diag/diagnostics.go create mode 100644 tfprotov6/internal/diag/diagnostics_test.go create mode 100644 tfprotov6/internal/diag/doc.go create mode 100644 tfprotov6/internal/tf6serverlogging/context_keys.go create mode 100644 tfprotov6/internal/tf6serverlogging/doc.go create mode 100644 tfprotov6/internal/tf6serverlogging/downstream_request.go create mode 100644 tfprotov6/internal/tf6serverlogging/downstream_request_test.go diff --git a/.changelog/203.txt b/.changelog/203.txt new file mode 100644 index 00000000..f6cccc45 --- /dev/null +++ b/.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 +``` diff --git a/internal/logging/context.go b/internal/logging/context.go index a35258a8..38ef4e35 100644 --- a/internal/logging/context.go +++ b/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 } diff --git a/internal/logging/keys.go b/internal/logging/keys.go index 3d7af961..ce803d75 100644 --- a/internal/logging/keys.go +++ b/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" diff --git a/internal/logging/protocol.go b/internal/logging/protocol.go index 9f9c2808..21a392a3 100644 --- a/internal/logging/protocol.go +++ b/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...) diff --git a/tfprotov5/internal/diag/diagnostics.go b/tfprotov5/internal/diag/diagnostics.go new file mode 100644 index 00000000..1032f7d4 --- /dev/null +++ b/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 +} diff --git a/tfprotov5/internal/diag/diagnostics_test.go b/tfprotov5/internal/diag/diagnostics_test.go new file mode 100644 index 00000000..fc00230d --- /dev/null +++ b/tfprotov5/internal/diag/diagnostics_test.go @@ -0,0 +1,600 @@ +package diag_test + +import ( + "bytes" + "context" + "testing" + + "github.com/google/go-cmp/cmp" + "github.com/hashicorp/terraform-plugin-go/internal/logging" + "github.com/hashicorp/terraform-plugin-go/tfprotov5" + "github.com/hashicorp/terraform-plugin-go/tfprotov5/internal/diag" + "github.com/hashicorp/terraform-plugin-go/tftypes" + "github.com/hashicorp/terraform-plugin-log/tfsdklog" + "github.com/hashicorp/terraform-plugin-log/tfsdklogtest" +) + +func TestDiagnosticsErrorCount(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + diagnostics diag.Diagnostics + expected int + }{ + "nil": { + diagnostics: nil, + expected: 0, + }, + "empty": { + diagnostics: diag.Diagnostics{}, + expected: 0, + }, + "error": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + }, + expected: 1, + }, + "errors": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + }, + expected: 2, + }, + "invalid": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + }, + expected: 0, + }, + "invalids": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + }, + expected: 0, + }, + "warning": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + }, + expected: 0, + }, + "warnings": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 2", + }, + }, + expected: 0, + }, + "mixed": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 2", + Detail: "test warning detail 2", + }, + }, + expected: 2, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + got := testCase.diagnostics.ErrorCount() + + if diff := cmp.Diff(got, testCase.expected); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } + }) + } +} + +func TestDiagnosticsLog(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + diagnostics diag.Diagnostics + expected []map[string]interface{} + }{ + "nil": { + diagnostics: nil, + expected: nil, + }, + "empty": { + diagnostics: diag.Diagnostics{}, + expected: nil, + }, + "attribute": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + Attribute: tftypes.NewAttributePath().WithAttributeName("test"), + }, + }, + expected: []map[string]interface{}{ + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_attribute": "AttributeName(\"test\")", + "diagnostic_detail": "test error detail 1", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 1", + }, + }, + }, + "error": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 1", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 1", + }, + }, + }, + "errors": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 1", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 1", + }, + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 2", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 2", + }, + }, + }, + "invalid": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 1", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 1", + }, + }, + }, + "invalids": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 1", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 1", + }, + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 2", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 2", + }, + }, + }, + "warning": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 1", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 1", + }, + }, + }, + "warnings": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 2", + Detail: "test warning detail 2", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 1", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 1", + }, + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 2", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 2", + }, + }, + }, + "mixed": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 2", + Detail: "test warning detail 2", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 1", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 1", + }, + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 1", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 1", + }, + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 1", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 1", + }, + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 2", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 2", + }, + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 2", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 2", + }, + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 2", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 2", + }, + }, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + var output bytes.Buffer + + ctx := tfsdklogtest.RootLogger(context.Background(), &output) + ctx = logging.ProtoSubsystemContext(ctx, tfsdklog.Options{}) + + testCase.diagnostics.Log(ctx) + + entries, err := tfsdklogtest.MultilineJSONDecode(&output) + + if err != nil { + t.Fatalf("unable to read multiple line JSON: %s", err) + } + + if diff := cmp.Diff(entries, testCase.expected); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } + }) + } +} + +func TestDiagnosticsWarningCount(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + diagnostics diag.Diagnostics + expected int + }{ + "nil": { + diagnostics: nil, + expected: 0, + }, + "empty": { + diagnostics: diag.Diagnostics{}, + expected: 0, + }, + "error": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + }, + expected: 0, + }, + "errors": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + }, + expected: 0, + }, + "invalid": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + }, + expected: 0, + }, + "invalids": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + }, + expected: 0, + }, + "warning": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + }, + expected: 1, + }, + "warnings": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 2", + }, + }, + expected: 2, + }, + "mixed": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 2", + Detail: "test warning detail 2", + }, + }, + expected: 2, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + got := testCase.diagnostics.WarningCount() + + if diff := cmp.Diff(got, testCase.expected); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } + }) + } +} diff --git a/tfprotov5/internal/diag/doc.go b/tfprotov5/internal/diag/doc.go new file mode 100644 index 00000000..0c73dab1 --- /dev/null +++ b/tfprotov5/internal/diag/doc.go @@ -0,0 +1,3 @@ +// Package diag contains diagnostics helpers. These implementations are +// intentionally outside the public API. +package diag diff --git a/tfprotov5/internal/tf5serverlogging/context_keys.go b/tfprotov5/internal/tf5serverlogging/context_keys.go new file mode 100644 index 00000000..cc72fe4b --- /dev/null +++ b/tfprotov5/internal/tf5serverlogging/context_keys.go @@ -0,0 +1,8 @@ +package tf5serverlogging + +// Context key types. +// Reference: https://staticcheck.io/docs/checks/#SA1029 + +// ContextKeyDownstreamRequestStartTime is a context.Context key to store the +// time.Time when the server began a downstream request. +type ContextKeyDownstreamRequestStartTime struct{} diff --git a/tfprotov5/internal/tf5serverlogging/doc.go b/tfprotov5/internal/tf5serverlogging/doc.go new file mode 100644 index 00000000..e77a831c --- /dev/null +++ b/tfprotov5/internal/tf5serverlogging/doc.go @@ -0,0 +1,3 @@ +// Package tf5serverlogging contains logging functionality specific to +// tf5server and tfprotov5 types. +package tf5serverlogging diff --git a/tfprotov5/internal/tf5serverlogging/downstream_request.go b/tfprotov5/internal/tf5serverlogging/downstream_request.go new file mode 100644 index 00000000..eeec76e8 --- /dev/null +++ b/tfprotov5/internal/tf5serverlogging/downstream_request.go @@ -0,0 +1,40 @@ +package tf5serverlogging + +import ( + "context" + "time" + + "github.com/hashicorp/terraform-plugin-go/internal/logging" + "github.com/hashicorp/terraform-plugin-go/tfprotov5/internal/diag" +) + +// DownstreamRequest sets a request duration start time context key and +// generates a TRACE "Sending request downstream" log. +func DownstreamRequest(ctx context.Context) context.Context { + requestStart := time.Now() + ctx = context.WithValue(ctx, ContextKeyDownstreamRequestStartTime{}, requestStart) + + logging.ProtocolTrace(ctx, "Sending request downstream") + + return ctx +} + +// DownstreamResponse generates the following logging: +// +// - TRACE "Received downstream response" log with request duration and +// diagnostic severity counts +// - Per-diagnostic logs +// +func DownstreamResponse(ctx context.Context, diagnostics diag.Diagnostics) { + responseFields := map[string]interface{}{ + logging.KeyDiagnosticErrorCount: diagnostics.ErrorCount(), + logging.KeyDiagnosticWarningCount: diagnostics.WarningCount(), + } + + if requestStart, ok := ctx.Value(ContextKeyDownstreamRequestStartTime{}).(time.Time); ok { + responseFields[logging.KeyRequestDurationMs] = time.Since(requestStart).Milliseconds() + } + + logging.ProtocolTrace(ctx, "Received downstream response", responseFields) + diagnostics.Log(ctx) +} diff --git a/tfprotov5/internal/tf5serverlogging/downstream_request_test.go b/tfprotov5/internal/tf5serverlogging/downstream_request_test.go new file mode 100644 index 00000000..6b2cfd58 --- /dev/null +++ b/tfprotov5/internal/tf5serverlogging/downstream_request_test.go @@ -0,0 +1,202 @@ +package tf5serverlogging_test + +import ( + "bytes" + "context" + "testing" + "time" + + "github.com/google/go-cmp/cmp" + "github.com/hashicorp/terraform-plugin-go/internal/logging" + "github.com/hashicorp/terraform-plugin-go/tfprotov5" + "github.com/hashicorp/terraform-plugin-go/tfprotov5/internal/diag" + "github.com/hashicorp/terraform-plugin-go/tfprotov5/internal/tf5serverlogging" + "github.com/hashicorp/terraform-plugin-log/tfsdklog" + "github.com/hashicorp/terraform-plugin-log/tfsdklogtest" +) + +func TestDownstreamRequest(t *testing.T) { + t.Parallel() + + var output bytes.Buffer + + ctx := tfsdklogtest.RootLogger(context.Background(), &output) + ctx = logging.ProtoSubsystemContext(ctx, tfsdklog.Options{}) + + got := tf5serverlogging.DownstreamRequest(ctx) + + if _, ok := got.Value(tf5serverlogging.ContextKeyDownstreamRequestStartTime{}).(time.Time); !ok { + t.Error("missing downstream request start time context key") + } + + entries, err := tfsdklogtest.MultilineJSONDecode(&output) + + if err != nil { + t.Fatalf("unable to read multiple line JSON: %s", err) + } + + expectedEntries := []map[string]interface{}{ + { + "@level": "trace", + "@message": "Sending request downstream", + "@module": "sdk.proto", + }, + } + + if diff := cmp.Diff(entries, expectedEntries); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } +} + +func TestDownstreamResponse(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + diagnostics diag.Diagnostics + expected []map[string]interface{} + }{ + "diagnostics-nil": { + diagnostics: nil, + expected: []map[string]interface{}{ + { + "@level": "trace", + "@message": "Received downstream response", + "@module": "sdk.proto", + // go-hclog treats int as float64 + "diagnostic_error_count": float64(0), + "diagnostic_warning_count": float64(0), + }, + }, + }, + "diagnostics-empty": { + diagnostics: diag.Diagnostics{}, + expected: []map[string]interface{}{ + { + "@level": "trace", + "@message": "Received downstream response", + "@module": "sdk.proto", + // go-hclog treats int as float64 + "diagnostic_error_count": float64(0), + "diagnostic_warning_count": float64(0), + }, + }, + }, + "diagnostics": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov5.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + { + Severity: tfprotov5.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + { + Severity: tfprotov5.DiagnosticSeverityWarning, + Summary: "test warning summary 2", + Detail: "test warning detail 2", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "trace", + "@message": "Received downstream response", + "@module": "sdk.proto", + // go-hclog treats int as float64 + "diagnostic_error_count": float64(2), + "diagnostic_warning_count": float64(2), + }, + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 1", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 1", + }, + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 1", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 1", + }, + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 1", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 1", + }, + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 2", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 2", + }, + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 2", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 2", + }, + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 2", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 2", + }, + }, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + var output bytes.Buffer + + ctx := tfsdklogtest.RootLogger(context.Background(), &output) + ctx = logging.ProtoSubsystemContext(ctx, tfsdklog.Options{}) + + tf5serverlogging.DownstreamResponse(ctx, testCase.diagnostics) + + entries, err := tfsdklogtest.MultilineJSONDecode(&output) + + if err != nil { + t.Fatalf("unable to read multiple line JSON: %s", err) + } + + if diff := cmp.Diff(entries, testCase.expected); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } + }) + } +} diff --git a/tfprotov5/tf5server/server.go b/tfprotov5/tf5server/server.go index 9ec7abef..3b48ae6c 100644 --- a/tfprotov5/tf5server/server.go +++ b/tfprotov5/tf5server/server.go @@ -16,6 +16,7 @@ import ( "github.com/hashicorp/terraform-plugin-go/internal/logging" "github.com/hashicorp/terraform-plugin-go/tfprotov5" "github.com/hashicorp/terraform-plugin-go/tfprotov5/internal/fromproto" + "github.com/hashicorp/terraform-plugin-go/tfprotov5/internal/tf5serverlogging" "github.com/hashicorp/terraform-plugin-go/tfprotov5/internal/tfplugin5" "github.com/hashicorp/terraform-plugin-go/tfprotov5/internal/toproto" "google.golang.org/grpc" @@ -494,13 +495,13 @@ func (s *server) GetSchema(ctx context.Context, req *tfplugin5.GetProviderSchema logging.ProtocolError(ctx, "Error converting request from protobuf", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf5serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.GetProviderSchema(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf5serverlogging.DownstreamResponse(ctx, resp.Diagnostics) ret, err := toproto.GetProviderSchema_Response(resp) if err != nil { logging.ProtocolError(ctx, "Error converting response to protobuf", map[string]interface{}{logging.KeyError: err}) @@ -522,13 +523,13 @@ func (s *server) PrepareProviderConfig(ctx context.Context, req *tfplugin5.Prepa return nil, err } logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf5serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.PrepareProviderConfig(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf5serverlogging.DownstreamResponse(ctx, resp.Diagnostics) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response", "PreparedConfig", resp.PreparedConfig) ret, err := toproto.PrepareProviderConfig_Response(resp) if err != nil { @@ -551,13 +552,13 @@ func (s *server) Configure(ctx context.Context, req *tfplugin5.Configure_Request return nil, err } logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf5serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ConfigureProvider(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf5serverlogging.DownstreamResponse(ctx, resp.Diagnostics) ret, err := toproto.Configure_Response(resp) if err != nil { logging.ProtocolError(ctx, "Error converting response to protobuf", map[string]interface{}{logging.KeyError: err}) @@ -591,13 +592,13 @@ func (s *server) Stop(ctx context.Context, req *tfplugin5.Stop_Request) (*tfplug logging.ProtocolError(ctx, "Error converting request from protobuf", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf5serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.StopProvider(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf5serverlogging.DownstreamResponse(ctx, nil) logging.ProtocolTrace(ctx, "Closing all our contexts") s.stop() logging.ProtocolTrace(ctx, "Closed all our contexts") @@ -623,13 +624,13 @@ func (s *server) ValidateDataSourceConfig(ctx context.Context, req *tfplugin5.Va return nil, err } logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf5serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ValidateDataSourceConfig(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf5serverlogging.DownstreamResponse(ctx, resp.Diagnostics) ret, err := toproto.ValidateDataSourceConfig_Response(resp) if err != nil { logging.ProtocolError(ctx, "Error converting response to protobuf", map[string]interface{}{logging.KeyError: err}) @@ -653,13 +654,13 @@ func (s *server) ReadDataSource(ctx context.Context, req *tfplugin5.ReadDataSour } logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "ProviderMeta", r.ProviderMeta) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf5serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ReadDataSource(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf5serverlogging.DownstreamResponse(ctx, resp.Diagnostics) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response", "State", resp.State) ret, err := toproto.ReadDataSource_Response(resp) if err != nil { @@ -683,13 +684,13 @@ func (s *server) ValidateResourceTypeConfig(ctx context.Context, req *tfplugin5. return nil, err } logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf5serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ValidateResourceTypeConfig(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf5serverlogging.DownstreamResponse(ctx, resp.Diagnostics) ret, err := toproto.ValidateResourceTypeConfig_Response(resp) if err != nil { logging.ProtocolError(ctx, "Error converting response to protobuf", map[string]interface{}{logging.KeyError: err}) @@ -711,13 +712,13 @@ func (s *server) UpgradeResourceState(ctx context.Context, req *tfplugin5.Upgrad logging.ProtocolError(ctx, "Error converting request from protobuf", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf5serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.UpgradeResourceState(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf5serverlogging.DownstreamResponse(ctx, resp.Diagnostics) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response", "UpgradedState", resp.UpgradedState) ret, err := toproto.UpgradeResourceState_Response(resp) if err != nil { @@ -742,13 +743,13 @@ func (s *server) ReadResource(ctx context.Context, req *tfplugin5.ReadResource_R } logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "CurrentState", r.CurrentState) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "ProviderMeta", r.ProviderMeta) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf5serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ReadResource(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf5serverlogging.DownstreamResponse(ctx, resp.Diagnostics) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response", "NewState", resp.NewState) ret, err := toproto.ReadResource_Response(resp) if err != nil { @@ -775,13 +776,13 @@ func (s *server) PlanResourceChange(ctx context.Context, req *tfplugin5.PlanReso logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "PriorState", r.PriorState) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "ProposedNewState", r.ProposedNewState) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "ProviderMeta", r.ProviderMeta) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf5serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.PlanResourceChange(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf5serverlogging.DownstreamResponse(ctx, resp.Diagnostics) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response", "PlannedState", resp.PlannedState) ret, err := toproto.PlanResourceChange_Response(resp) if err != nil { @@ -808,13 +809,13 @@ func (s *server) ApplyResourceChange(ctx context.Context, req *tfplugin5.ApplyRe logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "PlannedState", r.PlannedState) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf5serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ApplyResourceChange(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf5serverlogging.DownstreamResponse(ctx, resp.Diagnostics) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response", "NewState", resp.NewState) ret, err := toproto.ApplyResourceChange_Response(resp) if err != nil { @@ -837,13 +838,13 @@ func (s *server) ImportResourceState(ctx context.Context, req *tfplugin5.ImportR logging.ProtocolError(ctx, "Error converting request from protobuf", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf5serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ImportResourceState(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf5serverlogging.DownstreamResponse(ctx, resp.Diagnostics) for _, importedResource := range resp.ImportedResources { logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response_ImportedResource", "State", importedResource.State) } diff --git a/tfprotov6/internal/diag/diagnostics.go b/tfprotov6/internal/diag/diagnostics.go new file mode 100644 index 00000000..543a3623 --- /dev/null +++ b/tfprotov6/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/tfprotov6" +) + +// Diagnostics is a collection of Diagnostic. +type Diagnostics []*tfprotov6.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 != tfprotov6.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 tfprotov6.DiagnosticSeverityError: + logging.ProtocolError(ctx, "Response contains error diagnostic", diagnosticFields) + case tfprotov6.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 != tfprotov6.DiagnosticSeverityWarning { + continue + } + + result++ + } + + return result +} diff --git a/tfprotov6/internal/diag/diagnostics_test.go b/tfprotov6/internal/diag/diagnostics_test.go new file mode 100644 index 00000000..406434be --- /dev/null +++ b/tfprotov6/internal/diag/diagnostics_test.go @@ -0,0 +1,600 @@ +package diag_test + +import ( + "bytes" + "context" + "testing" + + "github.com/google/go-cmp/cmp" + "github.com/hashicorp/terraform-plugin-go/internal/logging" + "github.com/hashicorp/terraform-plugin-go/tfprotov6" + "github.com/hashicorp/terraform-plugin-go/tfprotov6/internal/diag" + "github.com/hashicorp/terraform-plugin-go/tftypes" + "github.com/hashicorp/terraform-plugin-log/tfsdklog" + "github.com/hashicorp/terraform-plugin-log/tfsdklogtest" +) + +func TestDiagnosticsErrorCount(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + diagnostics diag.Diagnostics + expected int + }{ + "nil": { + diagnostics: nil, + expected: 0, + }, + "empty": { + diagnostics: diag.Diagnostics{}, + expected: 0, + }, + "error": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + }, + expected: 1, + }, + "errors": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + }, + expected: 2, + }, + "invalid": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + }, + expected: 0, + }, + "invalids": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + }, + expected: 0, + }, + "warning": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + }, + expected: 0, + }, + "warnings": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 2", + }, + }, + expected: 0, + }, + "mixed": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 2", + Detail: "test warning detail 2", + }, + }, + expected: 2, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + got := testCase.diagnostics.ErrorCount() + + if diff := cmp.Diff(got, testCase.expected); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } + }) + } +} + +func TestDiagnosticsLog(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + diagnostics diag.Diagnostics + expected []map[string]interface{} + }{ + "nil": { + diagnostics: nil, + expected: nil, + }, + "empty": { + diagnostics: diag.Diagnostics{}, + expected: nil, + }, + "attribute": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + Attribute: tftypes.NewAttributePath().WithAttributeName("test"), + }, + }, + expected: []map[string]interface{}{ + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_attribute": "AttributeName(\"test\")", + "diagnostic_detail": "test error detail 1", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 1", + }, + }, + }, + "error": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 1", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 1", + }, + }, + }, + "errors": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 1", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 1", + }, + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 2", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 2", + }, + }, + }, + "invalid": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 1", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 1", + }, + }, + }, + "invalids": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 1", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 1", + }, + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 2", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 2", + }, + }, + }, + "warning": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 1", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 1", + }, + }, + }, + "warnings": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 2", + Detail: "test warning detail 2", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 1", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 1", + }, + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 2", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 2", + }, + }, + }, + "mixed": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 2", + Detail: "test warning detail 2", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 1", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 1", + }, + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 1", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 1", + }, + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 1", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 1", + }, + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 2", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 2", + }, + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 2", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 2", + }, + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 2", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 2", + }, + }, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + var output bytes.Buffer + + ctx := tfsdklogtest.RootLogger(context.Background(), &output) + ctx = logging.ProtoSubsystemContext(ctx, tfsdklog.Options{}) + + testCase.diagnostics.Log(ctx) + + entries, err := tfsdklogtest.MultilineJSONDecode(&output) + + if err != nil { + t.Fatalf("unable to read multiple line JSON: %s", err) + } + + if diff := cmp.Diff(entries, testCase.expected); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } + }) + } +} + +func TestDiagnosticsWarningCount(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + diagnostics diag.Diagnostics + expected int + }{ + "nil": { + diagnostics: nil, + expected: 0, + }, + "empty": { + diagnostics: diag.Diagnostics{}, + expected: 0, + }, + "error": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + }, + expected: 0, + }, + "errors": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + }, + expected: 0, + }, + "invalid": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + }, + expected: 0, + }, + "invalids": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + }, + expected: 0, + }, + "warning": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + }, + expected: 1, + }, + "warnings": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 2", + }, + }, + expected: 2, + }, + "mixed": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 2", + Detail: "test warning detail 2", + }, + }, + expected: 2, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + got := testCase.diagnostics.WarningCount() + + if diff := cmp.Diff(got, testCase.expected); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } + }) + } +} diff --git a/tfprotov6/internal/diag/doc.go b/tfprotov6/internal/diag/doc.go new file mode 100644 index 00000000..0c73dab1 --- /dev/null +++ b/tfprotov6/internal/diag/doc.go @@ -0,0 +1,3 @@ +// Package diag contains diagnostics helpers. These implementations are +// intentionally outside the public API. +package diag diff --git a/tfprotov6/internal/tf6serverlogging/context_keys.go b/tfprotov6/internal/tf6serverlogging/context_keys.go new file mode 100644 index 00000000..15386cd2 --- /dev/null +++ b/tfprotov6/internal/tf6serverlogging/context_keys.go @@ -0,0 +1,8 @@ +package tf6serverlogging + +// Context key types. +// Reference: https://staticcheck.io/docs/checks/#SA1029 + +// ContextKeyDownstreamRequestStartTime is a context.Context key to store the +// time.Time when the server began a downstream request. +type ContextKeyDownstreamRequestStartTime struct{} diff --git a/tfprotov6/internal/tf6serverlogging/doc.go b/tfprotov6/internal/tf6serverlogging/doc.go new file mode 100644 index 00000000..167a6182 --- /dev/null +++ b/tfprotov6/internal/tf6serverlogging/doc.go @@ -0,0 +1,3 @@ +// Package tf5serverlogging contains logging functionality specific to +// tf5server and tfprotov5 types. +package tf6serverlogging diff --git a/tfprotov6/internal/tf6serverlogging/downstream_request.go b/tfprotov6/internal/tf6serverlogging/downstream_request.go new file mode 100644 index 00000000..c47df9b4 --- /dev/null +++ b/tfprotov6/internal/tf6serverlogging/downstream_request.go @@ -0,0 +1,40 @@ +package tf6serverlogging + +import ( + "context" + "time" + + "github.com/hashicorp/terraform-plugin-go/internal/logging" + "github.com/hashicorp/terraform-plugin-go/tfprotov6/internal/diag" +) + +// DownstreamRequest sets a request duration start time context key and +// generates a TRACE "Sending request downstream" log. +func DownstreamRequest(ctx context.Context) context.Context { + requestStart := time.Now() + ctx = context.WithValue(ctx, ContextKeyDownstreamRequestStartTime{}, requestStart) + + logging.ProtocolTrace(ctx, "Sending request downstream") + + return ctx +} + +// DownstreamResponse generates the following logging: +// +// - TRACE "Received downstream response" log with request duration and +// diagnostic severity counts +// - Per-diagnostic logs +// +func DownstreamResponse(ctx context.Context, diagnostics diag.Diagnostics) { + responseFields := map[string]interface{}{ + logging.KeyDiagnosticErrorCount: diagnostics.ErrorCount(), + logging.KeyDiagnosticWarningCount: diagnostics.WarningCount(), + } + + if requestStart, ok := ctx.Value(ContextKeyDownstreamRequestStartTime{}).(time.Time); ok { + responseFields[logging.KeyRequestDurationMs] = time.Since(requestStart).Milliseconds() + } + + logging.ProtocolTrace(ctx, "Received downstream response", responseFields) + diagnostics.Log(ctx) +} diff --git a/tfprotov6/internal/tf6serverlogging/downstream_request_test.go b/tfprotov6/internal/tf6serverlogging/downstream_request_test.go new file mode 100644 index 00000000..fd992669 --- /dev/null +++ b/tfprotov6/internal/tf6serverlogging/downstream_request_test.go @@ -0,0 +1,202 @@ +package tf6serverlogging_test + +import ( + "bytes" + "context" + "testing" + "time" + + "github.com/google/go-cmp/cmp" + "github.com/hashicorp/terraform-plugin-go/internal/logging" + "github.com/hashicorp/terraform-plugin-go/tfprotov6" + "github.com/hashicorp/terraform-plugin-go/tfprotov6/internal/diag" + "github.com/hashicorp/terraform-plugin-go/tfprotov6/internal/tf6serverlogging" + "github.com/hashicorp/terraform-plugin-log/tfsdklog" + "github.com/hashicorp/terraform-plugin-log/tfsdklogtest" +) + +func TestDownstreamRequest(t *testing.T) { + t.Parallel() + + var output bytes.Buffer + + ctx := tfsdklogtest.RootLogger(context.Background(), &output) + ctx = logging.ProtoSubsystemContext(ctx, tfsdklog.Options{}) + + got := tf6serverlogging.DownstreamRequest(ctx) + + if _, ok := got.Value(tf6serverlogging.ContextKeyDownstreamRequestStartTime{}).(time.Time); !ok { + t.Error("missing downstream request start time context key") + } + + entries, err := tfsdklogtest.MultilineJSONDecode(&output) + + if err != nil { + t.Fatalf("unable to read multiple line JSON: %s", err) + } + + expectedEntries := []map[string]interface{}{ + { + "@level": "trace", + "@message": "Sending request downstream", + "@module": "sdk.proto", + }, + } + + if diff := cmp.Diff(entries, expectedEntries); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } +} + +func TestDownstreamResponse(t *testing.T) { + t.Parallel() + + testCases := map[string]struct { + diagnostics diag.Diagnostics + expected []map[string]interface{} + }{ + "diagnostics-nil": { + diagnostics: nil, + expected: []map[string]interface{}{ + { + "@level": "trace", + "@message": "Received downstream response", + "@module": "sdk.proto", + // go-hclog treats int as float64 + "diagnostic_error_count": float64(0), + "diagnostic_warning_count": float64(0), + }, + }, + }, + "diagnostics-empty": { + diagnostics: diag.Diagnostics{}, + expected: []map[string]interface{}{ + { + "@level": "trace", + "@message": "Received downstream response", + "@module": "sdk.proto", + // go-hclog treats int as float64 + "diagnostic_error_count": float64(0), + "diagnostic_warning_count": float64(0), + }, + }, + }, + "diagnostics": { + diagnostics: diag.Diagnostics{ + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 1", + Detail: "test error detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 1", + Detail: "test invalid detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 1", + Detail: "test warning detail 1", + }, + { + Severity: tfprotov6.DiagnosticSeverityError, + Summary: "test error summary 2", + Detail: "test error detail 2", + }, + { + Severity: tfprotov6.DiagnosticSeverityInvalid, + Summary: "test invalid summary 2", + Detail: "test invalid detail 2", + }, + { + Severity: tfprotov6.DiagnosticSeverityWarning, + Summary: "test warning summary 2", + Detail: "test warning detail 2", + }, + }, + expected: []map[string]interface{}{ + { + "@level": "trace", + "@message": "Received downstream response", + "@module": "sdk.proto", + // go-hclog treats int as float64 + "diagnostic_error_count": float64(2), + "diagnostic_warning_count": float64(2), + }, + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 1", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 1", + }, + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 1", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 1", + }, + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 1", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 1", + }, + { + "@level": "error", + "@message": "Response contains error diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test error detail 2", + "diagnostic_severity": "ERROR", + "diagnostic_summary": "test error summary 2", + }, + { + "@level": "warn", + "@message": "Response contains unknown diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test invalid detail 2", + "diagnostic_severity": "INVALID", + "diagnostic_summary": "test invalid summary 2", + }, + { + "@level": "warn", + "@message": "Response contains warning diagnostic", + "@module": "sdk.proto", + "diagnostic_detail": "test warning detail 2", + "diagnostic_severity": "WARNING", + "diagnostic_summary": "test warning summary 2", + }, + }, + }, + } + + for name, testCase := range testCases { + name, testCase := name, testCase + + t.Run(name, func(t *testing.T) { + t.Parallel() + + var output bytes.Buffer + + ctx := tfsdklogtest.RootLogger(context.Background(), &output) + ctx = logging.ProtoSubsystemContext(ctx, tfsdklog.Options{}) + + tf6serverlogging.DownstreamResponse(ctx, testCase.diagnostics) + + entries, err := tfsdklogtest.MultilineJSONDecode(&output) + + if err != nil { + t.Fatalf("unable to read multiple line JSON: %s", err) + } + + if diff := cmp.Diff(entries, testCase.expected); diff != "" { + t.Errorf("unexpected difference: %s", diff) + } + }) + } +} diff --git a/tfprotov6/tf6server/server.go b/tfprotov6/tf6server/server.go index 4ed9ece6..d4369e21 100644 --- a/tfprotov6/tf6server/server.go +++ b/tfprotov6/tf6server/server.go @@ -16,6 +16,7 @@ import ( "github.com/hashicorp/terraform-plugin-go/internal/logging" "github.com/hashicorp/terraform-plugin-go/tfprotov6" "github.com/hashicorp/terraform-plugin-go/tfprotov6/internal/fromproto" + "github.com/hashicorp/terraform-plugin-go/tfprotov6/internal/tf6serverlogging" "github.com/hashicorp/terraform-plugin-go/tfprotov6/internal/tfplugin6" "github.com/hashicorp/terraform-plugin-go/tfprotov6/internal/toproto" "google.golang.org/grpc" @@ -494,13 +495,13 @@ func (s *server) GetProviderSchema(ctx context.Context, req *tfplugin6.GetProvid logging.ProtocolError(ctx, "Error converting request from protobuf", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf6serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.GetProviderSchema(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf6serverlogging.DownstreamResponse(ctx, resp.Diagnostics) ret, err := toproto.GetProviderSchema_Response(resp) if err != nil { logging.ProtocolError(ctx, "Error converting response to protobuf", map[string]interface{}{logging.KeyError: err}) @@ -522,13 +523,13 @@ func (s *server) ConfigureProvider(ctx context.Context, req *tfplugin6.Configure return nil, err } logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf6serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ConfigureProvider(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf6serverlogging.DownstreamResponse(ctx, resp.Diagnostics) ret, err := toproto.Configure_Response(resp) if err != nil { logging.ProtocolError(ctx, "Error converting response to protobuf", map[string]interface{}{logging.KeyError: err}) @@ -549,13 +550,13 @@ func (s *server) ValidateProviderConfig(ctx context.Context, req *tfplugin6.Vali return nil, err } logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf6serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ValidateProviderConfig(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf6serverlogging.DownstreamResponse(ctx, resp.Diagnostics) ret, err := toproto.ValidateProviderConfig_Response(resp) if err != nil { logging.ProtocolError(ctx, "Error converting response to protobuf", map[string]interface{}{logging.KeyError: err}) @@ -589,13 +590,13 @@ func (s *server) Stop(ctx context.Context, req *tfplugin6.StopProvider_Request) logging.ProtocolError(ctx, "Error converting request from protobuf", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf6serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.StopProvider(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf6serverlogging.DownstreamResponse(ctx, nil) logging.ProtocolTrace(ctx, "Closing all our contexts") s.stop() logging.ProtocolTrace(ctx, "Closed all our contexts") @@ -621,13 +622,13 @@ func (s *server) ValidateDataResourceConfig(ctx context.Context, req *tfplugin6. return nil, err } logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf6serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ValidateDataResourceConfig(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf6serverlogging.DownstreamResponse(ctx, resp.Diagnostics) ret, err := toproto.ValidateDataResourceConfig_Response(resp) if err != nil { logging.ProtocolError(ctx, "Error converting response to protobuf", map[string]interface{}{logging.KeyError: err}) @@ -651,13 +652,13 @@ func (s *server) ReadDataSource(ctx context.Context, req *tfplugin6.ReadDataSour } logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "ProviderMeta", r.ProviderMeta) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf6serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ReadDataSource(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf6serverlogging.DownstreamResponse(ctx, resp.Diagnostics) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response", "State", resp.State) ret, err := toproto.ReadDataSource_Response(resp) if err != nil { @@ -681,13 +682,13 @@ func (s *server) ValidateResourceConfig(ctx context.Context, req *tfplugin6.Vali return nil, err } logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf6serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ValidateResourceConfig(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf6serverlogging.DownstreamResponse(ctx, resp.Diagnostics) ret, err := toproto.ValidateResourceConfig_Response(resp) if err != nil { logging.ProtocolError(ctx, "Error converting response to protobuf", map[string]interface{}{logging.KeyError: err}) @@ -709,13 +710,13 @@ func (s *server) UpgradeResourceState(ctx context.Context, req *tfplugin6.Upgrad logging.ProtocolError(ctx, "Error converting request from protobuf", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf6serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.UpgradeResourceState(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf6serverlogging.DownstreamResponse(ctx, resp.Diagnostics) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response", "UpgradedState", resp.UpgradedState) ret, err := toproto.UpgradeResourceState_Response(resp) if err != nil { @@ -740,13 +741,13 @@ func (s *server) ReadResource(ctx context.Context, req *tfplugin6.ReadResource_R } logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "CurrentState", r.CurrentState) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "ProviderMeta", r.ProviderMeta) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf6serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ReadResource(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf6serverlogging.DownstreamResponse(ctx, resp.Diagnostics) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response", "NewState", resp.NewState) ret, err := toproto.ReadResource_Response(resp) if err != nil { @@ -773,13 +774,13 @@ func (s *server) PlanResourceChange(ctx context.Context, req *tfplugin6.PlanReso logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "PriorState", r.PriorState) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "ProposedNewState", r.ProposedNewState) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "ProviderMeta", r.ProviderMeta) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf6serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.PlanResourceChange(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf6serverlogging.DownstreamResponse(ctx, resp.Diagnostics) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response", "PlannedState", resp.PlannedState) ret, err := toproto.PlanResourceChange_Response(resp) if err != nil { @@ -806,13 +807,13 @@ func (s *server) ApplyResourceChange(ctx context.Context, req *tfplugin6.ApplyRe logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "PlannedState", r.PlannedState) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Request", "Config", r.Config) - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf6serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ApplyResourceChange(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf6serverlogging.DownstreamResponse(ctx, resp.Diagnostics) logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response", "NewState", resp.NewState) ret, err := toproto.ApplyResourceChange_Response(resp) if err != nil { @@ -835,13 +836,13 @@ func (s *server) ImportResourceState(ctx context.Context, req *tfplugin6.ImportR logging.ProtocolError(ctx, "Error converting request from protobuf", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Calling downstream") + ctx = tf6serverlogging.DownstreamRequest(ctx) resp, err := s.downstream.ImportResourceState(ctx, r) if err != nil { logging.ProtocolError(ctx, "Error from downstream", map[string]interface{}{logging.KeyError: err}) return nil, err } - logging.ProtocolTrace(ctx, "Called downstream") + tf6serverlogging.DownstreamResponse(ctx, resp.Diagnostics) for _, importedResource := range resp.ImportedResources { logging.ProtocolData(ctx, s.protocolDataDir, rpc, "Response_ImportedResource", "State", importedResource.State) }