Implement protocol data logging (#135)

Reference: #107

Refactors `tf5server` and `tf6server` log handling into shared internal/logging package to prevent additional code duplication.

To enable protocol data handling, utilizes the `TF_LOG_SDK_PROTO_DATA_DIR` environment variable to enable writing individual data field files to disk. In the future, this may need to be offered as a server configuration so it can work better in conjunction with testing frameworks (e.g. `t.TempDir()`), but there should not be too much preventing that as a later enhancement as necessary.

Without `TF_LOG_SDK_PROTO_DATA_DIR` set (once):

```text
2022-01-06T16:04:54.787-0500 [TRACE] provider.terraform-provider-framework: Skipping protocol data file writing because no data directory is set. Use the TF_LOG_SDK_PROTO_DATA_DIR environment variable to enable this functionality.: tf_req_id=105b9e19-be94-411d-2f52-ca84c14f951e tf_resource_type=framework_optional_types tf_rpc=ValidateResourceConfig @caller=/Users/bflad/src/github.com/hashicorp/terraform-plugin-go/internal/logging/protocol.go:21 @module=sdk.proto EXTRA_VALUE_AT_END=<nil> tf_provider_addr=registry.terraform.io/bflad/framework tf_proto_version=6 timestamp=2022-01-06T16:04:54.786-0500
```

With `TF_LOG_SDK_PROTO_DATA_DIR` set (per `DynamicValue` field):

```text
2022-01-06T16:06:36.079-0500 [TRACE] provider.terraform-provider-framework: Writing protocol data file: EXTRA_VALUE_AT_END=[tf_proto_data_file, 1641503196_ValidateResourceConfig_Request_Config.msgpack] tf_rpc=ValidateResourceConfig @module=sdk.proto tf_proto_version=6 tf_provider_addr=registry.terraform.io/bflad/framework tf_req_id=9084bc21-f6d1-bcc8-b916-fe75595375d2 tf_resource_type=framework_optional_types @caller=/Users/bflad/src/github.com/hashicorp/terraform-plugin-go/internal/logging/protocol.go:21 timestamp=2022-01-06T16:06:36.079-0500
```

Viewing example MessagePack file contents:

```console
$ go install github.com/nokute78/msgpack-microscope/cmd/msgpack2json@latest
$ msgpack2json 1641503196_PlanResourceChange_Request_Config.msgpack | jq .
{
  "format": "fixmap",
  "header": "0x85",
  "length": 5,
  "raw": "0x85a26964c0b36f7074696f6e616c5f74797065735f626f6f6cc0b66f7074696f6e616c5f74797065735f666c6f61743634c0b46f7074696f6e616c5f74797065735f696e743634c0b56f7074696f6e616c5f74797065735f737472696e67c0",
  "value": [
    {
      "key": {
        "format": "fixstr",
        "header": "0xa2",
        "raw": "0xa26964",
        "value": "id"
      },
      "value": {
        "format": "nil",
        "header": "0xc0",
        "raw": "0xc0",
        "value": null
      }
    },
    {
      "key": {
        "format": "fixstr",
        "header": "0xb3",
        "raw": "0xb36f7074696f6e616c5f74797065735f626f6f6c",
        "value": "optional_types_bool"
      },
      "value": {
        "format": "nil",
        "header": "0xc0",
        "raw": "0xc0",
        "value": null
      }
    },
    {
      "key": {
        "format": "fixstr",
        "header": "0xb6",
        "raw": "0xb66f7074696f6e616c5f74797065735f666c6f61743634",
        "value": "optional_types_float64"
      },
      "value": {
        "format": "nil",
        "header": "0xc0",
        "raw": "0xc0",
        "value": null
      }
    },
    {
      "key": {
        "format": "fixstr",
        "header": "0xb4",
        "raw": "0xb46f7074696f6e616c5f74797065735f696e743634",
        "value": "optional_types_int64"
      },
      "value": {
        "format": "nil",
        "header": "0xc0",
        "raw": "0xc0",
        "value": null
      }
    },
    {
      "key": {
        "format": "fixstr",
        "header": "0xb5",
        "raw": "0xb56f7074696f6e616c5f74797065735f737472696e67",
        "value": "optional_types_string"
      },
      "value": {
        "format": "nil",
        "header": "0xc0",
        "raw": "0xc0",
        "value": null
      }
    }
  ]
}
```

Author: bflad

.changelog/135.txt

@@ -0,0 +1,7 @@
+```release-note:enhancement
+tfprotov5/tf5server: Added support for writing protocol data to disk by setting `TF_LOG_SDK_PROTO_DATA_DIR` environment variable
+```
+
+```release-note:enhancement
+tfprotov6/tf6server: Added support for writing protocol data to disk by setting `TF_LOG_SDK_PROTO_DATA_DIR` environment variable
+```

README.md

@@ -119,6 +119,10 @@ func main() {
 }
 ```
 
+### Protocol Data
+
+To write raw protocol MessagePack or JSON data to disk, set the `TF_LOG_SDK_PROTO_DATA_DIR` environment variable. During Terraform execution, this directory will get populated with `{TIME}_{RPC}_{MESSAGE}_{FIELD}.{EXTENSION}` named files. Tooling such as [`jq`](https://stedolan.github.io/jq/) can be used to inspect the JSON data. Tooling such as [`fq`](https://github.com/wader/fq) or [`msgpack2json`](https://pkg.go.dev/github.com/nokute78/msgpack-microscope/cmd/msgpack2json) can be used to inspect the MessagePack data.
+
 ## Documentation
 
 Documentation is a work in progress. The GoDoc for packages, types, functions,

internal/logging/context.go

@@ -0,0 +1,80 @@
+package logging
+
+import (
+	"context"
+
+	"github.com/hashicorp/go-uuid"
+	"github.com/hashicorp/terraform-plugin-log/tflog"
+	"github.com/hashicorp/terraform-plugin-log/tfsdklog"
+)
+
+// DataSourceContext injects the data source type into logger contexts.
+func DataSourceContext(ctx context.Context, dataSource string) context.Context {
+	ctx = tfsdklog.With(ctx, KeyDataSourceType, dataSource)
+	ctx = tfsdklog.SubsystemWith(ctx, SubsystemProto, KeyDataSourceType, dataSource)
+	ctx = tflog.With(ctx, KeyDataSourceType, dataSource)
+
+	return ctx
+}
+
+// InitContext creates SDK and provider logger contexts.
+func InitContext(ctx context.Context, sdkOpts tfsdklog.Options, providerOpts tflog.Options) context.Context {
+	ctx = tfsdklog.NewRootSDKLogger(ctx, append(tfsdklog.Options{
+		tfsdklog.WithLevelFromEnv(EnvTfLogSdk),
+	}, sdkOpts...)...)
+	ctx = tfsdklog.NewSubsystem(ctx, SubsystemProto, append(tfsdklog.Options{
+		tfsdklog.WithLevelFromEnv(EnvTfLogSdkProto),
+	}, sdkOpts...)...)
+	ctx = tfsdklog.NewRootProviderLogger(ctx, providerOpts...)
+
+	return ctx
+}
+
+// ProtocolVersionContext injects the protocol version into logger contexts.
+func ProtocolVersionContext(ctx context.Context, protocolVersion string) context.Context {
+	ctx = tfsdklog.SubsystemWith(ctx, SubsystemProto, KeyProtocolVersion, protocolVersion)
+
+	return ctx
+}
+
+// ProviderAddressContext injects the provider address into logger contexts.
+func ProviderAddressContext(ctx context.Context, providerAddress string) context.Context {
+	ctx = tfsdklog.With(ctx, KeyProviderAddress, providerAddress)
+	ctx = tfsdklog.SubsystemWith(ctx, SubsystemProto, KeyProviderAddress, providerAddress)
+	ctx = tflog.With(ctx, KeyProviderAddress, providerAddress)
+
+	return ctx
+}
+
+// RequestIdContext injects a unique request ID into logger contexts.
+func RequestIdContext(ctx context.Context) context.Context {
+	reqID, err := uuid.GenerateUUID()
+
+	if err != nil {
+		reqID = "unable to assign request ID: " + err.Error()
+	}
+
+	ctx = tfsdklog.With(ctx, KeyRequestID, reqID)
+	ctx = tfsdklog.SubsystemWith(ctx, SubsystemProto, KeyRequestID, reqID)
+	ctx = tflog.With(ctx, KeyRequestID, reqID)
+
+	return ctx
+}
+
+// ResourceContext injects the resource type into logger contexts.
+func ResourceContext(ctx context.Context, resource string) context.Context {
+	ctx = tfsdklog.With(ctx, KeyResourceType, resource)
+	ctx = tfsdklog.SubsystemWith(ctx, SubsystemProto, KeyResourceType, resource)
+	ctx = tflog.With(ctx, KeyResourceType, resource)
+
+	return ctx
+}
+
+// RpcContext injects the RPC name into logger contexts.
+func RpcContext(ctx context.Context, rpc string) context.Context {
+	ctx = tfsdklog.With(ctx, KeyRPC, rpc)
+	ctx = tfsdklog.SubsystemWith(ctx, SubsystemProto, KeyRPC, rpc)
+	ctx = tflog.With(ctx, KeyRPC, rpc)
+
+	return ctx
+}

internal/logging/doc.go

@@ -0,0 +1,2 @@
+// Package logging contains shared environment variable and log functionality.
+package logging

internal/logging/environment_variables.go

@@ -0,0 +1,22 @@
+package logging
+
+// Environment variables.
+const (
+	// EnvTfLogProvider is the prefix of the environment variable that sets the
+	// logging level of the root provider logger for the provider being served.
+	// The suffix is an underscore and the parsed provider name. For example,
+	// registry.terraform.io/hashicorp/example becomes TF_LOG_PROVIDER_EXAMPLE.
+	EnvTfLogProvider = "TF_LOG_PROVIDER"
+
+	// EnvTfLogSdk is an environment variable that sets the root logging level
+	// of SDK loggers.
+	EnvTfLogSdk = "TF_LOG_SDK"
+
+	// EnvTfLogSdkProto is an environment variable that sets the logging level
+	// of SDK protocol loggers. Infers root SDK logging level, if unset.
+	EnvTfLogSdkProto = "TF_LOG_SDK_PROTO"
+
+	// EnvTfLogSdkProtoDataDir is an environment variable that sets the
+	// directory to write raw protocol data files for debugging purposes.
+	EnvTfLogSdkProtoDataDir = "TF_LOG_SDK_PROTO_DATA_DIR"
+)

internal/logging/keys.go

@@ -0,0 +1,29 @@
+package logging
+
+// Global logging keys attached to all requests.
+//
+// Practitioners or tooling reading logs may be depending on these keys, so be
+// conscious of that when changing them.
+const (
+	// A unique ID for the RPC request
+	KeyRequestID = "tf_req_id"
+
+	// The full address of the provider, such as
+	// registry.terraform.io/hashicorp/random
+	KeyProviderAddress = "tf_provider_addr"
+
+	// The RPC being run, such as "ApplyResourceChange"
+	KeyRPC = "tf_rpc"
+
+	// The type of resource being operated on, such as "random_pet"
+	KeyResourceType = "tf_resource_type"
+
+	// The type of data source being operated on, such as "archive_file"
+	KeyDataSourceType = "tf_data_source_type"
+
+	// Path to protocol data file, such as "/tmp/example.json"
+	KeyProtocolDataFile = "tf_proto_data_file"
+
+	// The protocol version being used, as a string, such as "6"
+	KeyProtocolVersion = "tf_proto_version"
+)

internal/logging/protocol.go

@@ -0,0 +1,22 @@
+package logging
+
+import (
+	"context"
+
+	"github.com/hashicorp/terraform-plugin-log/tfsdklog"
+)
+
+const (
+	// SubsystemProto is the tfsdklog subsystem name for protocol logging.
+	SubsystemProto = "proto"
+)
+
+// ProtocolError emits a protocol subsystem log at ERROR level.
+func ProtocolError(ctx context.Context, msg string, args ...interface{}) {
+	tfsdklog.SubsystemError(ctx, SubsystemProto, msg, args)
+}
+
+// ProtocolTrace emits a protocol subsystem log at TRACE level.
+func ProtocolTrace(ctx context.Context, msg string, args ...interface{}) {
+	tfsdklog.SubsystemTrace(ctx, SubsystemProto, msg, args)
+}

internal/logging/protocol_data.go

@@ -0,0 +1,107 @@
+package logging
+
+import (
+	"context"
+	"fmt"
+	"os"
+	"path"
+	"sync"
+	"time"
+
+	"github.com/hashicorp/terraform-plugin-go/tfprotov5"
+	"github.com/hashicorp/terraform-plugin-go/tfprotov6"
+)
+
+const (
+	// fileExtEmpty is the file extension for empty data.
+	// Empty data may be expected, depending on the RPC.
+	fileExtEmpty = "empty"
+
+	// fileExtJson is the file extension for JSON data.
+	fileExtJson = "json"
+
+	// fileExtMsgpack is the file extension for MessagePack data.
+	fileExtMsgpack = "msgpack"
+)
+
+var protocolDataSkippedLog sync.Once
+
+// ProtocolData emits raw protocol data to a file, if given a directory.
+//
+// The directory must exist and be writable, prior to invoking this function.
+//
+// File names are in the format: {TIME}_{RPC}_{MESSAGE}_{FIELD}.{EXT}
+func ProtocolData(ctx context.Context, dataDir string, rpc string, message string, field string, data interface{}) {
+	if dataDir == "" {
+		// Write a log, only once, that explains how to enable this functionality.
+		protocolDataSkippedLog.Do(func() {
+			ProtocolTrace(ctx, "Skipping protocol data file writing because no data directory is set. "+
+				fmt.Sprintf("Use the %s environment variable to enable this functionality.", EnvTfLogSdkProtoDataDir))
+		})
+
+		return
+	}
+
+	var fileContents []byte
+	var fileExtension string
+
+	switch data := data.(type) {
+	case *tfprotov5.DynamicValue:
+		fileExtension, fileContents = protocolDataDynamicValue5(ctx, data)
+	case *tfprotov6.DynamicValue:
+		fileExtension, fileContents = protocolDataDynamicValue6(ctx, data)
+	default:
+		ProtocolError(ctx, fmt.Sprintf("Skipping unknown protocol data type: %T", data))
+		return
+	}
+
+	fileName := fmt.Sprintf("%d_%s_%s_%s.%s", time.Now().Unix(), rpc, message, field, fileExtension)
+	filePath := path.Join(dataDir, fileName)
+
+	ProtocolTrace(ctx, "Writing protocol data file", KeyProtocolDataFile, filePath)
+
+	err := os.WriteFile(filePath, fileContents, 0644)
+
+	if err != nil {
+		ProtocolError(ctx, fmt.Sprintf("Unable to write protocol data file: %s", err), KeyProtocolDataFile, filePath)
+		return
+	}
+
+	ProtocolTrace(ctx, "Wrote protocol data file", KeyProtocolDataFile, filePath)
+}
+
+func protocolDataDynamicValue5(ctx context.Context, value *tfprotov5.DynamicValue) (string, []byte) {
+	if value == nil {
+		return fileExtEmpty, nil
+	}
+
+	// (tfprotov5.DynamicValue).Unmarshal() prefers JSON first, so prefer to
+	// output JSON if found.
+	if len(value.JSON) > 0 {
+		return fileExtJson, value.JSON
+	}
+
+	if len(value.MsgPack) > 0 {
+		return fileExtMsgpack, value.MsgPack
+	}
+
+	return fileExtEmpty, nil
+}
+
+func protocolDataDynamicValue6(ctx context.Context, value *tfprotov6.DynamicValue) (string, []byte) {
+	if value == nil {
+		return fileExtEmpty, nil
+	}
+
+	// (tfprotov6.DynamicValue).Unmarshal() prefers JSON first, so prefer to
+	// output JSON if found.
+	if len(value.JSON) > 0 {
+		return fileExtJson, value.JSON
+	}
+
+	if len(value.MsgPack) > 0 {
+		return fileExtMsgpack, value.MsgPack
+	}
+
+	return fileExtEmpty, nil
+}

internal/logging/provider.go

@@ -0,0 +1,19 @@
+package logging
+
+import (
+	"log"
+	"strings"
+
+	tfaddr "github.com/hashicorp/terraform-registry-address"
+)
+
+func ProviderLoggerName(providerAddress string) string {
+	provider, err := tfaddr.ParseRawProviderSourceString(providerAddress)
+
+	if err != nil {
+		log.Printf("[ERROR] Error parsing provider name %q: %s", providerAddress, err)
+		return ""
+	}
+
+	return strings.ReplaceAll(provider.Type, "-", "_")
+}

internal/logging/provider_test.go

@@ -0,0 +1,39 @@
+package logging
+
+import "testing"
+
+func TestProviderLoggerName(t *testing.T) {
+	t.Parallel()
+
+	testCases := map[string]struct {
+		providerAddress string
+		expected        string
+	}{
+		"unparseable": {
+			providerAddress: "example.com/test",
+			expected:        "",
+		},
+		"basic": {
+			providerAddress: "example.com/user/test",
+			expected:        "test",
+		},
+		"hyphenated": {
+			providerAddress: "example.com/user/test-test",
+			expected:        "test_test",
+		},
+	}
+
+	for name, testCase := range testCases {
+		testCase := testCase
+
+		t.Run(name, func(t *testing.T) {
+			t.Parallel()
+
+			got := ProviderLoggerName(testCase.providerAddress)
+
+			if testCase.expected != got {
+				t.Errorf("wanted: %q, got: %q", testCase.expected, got)
+			}
+		})
+	}
+}