From e110ba693f53b47a17bf55e4f673b71d667b43a3 Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Mon, 18 Jul 2022 16:46:24 +0100 Subject: [PATCH 01/16] .gitignore JetBrains IDE project files --- .gitignore | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/.gitignore b/.gitignore index 1fa9f4e493..637ea69288 100644 --- a/.gitignore +++ b/.gitignore @@ -1,2 +1,6 @@ node_modules -website-preview \ No newline at end of file +website-preview + +# Jetbrains IDEs +.idea/ +*.iws From 6601cf7a294ec907dc18d404e48c5d18803e4593 Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Mon, 18 Jul 2022 16:47:01 +0100 Subject: [PATCH 02/16] Removing `fmtcheck` target in `Makefile`, and instead add `lint` to trigger GolangCI-Lint (what we use today) --- Makefile | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/Makefile b/Makefile index cc49a0929c..20cb17a7a6 100644 --- a/Makefile +++ b/Makefile @@ -22,17 +22,17 @@ WEBSITE_DOCKER_RUN_FLAGS=--interactive \ default: test -test: fmtcheck generate +test: generate go test ./... +lint: + golangci-lint run + generate: go generate ./... fmt: - gofmt -w $(GOFMT_FILES) - -fmtcheck: - @sh -c "'$(CURDIR)/scripts/gofmtcheck.sh'" + gofmt -s -w -e $(GOFMT_FILES) # Run the terraform.io website to preview local content changes website: @@ -55,4 +55,4 @@ website/build-local: @docker build https://github.com/hashicorp/terraform-website.git\#$(WEBSITE_BRANCH) \ -t $(WEBSITE_DOCKER_IMAGE_LOCAL) -.PHONY: default fmt fmtcheck generate test website website/local website/build-local \ No newline at end of file +.PHONY: default fmt lint generate test website website/local website/build-local From 6a4c7d939ce045035fda2feac42568bafd417630 Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Mon, 18 Jul 2022 16:48:55 +0100 Subject: [PATCH 03/16] Introducing `helper/logging` `NewLoggingHTTPTransport` This deprecated the `NewTransport` facility. --- helper/logging/logging_http_transport.go | 210 ++++++++++++++++++ helper/logging/logging_http_transport_test.go | 122 ++++++++++ helper/logging/transport.go | 9 + 3 files changed, 341 insertions(+) create mode 100644 helper/logging/logging_http_transport.go create mode 100644 helper/logging/logging_http_transport_test.go diff --git a/helper/logging/logging_http_transport.go b/helper/logging/logging_http_transport.go new file mode 100644 index 0000000000..ea8fb62b34 --- /dev/null +++ b/helper/logging/logging_http_transport.go @@ -0,0 +1,210 @@ +package logging + +import ( + "context" + "fmt" + "net/http" + "net/http/httputil" + "strconv" + "strings" + + "github.com/hashicorp/terraform-plugin-log/tflog" +) + +const ( + // FieldHttpOperationType is the field key used by NewLoggingHTTPTransport when logging the type of operation via tflog. + FieldHttpOperationType = "__HTTP_OP_TYPE__" + + // OperationHttpRequest is the field value used by NewLoggingHTTPTransport when logging a request via tflog. + OperationHttpRequest = "HTTP_REQ" + + // FieldHttpRequestMethod is the field key used by NewLoggingHTTPTransport when logging a request method via tflog. + FieldHttpRequestMethod = "__HTTP_REQ_METHOD__" + + // FieldHttpRequestUri is the field key used by NewLoggingHTTPTransport when logging a request URI via tflog. + FieldHttpRequestUri = "__HTTP_REQ_URI__" + + // FieldHttpRequestVersion is the field key used by NewLoggingHTTPTransport when logging a request HTTP version via tflog. + FieldHttpRequestVersion = "__HTTP_REQ_VERSION__" + + // OperationHttpResponse is the field value used by NewLoggingHTTPTransport when logging a response via tflog. + OperationHttpResponse = "HTTP_RES" + + // FieldHttpResponseVersion is the field key used by NewLoggingHTTPTransport when logging a response HTTP version via tflog. + FieldHttpResponseVersion = "__HTTP_RES_VERSION__" + + // FieldHttpResponseStatusCode is the field key used by NewLoggingHTTPTransport when logging a response status code via tflog. + FieldHttpResponseStatusCode = "__HTTP_RES_STATUS__" + + // FieldHttpResponseReason is the field key used by NewLoggingHTTPTransport when logging a response reason phrase via tflog. + FieldHttpResponseReason = "__HTTP_RES_REASON__" +) + +// ConfigureReqCtxFunc is the type of function accepted by loggingHTTPTransport.WithConfigureRequestContext, +// to configure the request subsystem logging context before the actual logging. +type ConfigureReqCtxFunc func(ctx context.Context, subsystem string) context.Context + +type loggingHTTPTransport struct { + subsystem string + transport http.RoundTripper + configureReqCtx ConfigureReqCtxFunc +} + +func (t *loggingHTTPTransport) RoundTrip(req *http.Request) (*http.Response, error) { + // Create a new subsystem logging context from the request context + ctx := tflog.NewSubsystem(req.Context(), t.subsystem) + + // If set, allow for further configuration of the new subsystem logging context + if t.configureReqCtx != nil { + ctx = t.configureReqCtx(ctx, t.subsystem) + } + + if IsDebugOrHigher() { + // Grub the outgoing request bytes + reqDump, err := httputil.DumpRequestOut(req, true) + if err != nil { + tflog.SubsystemError(ctx, t.subsystem, "HTTP Request introspection failed", map[string]interface{}{ + "error": fmt.Sprintf("%#v", err), + }) + } + + // Decompose the request bytes in a message (HTTP body) and fields (HTTP headers), then log it + msg, fields := decomposeRequestBytes(reqDump) + tflog.SubsystemDebug(ctx, t.subsystem, msg, fields) + } + + // Invoke the wrapped RoundTrip now + res, err := t.transport.RoundTrip(req) + if err != nil { + return res, err + } + + if IsDebugOrHigher() { + // Grub the incoming response bytes + resDump, err := httputil.DumpResponse(res, true) + if err != nil { + tflog.SubsystemError(ctx, t.subsystem, "HTTP Response introspection error", map[string]interface{}{ + "error": fmt.Sprintf("%#v", err), + }) + } + + // Decompose the response bytes in a message (HTTP body) and fields (HTTP headers), then log it + msg, fields := decomposeResponseBytes(resDump) + tflog.SubsystemDebug(ctx, t.subsystem, msg, fields) + } + + return res, nil +} + +// NewLoggingHTTPTransport creates a wrapper around a *http.RoundTripper, +// designed to be used for the `Transport` field of http.Client. +// +// This logs each pair of HTTP request/response that it handles. +// The logging is done via `tflog`, that is part of the terraform-plugin-log +// library, included by this SDK. +// +// The request/response is logged via tflog.SubsystemDebug, and the `subsystem` +// is the one provide here. +// +// IMPORTANT: For logging to work, it's mandatory that each http.Request it handles +// is configured with the Context (i.e. `Request.WithContext(ctx)`) +// that the SDK passes into all resources/data-sources/provider entry-points +// (i.e. schema.Resource fields like `CreateContext`, `ReadContext`, etc.). +func NewLoggingHTTPTransport(subsystem string, t http.RoundTripper) *loggingHTTPTransport { + return &loggingHTTPTransport{subsystem, t, nil} +} + +// WithConfigureRequestContext allows to optionally configure a callback ConfigureReqCtxFunc. +// This is used by the underlying structure to allow user to configure the +// http.Request context.Context, before the request is executed and the logger +// tflog.SubsystemDebug invoked. +// +// Log entries will be structured to contain: +// +// * the HTTP message first line, broken up into "fields" (see `FieldHttp*` constants) +// * the Headers, each as "fields" of the log +// * the Request/Response Body as "message" of the log +// +// For example, here is how to add an extra field to each log emitted here, +// as well as masking fields that have a specific key: +// +// t.WithConfigureRequestContext(func (ctx context.Context, subsystem string) context.Context { +// ctx = tflog.SetField(ctx, "additional_key", "additional_value") +// ctx = tflog.MaskFieldValuesWithFieldKeys(ctx, "secret", "token", "Authorization") +// }) +// +func (t *loggingHTTPTransport) WithConfigureRequestContext(callback ConfigureReqCtxFunc) *loggingHTTPTransport { + t.configureReqCtx = callback + return t +} + +func decomposeRequestBytes(b []byte) (string, map[string]interface{}) { + parts := strings.Split(string(b), "\r\n") + + // We will end up with a number of fields equivalent to the number of parts + 1: + // - the first will be split into 3 parts + // - the last 2 are "end of headers" and "body" + // - one extra for the operation type + fields := make(map[string]interface{}, len(parts)+1) + fields[FieldHttpOperationType] = OperationHttpRequest + + // HTTP Request Line + reqLineParts := strings.Split(parts[0], " ") + fields[FieldHttpRequestMethod] = reqLineParts[0] + fields[FieldHttpRequestUri] = reqLineParts[1] + fields[FieldHttpRequestVersion] = reqLineParts[2] + + // HTTP Request Headers + var i int + for i = 1; i < len(parts)-2; i++ { + // Check if we reached the end of the headers + if parts[i] == "" { + break + } + + headerParts := strings.Split(parts[i], ": ") + fields[headerParts[0]] = headerParts[1] + } + + // HTTP Response Body: the last part is always the body (can be empty) + return parts[len(parts)-1], fields +} + +func decomposeResponseBytes(b []byte) (string, map[string]interface{}) { + parts := strings.Split(string(b), "\r\n") + + // We will end up with a number of fields equivalent to the number of parts: + // - the first will be split into 3 parts + // - the last 2 are "end of headers" and "body" + // - one extra for the operation type + fields := make(map[string]interface{}, len(parts)) + fields[FieldHttpOperationType] = OperationHttpResponse + + // HTTP Message Status Line + reqLineParts := strings.Split(parts[0], " ") + fields[FieldHttpResponseVersion] = reqLineParts[0] + // NOTE: Unlikely, but if we can't parse the status code, + // we set its field value to string + statusCode, err := strconv.Atoi(reqLineParts[1]) + if err != nil { + fields[FieldHttpResponseStatusCode] = reqLineParts[1] + } else { + fields[FieldHttpResponseStatusCode] = statusCode + } + fields[FieldHttpResponseReason] = reqLineParts[2] + + // HTTP Response Headers + var i int + for i = 1; i < len(parts)-2; i++ { + // Check if we reached the end of the headers + if parts[i] == "" { + break + } + + headerParts := strings.Split(parts[i], ": ") + fields[headerParts[0]] = headerParts[1] + } + + // HTTP Response Body: the last part is always the body (can be empty) + return parts[len(parts)-1], fields +} diff --git a/helper/logging/logging_http_transport_test.go b/helper/logging/logging_http_transport_test.go new file mode 100644 index 0000000000..3f22757499 --- /dev/null +++ b/helper/logging/logging_http_transport_test.go @@ -0,0 +1,122 @@ +package logging_test + +import ( + "bytes" + "context" + "net/http" + "regexp" + "testing" + "time" + + "github.com/google/go-cmp/cmp" + "github.com/hashicorp/terraform-plugin-log/tflog" + "github.com/hashicorp/terraform-plugin-log/tflogtest" + "github.com/hashicorp/terraform-plugin-sdk/v2/helper/logging" +) + +func TestNewLoggingHTTPTransport(t *testing.T) { + ctx, loggerOutput := setupRootLogger(t) + + transport := logging.NewLoggingHTTPTransport("test", http.DefaultTransport) + client := http.Client{ + Transport: transport, + Timeout: 10 * time.Second, + } + + req, _ := http.NewRequest("GET", "https://www.terraform.io", nil) + res, err := client.Do(req.WithContext(ctx)) + if err != nil { + t.Fatalf("request failed: %v", err) + } + defer res.Body.Close() + + entries, err := tflogtest.MultilineJSONDecode(loggerOutput) + if err != nil { + t.Fatalf("log outtput parsing failed: %v", err) + } + + if len(entries) != 2 { + t.Fatalf("unexpected amount of logs produced; expected 2, got %d", len(entries)) + } + + reqEntry := entries[0] + if diff := cmp.Diff(reqEntry, map[string]interface{}{ + "@level": "debug", + "@message": "", + "@module": "provider.test", + "__HTTP_OP_TYPE__": "HTTP_REQ", + "__HTTP_REQ_METHOD__": "GET", + "__HTTP_REQ_URI__": "/", + "__HTTP_REQ_VERSION__": "HTTP/1.1", + "Accept-Encoding": "gzip", + "Host": "www.terraform.io", + "User-Agent": "Go-http-client/1.1", + }); diff != "" { + t.Fatalf("unexpected difference for logging of the request:\n%s", diff) + } + + resEntry := entries[1] + expectedResEntryFields := map[string]interface{}{ + "@level": "debug", + "@module": "provider.test", + "Content-Type": "text/html", + "__HTTP_OP_TYPE__": "HTTP_RES", + "__HTTP_RES_STATUS__": float64(200), + "__HTTP_RES_VERSION__": "HTTP/2.0", + "__HTTP_RES_REASON__": "OK", + } + for ek, ev := range expectedResEntryFields { + if resEntry[ek] != ev { + t.Fatalf("Unexpected value for field %q; expected %q, got %q", ek, ev, resEntry[ek]) + } + } +} + +func TestNewLoggingHTTPTransport_LogMasking(t *testing.T) { + ctx, loggerOutput := setupRootLogger(t) + + transport := logging.NewLoggingHTTPTransport("test", http.DefaultTransport) + transport.WithConfigureRequestContext(func(ctx context.Context, subsystem string) context.Context { + ctx = tflog.SubsystemMaskFieldValuesWithFieldKeys(ctx, subsystem, "__HTTP_OP_TYPE__") + ctx = tflog.SubsystemMaskMessageRegexes(ctx, subsystem, regexp.MustCompile(`.*`)) + return ctx + }) + client := http.Client{ + Transport: transport, + Timeout: 10 * time.Second, + } + + req, _ := http.NewRequest("GET", "https://www.terraform.io", nil) + res, err := client.Do(req.WithContext(ctx)) + if err != nil { + t.Fatalf("request failed: %v", err) + } + defer res.Body.Close() + + entries, err := tflogtest.MultilineJSONDecode(loggerOutput) + if err != nil { + t.Fatalf("log outtput parsing failed: %v", err) + } + + if len(entries) != 2 { + t.Fatalf("unexpected amount of logs produced; expected 2, got %d", len(entries)) + } + + expectedMaskedEntryFields := map[string]interface{}{ + "__HTTP_OP_TYPE__": "***", + "@message": "***", + } + for _, entry := range entries { + for ek, ev := range expectedMaskedEntryFields { + if entry[ek] != "" && entry[ek] != ev { + t.Fatalf("Unexpected value for field %q; expected %q, got %q", ek, ev, entry[ek]) + } + } + } +} + +func setupRootLogger(t *testing.T) (context.Context, *bytes.Buffer) { + t.Setenv(logging.EnvLog, "TRACE") + var output bytes.Buffer + return tflogtest.RootLogger(context.Background(), &output), &output +} diff --git a/helper/logging/transport.go b/helper/logging/transport.go index 6419605e79..1d86838649 100644 --- a/helper/logging/transport.go +++ b/helper/logging/transport.go @@ -41,6 +41,15 @@ func (t *transport) RoundTrip(req *http.Request) (*http.Response, error) { return resp, nil } +// NewTransport creates a wrapper around a *http.RoundTripper, +// designed to be used for the `Transport` field of http.Client. +// +// This logs each pair of HTTP request/response that it handles. +// The logging is done via standard `log`. +// +// Deprecated: This will log the content of every http request/response +// at `[DEBUG]` level, without any filtering. Any sensitive information +// will appear as-is in your logs. Please use NewLoggingHTTPTransport instead. func NewTransport(name string, t http.RoundTripper) *transport { return &transport{name, t} } From a1c98bb6974bc4454255ff90cc7842dce88d2dfb Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Mon, 18 Jul 2022 17:56:53 +0100 Subject: [PATCH 04/16] Set golangci-lint GH Action to always pick the latest version of golangci-lint executable --- .github/workflows/ci-go.yml | 4 +++- helper/schema/provider_test.go | 3 +-- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/.github/workflows/ci-go.yml b/.github/workflows/ci-go.yml index 56a997cd6e..c9bc27e363 100644 --- a/.github/workflows/ci-go.yml +++ b/.github/workflows/ci-go.yml @@ -21,7 +21,9 @@ jobs: with: go-version-file: 'go.mod' - run: go mod download - - uses: golangci/golangci-lint-action@v3.2.0 + - uses: golangci/golangci-lint-action@v3 + with: + version: latest terraform-provider-corner: defaults: run: diff --git a/helper/schema/provider_test.go b/helper/schema/provider_test.go index 0445e0ef88..e791df50e4 100644 --- a/helper/schema/provider_test.go +++ b/helper/schema/provider_test.go @@ -1002,8 +1002,7 @@ func TestProviderUserAgentAppendViaEnvVar(t *testing.T) { for i, tc := range testCases { t.Run(fmt.Sprintf("%d", i), func(t *testing.T) { - os.Unsetenv(uaEnvVar) - os.Setenv(uaEnvVar, tc.envVarValue) + t.Setenv(uaEnvVar, tc.envVarValue) p := &Provider{TerraformVersion: "4.5.6"} givenUA := p.UserAgent(tc.providerName, tc.providerVersion) if givenUA != tc.expected { From 9e04373c42d496df16e693be9f53695fe2d6c5f5 Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Tue, 19 Jul 2022 19:14:28 +0100 Subject: [PATCH 05/16] PR review implementation --- helper/logging/logging_http_transport.go | 222 ++++++++++-------- helper/logging/logging_http_transport_test.go | 135 ++++++++--- helper/logging/transport.go | 4 +- 3 files changed, 222 insertions(+), 139 deletions(-) diff --git a/helper/logging/logging_http_transport.go b/helper/logging/logging_http_transport.go index ea8fb62b34..3be3ea8371 100644 --- a/helper/logging/logging_http_transport.go +++ b/helper/logging/logging_http_transport.go @@ -11,66 +11,106 @@ import ( "github.com/hashicorp/terraform-plugin-log/tflog" ) +// NewLoggingHTTPTransport creates a wrapper around an *http.RoundTripper, +// designed to be used for the `Transport` field of http.Client. +// +// This logs each pair of HTTP request/response that it handles. +// The logging is done via `tflog`, that is part of the terraform-plugin-log +// library, included by this SDK. +// +// The request/response is logged via tflog.Debug, using the context.Context +// attached to the http.Request that the transport receives as input +// of http.RoundTripper RoundTrip method. +// +// It's responsibility of the developer using this transport, to ensure that each +// http.Request it handles is configured with the SDK-initialized Provider Root Logger +// context.Context, that it's passed to all resources/data-sources/provider entry-points +// (i.e. schema.Resource fields like `CreateContext`, `ReadContext`, etc.). +// +// This also gives the developer the flexibility to further configure the +// logging behaviour via the above-mentioned context: please see +// https://www.terraform.io/plugin/log/writing. +func NewLoggingHTTPTransport(t http.RoundTripper) *loggingHttpTransport { + return &loggingHttpTransport{"", false, t} +} + +// NewSubsystemLoggingHTTPTransport creates a wrapper around an *http.RoundTripper, +// designed to be used for the `Transport` field of http.Client. +// +// This logs each pair of HTTP request/response that it handles. +// The logging is done via `tflog`, that is part of the terraform-plugin-log +// library, included by this SDK. +// +// The request/response is logged via tflog.SubsystemDebug, using the context.Context +// attached to the http.Request that the transport receives as input +// of http.RoundTripper RoundTrip method, as well as the `subsystem` string +// provided at construction time. +// +// It's responsibility of the developer using this transport, to ensure that each +// http.Request it handles is configured with a Subsystem Logger +// context.Context that was initialized via tflog.NewSubsystem. +// +// This also gives the developer the flexibility to further configure the +// logging behaviour via the above-mentioned context: please see +// https://www.terraform.io/plugin/log/writing. +func NewSubsystemLoggingHTTPTransport(subsystem string, t http.RoundTripper) *loggingHttpTransport { + return &loggingHttpTransport{subsystem, true, t} +} + const ( - // FieldHttpOperationType is the field key used by NewLoggingHTTPTransport when logging the type of operation via tflog. - FieldHttpOperationType = "__HTTP_OP_TYPE__" + // FieldHttpOperationType is the field key used by NewSubsystemLoggingHTTPTransport when logging the type of operation via tflog. + FieldHttpOperationType = "tf_http_op_type" - // OperationHttpRequest is the field value used by NewLoggingHTTPTransport when logging a request via tflog. - OperationHttpRequest = "HTTP_REQ" + // OperationHttpRequest is the field value used by NewSubsystemLoggingHTTPTransport when logging a request via tflog. + OperationHttpRequest = "request" - // FieldHttpRequestMethod is the field key used by NewLoggingHTTPTransport when logging a request method via tflog. - FieldHttpRequestMethod = "__HTTP_REQ_METHOD__" + // FieldHttpRequestMethod is the field key used by NewSubsystemLoggingHTTPTransport when logging a request method via tflog. + FieldHttpRequestMethod = "tf_http_req_method" - // FieldHttpRequestUri is the field key used by NewLoggingHTTPTransport when logging a request URI via tflog. - FieldHttpRequestUri = "__HTTP_REQ_URI__" + // FieldHttpRequestUri is the field key used by NewSubsystemLoggingHTTPTransport when logging a request URI via tflog. + FieldHttpRequestUri = "tf_http_req_uri" - // FieldHttpRequestVersion is the field key used by NewLoggingHTTPTransport when logging a request HTTP version via tflog. - FieldHttpRequestVersion = "__HTTP_REQ_VERSION__" + // FieldHttpRequestVersion is the field key used by NewSubsystemLoggingHTTPTransport when logging a request HTTP version via tflog. + FieldHttpRequestVersion = "tf_http_req_version" - // OperationHttpResponse is the field value used by NewLoggingHTTPTransport when logging a response via tflog. - OperationHttpResponse = "HTTP_RES" + // OperationHttpResponse is the field value used by NewSubsystemLoggingHTTPTransport when logging a response via tflog. + OperationHttpResponse = "response" - // FieldHttpResponseVersion is the field key used by NewLoggingHTTPTransport when logging a response HTTP version via tflog. - FieldHttpResponseVersion = "__HTTP_RES_VERSION__" + // FieldHttpResponseVersion is the field key used by NewSubsystemLoggingHTTPTransport when logging a response HTTP version via tflog. + FieldHttpResponseVersion = "tf_http_res_version" - // FieldHttpResponseStatusCode is the field key used by NewLoggingHTTPTransport when logging a response status code via tflog. - FieldHttpResponseStatusCode = "__HTTP_RES_STATUS__" + // FieldHttpResponseStatusCode is the field key used by NewSubsystemLoggingHTTPTransport when logging a response status code via tflog. + FieldHttpResponseStatusCode = "tf_http_res_status" - // FieldHttpResponseReason is the field key used by NewLoggingHTTPTransport when logging a response reason phrase via tflog. - FieldHttpResponseReason = "__HTTP_RES_REASON__" + // FieldHttpResponseReason is the field key used by NewSubsystemLoggingHTTPTransport when logging a response reason phrase via tflog. + FieldHttpResponseReason = "tf_http_res_reason" ) -// ConfigureReqCtxFunc is the type of function accepted by loggingHTTPTransport.WithConfigureRequestContext, -// to configure the request subsystem logging context before the actual logging. -type ConfigureReqCtxFunc func(ctx context.Context, subsystem string) context.Context - -type loggingHTTPTransport struct { - subsystem string - transport http.RoundTripper - configureReqCtx ConfigureReqCtxFunc +type loggingHttpTransport struct { + subsystem string + logToSubsystem bool + transport http.RoundTripper } -func (t *loggingHTTPTransport) RoundTrip(req *http.Request) (*http.Response, error) { - // Create a new subsystem logging context from the request context - ctx := tflog.NewSubsystem(req.Context(), t.subsystem) +func (t *loggingHttpTransport) RoundTrip(req *http.Request) (*http.Response, error) { + ctx := req.Context() - // If set, allow for further configuration of the new subsystem logging context - if t.configureReqCtx != nil { - ctx = t.configureReqCtx(ctx, t.subsystem) + // Grub the outgoing request bytes + reqDump, err := httputil.DumpRequestOut(req, true) + if err != nil { + t.Error(ctx, "HTTP Request introspection failed", map[string]interface{}{ + "error": fmt.Sprintf("%#v", err), + }) } - if IsDebugOrHigher() { - // Grub the outgoing request bytes - reqDump, err := httputil.DumpRequestOut(req, true) - if err != nil { - tflog.SubsystemError(ctx, t.subsystem, "HTTP Request introspection failed", map[string]interface{}{ - "error": fmt.Sprintf("%#v", err), - }) - } - - // Decompose the request bytes in a message (HTTP body) and fields (HTTP headers), then log it - msg, fields := decomposeRequestBytes(reqDump) - tflog.SubsystemDebug(ctx, t.subsystem, msg, fields) + // Decompose the request bytes in a message (HTTP body) and fields (HTTP headers), then log it + msg, fields, err := parseRequestBytes(reqDump) + if err != nil { + t.Error(ctx, "Failed to parse request bytes for logging", map[string]interface{}{ + "error": err, + }) + } else { + t.Debug(ctx, msg, fields) } // Invoke the wrapped RoundTrip now @@ -79,66 +119,44 @@ func (t *loggingHTTPTransport) RoundTrip(req *http.Request) (*http.Response, err return res, err } - if IsDebugOrHigher() { - // Grub the incoming response bytes - resDump, err := httputil.DumpResponse(res, true) - if err != nil { - tflog.SubsystemError(ctx, t.subsystem, "HTTP Response introspection error", map[string]interface{}{ - "error": fmt.Sprintf("%#v", err), - }) - } + // Grub the incoming response bytes + resDump, err := httputil.DumpResponse(res, true) + if err != nil { + t.Error(ctx, "HTTP Response introspection error", map[string]interface{}{ + "error": fmt.Sprintf("%#v", err), + }) + } - // Decompose the response bytes in a message (HTTP body) and fields (HTTP headers), then log it - msg, fields := decomposeResponseBytes(resDump) - tflog.SubsystemDebug(ctx, t.subsystem, msg, fields) + // Decompose the response bytes in a message (HTTP body) and fields (HTTP headers), then log it + msg, fields, err = parseResponseBytes(resDump) + if err != nil { + t.Error(ctx, "Failed to parse response bytes for logging", map[string]interface{}{ + "error": err, + }) + } else { + t.Debug(ctx, msg, fields) } return res, nil } -// NewLoggingHTTPTransport creates a wrapper around a *http.RoundTripper, -// designed to be used for the `Transport` field of http.Client. -// -// This logs each pair of HTTP request/response that it handles. -// The logging is done via `tflog`, that is part of the terraform-plugin-log -// library, included by this SDK. -// -// The request/response is logged via tflog.SubsystemDebug, and the `subsystem` -// is the one provide here. -// -// IMPORTANT: For logging to work, it's mandatory that each http.Request it handles -// is configured with the Context (i.e. `Request.WithContext(ctx)`) -// that the SDK passes into all resources/data-sources/provider entry-points -// (i.e. schema.Resource fields like `CreateContext`, `ReadContext`, etc.). -func NewLoggingHTTPTransport(subsystem string, t http.RoundTripper) *loggingHTTPTransport { - return &loggingHTTPTransport{subsystem, t, nil} +func (t *loggingHttpTransport) Debug(ctx context.Context, msg string, fields ...map[string]interface{}) { + if t.logToSubsystem { + tflog.SubsystemDebug(ctx, t.subsystem, msg, fields...) + } else { + tflog.Debug(ctx, msg, fields...) + } } -// WithConfigureRequestContext allows to optionally configure a callback ConfigureReqCtxFunc. -// This is used by the underlying structure to allow user to configure the -// http.Request context.Context, before the request is executed and the logger -// tflog.SubsystemDebug invoked. -// -// Log entries will be structured to contain: -// -// * the HTTP message first line, broken up into "fields" (see `FieldHttp*` constants) -// * the Headers, each as "fields" of the log -// * the Request/Response Body as "message" of the log -// -// For example, here is how to add an extra field to each log emitted here, -// as well as masking fields that have a specific key: -// -// t.WithConfigureRequestContext(func (ctx context.Context, subsystem string) context.Context { -// ctx = tflog.SetField(ctx, "additional_key", "additional_value") -// ctx = tflog.MaskFieldValuesWithFieldKeys(ctx, "secret", "token", "Authorization") -// }) -// -func (t *loggingHTTPTransport) WithConfigureRequestContext(callback ConfigureReqCtxFunc) *loggingHTTPTransport { - t.configureReqCtx = callback - return t +func (t *loggingHttpTransport) Error(ctx context.Context, msg string, fields ...map[string]interface{}) { + if t.logToSubsystem { + tflog.SubsystemError(ctx, t.subsystem, msg, fields...) + } else { + tflog.Error(ctx, msg, fields...) + } } -func decomposeRequestBytes(b []byte) (string, map[string]interface{}) { +func parseRequestBytes(b []byte) (string, map[string]interface{}, error) { parts := strings.Split(string(b), "\r\n") // We will end up with a number of fields equivalent to the number of parts + 1: @@ -163,14 +181,17 @@ func decomposeRequestBytes(b []byte) (string, map[string]interface{}) { } headerParts := strings.Split(parts[i], ": ") - fields[headerParts[0]] = headerParts[1] + if len(headerParts) != 2 { + return "", nil, fmt.Errorf("failed to parse header line %q", parts[i]) + } + fields[strings.TrimSpace(headerParts[0])] = strings.TrimSpace(headerParts[1]) } // HTTP Response Body: the last part is always the body (can be empty) - return parts[len(parts)-1], fields + return parts[len(parts)-1], fields, nil } -func decomposeResponseBytes(b []byte) (string, map[string]interface{}) { +func parseResponseBytes(b []byte) (string, map[string]interface{}, error) { parts := strings.Split(string(b), "\r\n") // We will end up with a number of fields equivalent to the number of parts: @@ -202,9 +223,12 @@ func decomposeResponseBytes(b []byte) (string, map[string]interface{}) { } headerParts := strings.Split(parts[i], ": ") - fields[headerParts[0]] = headerParts[1] + if len(headerParts) != 2 { + return "", nil, fmt.Errorf("failed to parse header line %q", parts[i]) + } + fields[strings.TrimSpace(headerParts[0])] = strings.TrimSpace(headerParts[1]) } // HTTP Response Body: the last part is always the body (can be empty) - return parts[len(parts)-1], fields + return parts[len(parts)-1], fields, nil } diff --git a/helper/logging/logging_http_transport_test.go b/helper/logging/logging_http_transport_test.go index 3f22757499..3cea435dc1 100644 --- a/helper/logging/logging_http_transport_test.go +++ b/helper/logging/logging_http_transport_test.go @@ -4,7 +4,6 @@ import ( "bytes" "context" "net/http" - "regexp" "testing" "time" @@ -15,9 +14,9 @@ import ( ) func TestNewLoggingHTTPTransport(t *testing.T) { - ctx, loggerOutput := setupRootLogger(t) + ctx, loggerOutput := setupRootLogger() - transport := logging.NewLoggingHTTPTransport("test", http.DefaultTransport) + transport := logging.NewLoggingHTTPTransport(http.DefaultTransport) client := http.Client{ Transport: transport, Timeout: 10 * time.Second, @@ -41,29 +40,29 @@ func TestNewLoggingHTTPTransport(t *testing.T) { reqEntry := entries[0] if diff := cmp.Diff(reqEntry, map[string]interface{}{ - "@level": "debug", - "@message": "", - "@module": "provider.test", - "__HTTP_OP_TYPE__": "HTTP_REQ", - "__HTTP_REQ_METHOD__": "GET", - "__HTTP_REQ_URI__": "/", - "__HTTP_REQ_VERSION__": "HTTP/1.1", - "Accept-Encoding": "gzip", - "Host": "www.terraform.io", - "User-Agent": "Go-http-client/1.1", + "@level": "debug", + "@message": "", + "@module": "provider", + "tf_http_op_type": "request", + "tf_http_req_method": "GET", + "tf_http_req_uri": "/", + "tf_http_req_version": "HTTP/1.1", + "Accept-Encoding": "gzip", + "Host": "www.terraform.io", + "User-Agent": "Go-http-client/1.1", }); diff != "" { t.Fatalf("unexpected difference for logging of the request:\n%s", diff) } resEntry := entries[1] expectedResEntryFields := map[string]interface{}{ - "@level": "debug", - "@module": "provider.test", - "Content-Type": "text/html", - "__HTTP_OP_TYPE__": "HTTP_RES", - "__HTTP_RES_STATUS__": float64(200), - "__HTTP_RES_VERSION__": "HTTP/2.0", - "__HTTP_RES_REASON__": "OK", + "@level": "debug", + "@module": "provider", + "Content-Type": "text/html", + "tf_http_op_type": "response", + "tf_http_res_status": float64(200), + "tf_http_res_version": "HTTP/2.0", + "tf_http_res_reason": "OK", } for ek, ev := range expectedResEntryFields { if resEntry[ek] != ev { @@ -72,15 +71,13 @@ func TestNewLoggingHTTPTransport(t *testing.T) { } } -func TestNewLoggingHTTPTransport_LogMasking(t *testing.T) { - ctx, loggerOutput := setupRootLogger(t) +func TestNewSubsystemLoggingHTTPTransport(t *testing.T) { + subsys := "test-subsystem" - transport := logging.NewLoggingHTTPTransport("test", http.DefaultTransport) - transport.WithConfigureRequestContext(func(ctx context.Context, subsystem string) context.Context { - ctx = tflog.SubsystemMaskFieldValuesWithFieldKeys(ctx, subsystem, "__HTTP_OP_TYPE__") - ctx = tflog.SubsystemMaskMessageRegexes(ctx, subsystem, regexp.MustCompile(`.*`)) - return ctx - }) + ctx, loggerOutput := setupRootLogger() + ctx = tflog.NewSubsystem(ctx, subsys) + + transport := logging.NewSubsystemLoggingHTTPTransport(subsys, http.DefaultTransport) client := http.Client{ Transport: transport, Timeout: 10 * time.Second, @@ -102,21 +99,83 @@ func TestNewLoggingHTTPTransport_LogMasking(t *testing.T) { t.Fatalf("unexpected amount of logs produced; expected 2, got %d", len(entries)) } - expectedMaskedEntryFields := map[string]interface{}{ - "__HTTP_OP_TYPE__": "***", - "@message": "***", + reqEntry := entries[0] + if diff := cmp.Diff(reqEntry, map[string]interface{}{ + "@level": "debug", + "@message": "", + "@module": "provider.test-subsystem", + "tf_http_op_type": "request", + "tf_http_req_method": "GET", + "tf_http_req_uri": "/", + "tf_http_req_version": "HTTP/1.1", + "Accept-Encoding": "gzip", + "Host": "www.terraform.io", + "User-Agent": "Go-http-client/1.1", + }); diff != "" { + t.Fatalf("unexpected difference for logging of the request:\n%s", diff) + } + + resEntry := entries[1] + expectedResEntryFields := map[string]interface{}{ + "@level": "debug", + "@module": "provider.test-subsystem", + "Content-Type": "text/html", + "tf_http_op_type": "response", + "tf_http_res_status": float64(200), + "tf_http_res_version": "HTTP/2.0", + "tf_http_res_reason": "OK", } - for _, entry := range entries { - for ek, ev := range expectedMaskedEntryFields { - if entry[ek] != "" && entry[ek] != ev { - t.Fatalf("Unexpected value for field %q; expected %q, got %q", ek, ev, entry[ek]) - } + for ek, ev := range expectedResEntryFields { + if resEntry[ek] != ev { + t.Fatalf("Unexpected value for field %q; expected %q, got %q", ek, ev, resEntry[ek]) } } } -func setupRootLogger(t *testing.T) (context.Context, *bytes.Buffer) { - t.Setenv(logging.EnvLog, "TRACE") +//func TestNewLoggingHTTPTransport_LogMasking(t *testing.T) { +// ctx, loggerOutput := setupRootLogger(t) +// +// transport := logging.NewSubsystemLoggingHTTPTransport("test", http.DefaultTransport) +// transport.WithConfigureRequestContext(func(ctx context.Context, subsystem string) context.Context { +// ctx = tflog.SubsystemMaskFieldValuesWithFieldKeys(ctx, subsystem, "tf_http_op_type") +// ctx = tflog.SubsystemMaskMessageRegexes(ctx, subsystem, regexp.MustCompile(`.*`)) +// return ctx +// }) +// client := http.Client{ +// Transport: transport, +// Timeout: 10 * time.Second, +// } +// +// req, _ := http.NewRequest("GET", "https://www.terraform.io", nil) +// res, err := client.Do(req.WithContext(ctx)) +// if err != nil { +// t.Fatalf("request failed: %v", err) +// } +// defer res.Body.Close() +// +// entries, err := tflogtest.MultilineJSONDecode(loggerOutput) +// if err != nil { +// t.Fatalf("log outtput parsing failed: %v", err) +// } +// +// if len(entries) != 2 { +// t.Fatalf("unexpected amount of logs produced; expected 2, got %d", len(entries)) +// } +// +// expectedMaskedEntryFields := map[string]interface{}{ +// "tf_http_op_type": "***", +// "@message": "***", +// } +// for _, entry := range entries { +// for ek, ev := range expectedMaskedEntryFields { +// if entry[ek] != "" && entry[ek] != ev { +// t.Fatalf("Unexpected value for field %q; expected %q, got %q", ek, ev, entry[ek]) +// } +// } +// } +//} + +func setupRootLogger() (context.Context, *bytes.Buffer) { var output bytes.Buffer return tflogtest.RootLogger(context.Background(), &output), &output } diff --git a/helper/logging/transport.go b/helper/logging/transport.go index 1d86838649..bda3813d96 100644 --- a/helper/logging/transport.go +++ b/helper/logging/transport.go @@ -45,11 +45,11 @@ func (t *transport) RoundTrip(req *http.Request) (*http.Response, error) { // designed to be used for the `Transport` field of http.Client. // // This logs each pair of HTTP request/response that it handles. -// The logging is done via standard `log`. +// The logging is done via Go standard library `log` package. // // Deprecated: This will log the content of every http request/response // at `[DEBUG]` level, without any filtering. Any sensitive information -// will appear as-is in your logs. Please use NewLoggingHTTPTransport instead. +// will appear as-is in your logs. Please use NewSubsystemLoggingHTTPTransport instead. func NewTransport(name string, t http.RoundTripper) *transport { return &transport{name, t} } From acd499746bc2e69f6d07a107c6d1f0c3410d8e01 Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Wed, 20 Jul 2022 14:04:47 +0100 Subject: [PATCH 06/16] Refactor to make use of textproto.ReadMIMEHeader() --- helper/logging/logging_http_transport.go | 200 +++++++++++++---------- 1 file changed, 113 insertions(+), 87 deletions(-) diff --git a/helper/logging/logging_http_transport.go b/helper/logging/logging_http_transport.go index 3be3ea8371..81c4820964 100644 --- a/helper/logging/logging_http_transport.go +++ b/helper/logging/logging_http_transport.go @@ -1,11 +1,12 @@ package logging import ( + "bufio" + "bytes" "context" - "fmt" "net/http" "net/http/httputil" - "strconv" + "net/textproto" "strings" "github.com/hashicorp/terraform-plugin-log/tflog" @@ -70,20 +71,20 @@ const ( // FieldHttpRequestUri is the field key used by NewSubsystemLoggingHTTPTransport when logging a request URI via tflog. FieldHttpRequestUri = "tf_http_req_uri" - // FieldHttpRequestVersion is the field key used by NewSubsystemLoggingHTTPTransport when logging a request HTTP version via tflog. - FieldHttpRequestVersion = "tf_http_req_version" + // FieldHttpRequestProtoVersion is the field key used by NewSubsystemLoggingHTTPTransport when logging a request HTTP version via tflog. + FieldHttpRequestProtoVersion = "tf_http_req_version" // OperationHttpResponse is the field value used by NewSubsystemLoggingHTTPTransport when logging a response via tflog. OperationHttpResponse = "response" - // FieldHttpResponseVersion is the field key used by NewSubsystemLoggingHTTPTransport when logging a response HTTP version via tflog. - FieldHttpResponseVersion = "tf_http_res_version" + // FieldHttpResponseProtoVersion is the field key used by NewSubsystemLoggingHTTPTransport when logging a response HTTP protocol version via tflog. + FieldHttpResponseProtoVersion = "tf_http_res_version" // FieldHttpResponseStatusCode is the field key used by NewSubsystemLoggingHTTPTransport when logging a response status code via tflog. - FieldHttpResponseStatusCode = "tf_http_res_status" + FieldHttpResponseStatusCode = "tf_http_res_status_code" - // FieldHttpResponseReason is the field key used by NewSubsystemLoggingHTTPTransport when logging a response reason phrase via tflog. - FieldHttpResponseReason = "tf_http_res_reason" + // FieldHttpResponseStatusReason is the field key used by NewSubsystemLoggingHTTPTransport when logging a response status reason phrase via tflog. + FieldHttpResponseStatusReason = "tf_http_res_status_reason" ) type loggingHttpTransport struct { @@ -95,16 +96,8 @@ type loggingHttpTransport struct { func (t *loggingHttpTransport) RoundTrip(req *http.Request) (*http.Response, error) { ctx := req.Context() - // Grub the outgoing request bytes - reqDump, err := httputil.DumpRequestOut(req, true) - if err != nil { - t.Error(ctx, "HTTP Request introspection failed", map[string]interface{}{ - "error": fmt.Sprintf("%#v", err), - }) - } - - // Decompose the request bytes in a message (HTTP body) and fields (HTTP headers), then log it - msg, fields, err := parseRequestBytes(reqDump) + //// Decompose the request bytes in a message (HTTP body) and fields (HTTP headers), then log it + msg, fields, err := decomposeRequestForLogging(req) if err != nil { t.Error(ctx, "Failed to parse request bytes for logging", map[string]interface{}{ "error": err, @@ -119,16 +112,8 @@ func (t *loggingHttpTransport) RoundTrip(req *http.Request) (*http.Response, err return res, err } - // Grub the incoming response bytes - resDump, err := httputil.DumpResponse(res, true) - if err != nil { - t.Error(ctx, "HTTP Response introspection error", map[string]interface{}{ - "error": fmt.Sprintf("%#v", err), - }) - } - // Decompose the response bytes in a message (HTTP body) and fields (HTTP headers), then log it - msg, fields, err = parseResponseBytes(resDump) + msg, fields, err = decomposeResponseForLogging(res) if err != nil { t.Error(ctx, "Failed to parse response bytes for logging", map[string]interface{}{ "error": err, @@ -156,79 +141,120 @@ func (t *loggingHttpTransport) Error(ctx context.Context, msg string, fields ... } } -func parseRequestBytes(b []byte) (string, map[string]interface{}, error) { - parts := strings.Split(string(b), "\r\n") - - // We will end up with a number of fields equivalent to the number of parts + 1: - // - the first will be split into 3 parts - // - the last 2 are "end of headers" and "body" - // - one extra for the operation type - fields := make(map[string]interface{}, len(parts)+1) +func decomposeRequestForLogging(req *http.Request) (string, map[string]interface{}, error) { + fields := make(map[string]interface{}, len(req.Header)+4) fields[FieldHttpOperationType] = OperationHttpRequest - // HTTP Request Line - reqLineParts := strings.Split(parts[0], " ") - fields[FieldHttpRequestMethod] = reqLineParts[0] - fields[FieldHttpRequestUri] = reqLineParts[1] - fields[FieldHttpRequestVersion] = reqLineParts[2] - - // HTTP Request Headers - var i int - for i = 1; i < len(parts)-2; i++ { - // Check if we reached the end of the headers - if parts[i] == "" { - break - } + fields[FieldHttpRequestMethod] = req.Method + fields[FieldHttpRequestUri] = req.URL.RequestURI() + fields[FieldHttpRequestProtoVersion] = req.Proto + + // Get the full body of the request, including headers appended by http.Transport: + // this is necessary because the http.Request at this stage doesn't contain + // all the headers that will be eventually sent. + // We rely on `httputil.DumpRequestOut` to obtain the actual bytes that will be sent out. + reqBytes, err := httputil.DumpRequestOut(req, true) + if err != nil { + return "", nil, err + } + + // Create a reader around the request full body + reqReader := textproto.NewReader(bufio.NewReader(bytes.NewReader(reqBytes))) + + // Ignore the first line: it contains non-header content + // that we have already captured above. + // Skipping this step, would cause the following call to `ReadMIMEHeader()` + // to fail as it cannot parse the first line. + _, _ = reqReader.ReadLine() - headerParts := strings.Split(parts[i], ": ") - if len(headerParts) != 2 { - return "", nil, fmt.Errorf("failed to parse header line %q", parts[i]) + // Read the request MIME-style headers + mimeHeader, err := reqReader.ReadMIMEHeader() + if err != nil { + return "", nil, err + } + + // Set the headers as fields to log + for k, v := range mimeHeader { + if len(v) == 1 { + fields[k] = v[0] + } else { + fields[k] = v } - fields[strings.TrimSpace(headerParts[0])] = strings.TrimSpace(headerParts[1]) } - // HTTP Response Body: the last part is always the body (can be empty) - return parts[len(parts)-1], fields, nil + // Read the rest of the body content, + // into what will be the log message + var msgBuilder strings.Builder + for { + line, err := reqReader.ReadContinuedLine() + if err != nil { + if err.Error() == "EOF" { + break + } else { + return "", nil, err + } + } + msgBuilder.WriteString(line) + } + return msgBuilder.String(), fields, nil } -func parseResponseBytes(b []byte) (string, map[string]interface{}, error) { - parts := strings.Split(string(b), "\r\n") - - // We will end up with a number of fields equivalent to the number of parts: - // - the first will be split into 3 parts - // - the last 2 are "end of headers" and "body" - // - one extra for the operation type - fields := make(map[string]interface{}, len(parts)) +func decomposeResponseForLogging(res *http.Response) (string, map[string]interface{}, error) { + fields := make(map[string]interface{}, len(res.Header)+4) fields[FieldHttpOperationType] = OperationHttpResponse - // HTTP Message Status Line - reqLineParts := strings.Split(parts[0], " ") - fields[FieldHttpResponseVersion] = reqLineParts[0] - // NOTE: Unlikely, but if we can't parse the status code, - // we set its field value to string - statusCode, err := strconv.Atoi(reqLineParts[1]) + fields[FieldHttpResponseProtoVersion] = res.Proto + fields[FieldHttpResponseStatusCode] = res.StatusCode + fields[FieldHttpResponseStatusReason] = res.Status + + // Get the full body of the response: + // this is necessary because the http.Response `Body` is a ReadCloser, + // so the only way to read it's content without affecting the final consumer + // of this response, is to rely on `httputil.DumpRequestOut`, + // that handles duplicating the underlying buffers and make the extraction + // of these bytes transparent. + resBytes, err := httputil.DumpResponse(res, true) if err != nil { - fields[FieldHttpResponseStatusCode] = reqLineParts[1] - } else { - fields[FieldHttpResponseStatusCode] = statusCode + return "", nil, err } - fields[FieldHttpResponseReason] = reqLineParts[2] - - // HTTP Response Headers - var i int - for i = 1; i < len(parts)-2; i++ { - // Check if we reached the end of the headers - if parts[i] == "" { - break - } - headerParts := strings.Split(parts[i], ": ") - if len(headerParts) != 2 { - return "", nil, fmt.Errorf("failed to parse header line %q", parts[i]) + // Create a reader around the response full body + resReader := textproto.NewReader(bufio.NewReader(bytes.NewReader(resBytes))) + + // Ignore the first line: it contains non-header content + // that we have already captured above. + // Skipping this step, would cause the following call to `ReadMIMEHeader()` + // to fail as it cannot parse the first line. + _, _ = resReader.ReadLine() + + // Read the response MIME-style headers + mimeHeader, err := resReader.ReadMIMEHeader() + if err != nil { + return "", nil, err + } + + // Set the headers as fields to log + for k, v := range mimeHeader { + if len(v) == 1 { + fields[k] = v[0] + } else { + fields[k] = v } - fields[strings.TrimSpace(headerParts[0])] = strings.TrimSpace(headerParts[1]) } - // HTTP Response Body: the last part is always the body (can be empty) - return parts[len(parts)-1], fields, nil + // Read the rest of the body content, + // into what will be the log message + var msgBuilder strings.Builder + for { + line, err := resReader.ReadContinuedLine() + if err != nil { + if err.Error() == "EOF" { + break + } else { + return "", nil, err + } + } + msgBuilder.WriteString(line) + } + return msgBuilder.String(), fields, nil } From a24de605da493a3bbd600590bc204c41cf51d3b8 Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Wed, 20 Jul 2022 14:05:18 +0100 Subject: [PATCH 07/16] Added test coverage to confirm request-body is captured, as well as log masking and filtering --- helper/logging/logging_http_transport_test.go | 172 ++++++++++++------ 1 file changed, 112 insertions(+), 60 deletions(-) diff --git a/helper/logging/logging_http_transport_test.go b/helper/logging/logging_http_transport_test.go index 3cea435dc1..b48781da15 100644 --- a/helper/logging/logging_http_transport_test.go +++ b/helper/logging/logging_http_transport_test.go @@ -4,6 +4,7 @@ import ( "bytes" "context" "net/http" + "regexp" "testing" "time" @@ -22,7 +23,10 @@ func TestNewLoggingHTTPTransport(t *testing.T) { Timeout: 10 * time.Second, } - req, _ := http.NewRequest("GET", "https://www.terraform.io", nil) + reqBody := `An example + multiline + request body` + req, _ := http.NewRequest("GET", "https://www.terraform.io", bytes.NewBufferString(reqBody)) res, err := client.Do(req.WithContext(ctx)) if err != nil { t.Fatalf("request failed: %v", err) @@ -41,7 +45,7 @@ func TestNewLoggingHTTPTransport(t *testing.T) { reqEntry := entries[0] if diff := cmp.Diff(reqEntry, map[string]interface{}{ "@level": "debug", - "@message": "", + "@message": "An example multiline request body", "@module": "provider", "tf_http_op_type": "request", "tf_http_req_method": "GET", @@ -50,25 +54,35 @@ func TestNewLoggingHTTPTransport(t *testing.T) { "Accept-Encoding": "gzip", "Host": "www.terraform.io", "User-Agent": "Go-http-client/1.1", + "Content-Length": "37", }); diff != "" { t.Fatalf("unexpected difference for logging of the request:\n%s", diff) } resEntry := entries[1] expectedResEntryFields := map[string]interface{}{ - "@level": "debug", - "@module": "provider", - "Content-Type": "text/html", - "tf_http_op_type": "response", - "tf_http_res_status": float64(200), - "tf_http_res_version": "HTTP/2.0", - "tf_http_res_reason": "OK", + "@level": "debug", + "@module": "provider", + "Content-Type": "text/html", + "tf_http_op_type": "response", + "tf_http_res_status_code": float64(200), + "tf_http_res_version": "HTTP/2.0", + "tf_http_res_status_reason": "200 OK", } for ek, ev := range expectedResEntryFields { if resEntry[ek] != ev { t.Fatalf("Unexpected value for field %q; expected %q, got %q", ek, ev, resEntry[ek]) } } + + expectedNonEmptyEntryFields := []string{ + "@message", "Etag", "Date", "X-Frame-Options", "Server", + } + for _, ek := range expectedNonEmptyEntryFields { + if ev, ok := resEntry[ek]; !ok || ev == "" { + t.Fatalf("Expected field %q to contain a non-null value", ek) + } + } } func TestNewSubsystemLoggingHTTPTransport(t *testing.T) { @@ -83,7 +97,10 @@ func TestNewSubsystemLoggingHTTPTransport(t *testing.T) { Timeout: 10 * time.Second, } - req, _ := http.NewRequest("GET", "https://www.terraform.io", nil) + reqBody := `An example + multiline + request body` + req, _ := http.NewRequest("GET", "https://www.terraform.io", bytes.NewBufferString(reqBody)) res, err := client.Do(req.WithContext(ctx)) if err != nil { t.Fatalf("request failed: %v", err) @@ -102,7 +119,7 @@ func TestNewSubsystemLoggingHTTPTransport(t *testing.T) { reqEntry := entries[0] if diff := cmp.Diff(reqEntry, map[string]interface{}{ "@level": "debug", - "@message": "", + "@message": "An example multiline request body", "@module": "provider.test-subsystem", "tf_http_op_type": "request", "tf_http_req_method": "GET", @@ -111,69 +128,104 @@ func TestNewSubsystemLoggingHTTPTransport(t *testing.T) { "Accept-Encoding": "gzip", "Host": "www.terraform.io", "User-Agent": "Go-http-client/1.1", + "Content-Length": "37", }); diff != "" { t.Fatalf("unexpected difference for logging of the request:\n%s", diff) } resEntry := entries[1] expectedResEntryFields := map[string]interface{}{ - "@level": "debug", - "@module": "provider.test-subsystem", - "Content-Type": "text/html", - "tf_http_op_type": "response", - "tf_http_res_status": float64(200), - "tf_http_res_version": "HTTP/2.0", - "tf_http_res_reason": "OK", + "@level": "debug", + "@module": "provider.test-subsystem", + "Content-Type": "text/html", + "tf_http_op_type": "response", + "tf_http_res_status_code": float64(200), + "tf_http_res_version": "HTTP/2.0", + "tf_http_res_status_reason": "200 OK", } for ek, ev := range expectedResEntryFields { if resEntry[ek] != ev { t.Fatalf("Unexpected value for field %q; expected %q, got %q", ek, ev, resEntry[ek]) } } + + expectedNonEmptyEntryFields := []string{ + "@message", "Etag", "Date", "X-Frame-Options", "Server", + } + for _, ek := range expectedNonEmptyEntryFields { + if ev, ok := resEntry[ek]; !ok || ev == "" { + t.Fatalf("Expected field %q to contain a non-null value", ek) + } + } } -//func TestNewLoggingHTTPTransport_LogMasking(t *testing.T) { -// ctx, loggerOutput := setupRootLogger(t) -// -// transport := logging.NewSubsystemLoggingHTTPTransport("test", http.DefaultTransport) -// transport.WithConfigureRequestContext(func(ctx context.Context, subsystem string) context.Context { -// ctx = tflog.SubsystemMaskFieldValuesWithFieldKeys(ctx, subsystem, "tf_http_op_type") -// ctx = tflog.SubsystemMaskMessageRegexes(ctx, subsystem, regexp.MustCompile(`.*`)) -// return ctx -// }) -// client := http.Client{ -// Transport: transport, -// Timeout: 10 * time.Second, -// } -// -// req, _ := http.NewRequest("GET", "https://www.terraform.io", nil) -// res, err := client.Do(req.WithContext(ctx)) -// if err != nil { -// t.Fatalf("request failed: %v", err) -// } -// defer res.Body.Close() -// -// entries, err := tflogtest.MultilineJSONDecode(loggerOutput) -// if err != nil { -// t.Fatalf("log outtput parsing failed: %v", err) -// } -// -// if len(entries) != 2 { -// t.Fatalf("unexpected amount of logs produced; expected 2, got %d", len(entries)) -// } -// -// expectedMaskedEntryFields := map[string]interface{}{ -// "tf_http_op_type": "***", -// "@message": "***", -// } -// for _, entry := range entries { -// for ek, ev := range expectedMaskedEntryFields { -// if entry[ek] != "" && entry[ek] != ev { -// t.Fatalf("Unexpected value for field %q; expected %q, got %q", ek, ev, entry[ek]) -// } -// } -// } -//} +func TestNewLoggingHTTPTransport_LogMasking(t *testing.T) { + ctx, loggerOutput := setupRootLogger() + ctx = tflog.MaskFieldValuesWithFieldKeys(ctx, "tf_http_op_type") + ctx = tflog.MaskMessageRegexes(ctx, regexp.MustCompile(`.*`)) + + transport := logging.NewLoggingHTTPTransport(http.DefaultTransport) + client := http.Client{ + Transport: transport, + Timeout: 10 * time.Second, + } + + req, _ := http.NewRequest("GET", "https://www.terraform.io", nil) + res, err := client.Do(req.WithContext(ctx)) + if err != nil { + t.Fatalf("request failed: %v", err) + } + defer res.Body.Close() + + entries, err := tflogtest.MultilineJSONDecode(loggerOutput) + if err != nil { + t.Fatalf("log outtput parsing failed: %v", err) + } + + if len(entries) != 2 { + t.Fatalf("unexpected amount of logs produced; expected 2, got %d", len(entries)) + } + + expectedMaskedEntryFields := map[string]interface{}{ + "tf_http_op_type": "***", + "@message": "***", + } + for _, entry := range entries { + for ek, ev := range expectedMaskedEntryFields { + if entry[ek] != "" && entry[ek] != ev { + t.Fatalf("Unexpected value for field %q; expected %q, got %q", ek, ev, entry[ek]) + } + } + } +} + +func TestNewLoggingHTTPTransport_LogOmitting(t *testing.T) { + ctx, loggerOutput := setupRootLogger() + ctx = tflog.OmitLogWithMessageRegexes(ctx, regexp.MustCompile("(?i)")) + ctx = tflog.OmitLogWithFieldKeys(ctx, "tf_http_req_method") + + transport := logging.NewLoggingHTTPTransport(http.DefaultTransport) + client := http.Client{ + Transport: transport, + Timeout: 10 * time.Second, + } + + req, _ := http.NewRequest("GET", "https://www.terraform.io", nil) + res, err := client.Do(req.WithContext(ctx)) + if err != nil { + t.Fatalf("request failed: %v", err) + } + defer res.Body.Close() + + entries, err := tflogtest.MultilineJSONDecode(loggerOutput) + if err != nil { + t.Fatalf("log outtput parsing failed: %v", err) + } + + if len(entries) != 0 { + t.Fatalf("unexpected amount of logs produced; expected 0 (because they should have been omitted), got %d", len(entries)) + } +} func setupRootLogger() (context.Context, *bytes.Buffer) { var output bytes.Buffer From e3919f72eb0cc1ef8b6d53d9145c143c51bf24b3 Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Wed, 20 Jul 2022 14:26:03 +0100 Subject: [PATCH 08/16] Further simplified code, to reduce repetition further --- helper/logging/logging_http_transport.go | 81 ++++++++++-------------- 1 file changed, 34 insertions(+), 47 deletions(-) diff --git a/helper/logging/logging_http_transport.go b/helper/logging/logging_http_transport.go index 81c4820964..92e5745811 100644 --- a/helper/logging/logging_http_transport.go +++ b/helper/logging/logging_http_transport.go @@ -4,6 +4,8 @@ import ( "bufio" "bytes" "context" + "errors" + "io" "net/http" "net/http/httputil" "net/textproto" @@ -161,42 +163,14 @@ func decomposeRequestForLogging(req *http.Request) (string, map[string]interface // Create a reader around the request full body reqReader := textproto.NewReader(bufio.NewReader(bytes.NewReader(reqBytes))) - // Ignore the first line: it contains non-header content - // that we have already captured above. - // Skipping this step, would cause the following call to `ReadMIMEHeader()` - // to fail as it cannot parse the first line. - _, _ = reqReader.ReadLine() - - // Read the request MIME-style headers - mimeHeader, err := reqReader.ReadMIMEHeader() + err = readHeadersIntoFields(reqReader, fields) if err != nil { return "", nil, err } - // Set the headers as fields to log - for k, v := range mimeHeader { - if len(v) == 1 { - fields[k] = v[0] - } else { - fields[k] = v - } - } - // Read the rest of the body content, // into what will be the log message - var msgBuilder strings.Builder - for { - line, err := reqReader.ReadContinuedLine() - if err != nil { - if err.Error() == "EOF" { - break - } else { - return "", nil, err - } - } - msgBuilder.WriteString(line) - } - return msgBuilder.String(), fields, nil + return readRestToString(reqReader), fields, nil } func decomposeResponseForLogging(res *http.Response) (string, map[string]interface{}, error) { @@ -221,16 +195,30 @@ func decomposeResponseForLogging(res *http.Response) (string, map[string]interfa // Create a reader around the response full body resReader := textproto.NewReader(bufio.NewReader(bytes.NewReader(resBytes))) + err = readHeadersIntoFields(resReader, fields) + if err != nil { + return "", nil, err + } + + // Read the rest of the body content, + // into what will be the log message + return readRestToString(resReader), fields, nil +} + +func readHeadersIntoFields(reader *textproto.Reader, fields map[string]interface{}) error { // Ignore the first line: it contains non-header content - // that we have already captured above. + // that we have already captured. // Skipping this step, would cause the following call to `ReadMIMEHeader()` // to fail as it cannot parse the first line. - _, _ = resReader.ReadLine() + _, err := reader.ReadLine() + if err != nil { + return err + } - // Read the response MIME-style headers - mimeHeader, err := resReader.ReadMIMEHeader() + // Read the MIME-style headers + mimeHeader, err := reader.ReadMIMEHeader() if err != nil { - return "", nil, err + return err } // Set the headers as fields to log @@ -242,19 +230,18 @@ func decomposeResponseForLogging(res *http.Response) (string, map[string]interfa } } - // Read the rest of the body content, - // into what will be the log message - var msgBuilder strings.Builder + return nil +} + +func readRestToString(reader *textproto.Reader) string { + var builder strings.Builder for { - line, err := resReader.ReadContinuedLine() - if err != nil { - if err.Error() == "EOF" { - break - } else { - return "", nil, err - } + line, err := reader.ReadContinuedLine() + if errors.Is(err, io.EOF) { + break } - msgBuilder.WriteString(line) + builder.WriteString(line) } - return msgBuilder.String(), fields, nil + + return builder.String() } From 67b58fe00122ee2a03530700cf38c3f231c38cb6 Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Thu, 21 Jul 2022 17:33:26 +0100 Subject: [PATCH 09/16] Adding CHANGELOG entry --- .changelog/1006.txt | 7 +++++++ 1 file changed, 7 insertions(+) create mode 100644 .changelog/1006.txt diff --git a/.changelog/1006.txt b/.changelog/1006.txt new file mode 100644 index 0000000000..9dda15146a --- /dev/null +++ b/.changelog/1006.txt @@ -0,0 +1,7 @@ +```release-note:feature +helper/logging: New `NewLoggingHTTPTransport()` and `NewSubsystemLoggingHTTPTransport()` functions, providing `http.RoundTripper` Transport implementations that log request/response using [terraform-plugin-log](https://pkg.go.dev/github.com/hashicorp/terraform-plugin-log) +``` + +```release-note:note +helper/logging: Existing `NewTransport()` is now deprecated in favour of using the new `NewLoggingHTTPTransport()` or `NewSubsystemLoggingHTTPTransport()` +``` From 69421fb312a94e5c0796e8804466fde24570f9c9 Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Thu, 21 Jul 2022 17:33:38 +0100 Subject: [PATCH 10/16] PR review --- helper/logging/logging_http_transport.go | 53 +++++++++++++----------- 1 file changed, 29 insertions(+), 24 deletions(-) diff --git a/helper/logging/logging_http_transport.go b/helper/logging/logging_http_transport.go index 92e5745811..625ac748d6 100644 --- a/helper/logging/logging_http_transport.go +++ b/helper/logging/logging_http_transport.go @@ -34,7 +34,7 @@ import ( // logging behaviour via the above-mentioned context: please see // https://www.terraform.io/plugin/log/writing. func NewLoggingHTTPTransport(t http.RoundTripper) *loggingHttpTransport { - return &loggingHttpTransport{"", false, t} + return &loggingHttpTransport{"", t} } // NewSubsystemLoggingHTTPTransport creates a wrapper around an *http.RoundTripper, @@ -56,8 +56,11 @@ func NewLoggingHTTPTransport(t http.RoundTripper) *loggingHttpTransport { // This also gives the developer the flexibility to further configure the // logging behaviour via the above-mentioned context: please see // https://www.terraform.io/plugin/log/writing. +// +// Please note: setting `subsystem` to an empty string it's equivalent to +// using NewLoggingHTTPTransport. func NewSubsystemLoggingHTTPTransport(subsystem string, t http.RoundTripper) *loggingHttpTransport { - return &loggingHttpTransport{subsystem, true, t} + return &loggingHttpTransport{subsystem, t} } const ( @@ -90,15 +93,14 @@ const ( ) type loggingHttpTransport struct { - subsystem string - logToSubsystem bool - transport http.RoundTripper + subsystem string + transport http.RoundTripper } func (t *loggingHttpTransport) RoundTrip(req *http.Request) (*http.Response, error) { ctx := req.Context() - //// Decompose the request bytes in a message (HTTP body) and fields (HTTP headers), then log it + // Decompose the request bytes in a message (HTTP body) and fields (HTTP headers), then log it msg, fields, err := decomposeRequestForLogging(req) if err != nil { t.Error(ctx, "Failed to parse request bytes for logging", map[string]interface{}{ @@ -128,7 +130,7 @@ func (t *loggingHttpTransport) RoundTrip(req *http.Request) (*http.Response, err } func (t *loggingHttpTransport) Debug(ctx context.Context, msg string, fields ...map[string]interface{}) { - if t.logToSubsystem { + if t.subsystem != "" { tflog.SubsystemDebug(ctx, t.subsystem, msg, fields...) } else { tflog.Debug(ctx, msg, fields...) @@ -136,7 +138,7 @@ func (t *loggingHttpTransport) Debug(ctx context.Context, msg string, fields ... } func (t *loggingHttpTransport) Error(ctx context.Context, msg string, fields ...map[string]interface{}) { - if t.logToSubsystem { + if t.subsystem != "" { tflog.SubsystemError(ctx, t.subsystem, msg, fields...) } else { tflog.Error(ctx, msg, fields...) @@ -181,28 +183,31 @@ func decomposeResponseForLogging(res *http.Response) (string, map[string]interfa fields[FieldHttpResponseStatusCode] = res.StatusCode fields[FieldHttpResponseStatusReason] = res.Status - // Get the full body of the response: - // this is necessary because the http.Response `Body` is a ReadCloser, - // so the only way to read it's content without affecting the final consumer - // of this response, is to rely on `httputil.DumpRequestOut`, - // that handles duplicating the underlying buffers and make the extraction - // of these bytes transparent. - resBytes, err := httputil.DumpResponse(res, true) - if err != nil { - return "", nil, err + // Set the headers as fields to log + for k, v := range res.Header { + if len(v) == 1 { + fields[k] = v[0] + } else { + fields[k] = v + } } - // Create a reader around the response full body - resReader := textproto.NewReader(bufio.NewReader(bytes.NewReader(resBytes))) - - err = readHeadersIntoFields(resReader, fields) + // Read the whole response body + resBody, err := io.ReadAll(res.Body) if err != nil { return "", nil, err } - // Read the rest of the body content, - // into what will be the log message - return readRestToString(resReader), fields, nil + // Make a copy of the response body bytes, to be returned as log message + msgBytes := make([]byte, len(resBody)) + copy(msgBytes, resBody) + + // Wrap the bytes from the response body, back into an io.ReadCloser, + // to respect the interface of http.Response, as expected by users of the + // http.Client + res.Body = io.NopCloser(bytes.NewBuffer(resBody)) + + return string(resBody), fields, nil } func readHeadersIntoFields(reader *textproto.Reader, fields map[string]interface{}) error { From 5583b6cf00e7302c464b010172af11a6b18b656a Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Mon, 25 Jul 2022 09:23:39 +0100 Subject: [PATCH 11/16] Temporarily use terraform-plugin-log candidate for v0.7.0 release --- go.mod | 2 +- go.sum | 3 ++- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/go.mod b/go.mod index 06c489ab0e..250e24d6c2 100644 --- a/go.mod +++ b/go.mod @@ -19,7 +19,7 @@ require ( github.com/hashicorp/terraform-exec v0.17.2 github.com/hashicorp/terraform-json v0.14.0 github.com/hashicorp/terraform-plugin-go v0.12.0 - github.com/hashicorp/terraform-plugin-log v0.6.0 + github.com/hashicorp/terraform-plugin-log v0.6.1-0.20220724091104-b3ff5d724111 github.com/mitchellh/copystructure v1.2.0 github.com/mitchellh/go-testing-interface v1.14.1 github.com/mitchellh/mapstructure v1.5.0 diff --git a/go.sum b/go.sum index fe6c0759bc..9f57bcdc19 100644 --- a/go.sum +++ b/go.sum @@ -127,8 +127,9 @@ github.com/hashicorp/terraform-json v0.14.0 h1:sh9iZ1Y8IFJLx+xQiKHGud6/TSUCM0N8e github.com/hashicorp/terraform-json v0.14.0/go.mod h1:5A9HIWPkk4e5aeeXIBbkcOvaZbIYnAIkEyqP2pNSckM= github.com/hashicorp/terraform-plugin-go v0.12.0 h1:6wW9mT1dSs0Xq4LR6HXj1heQ5ovr5GxXNJwkErZzpJw= github.com/hashicorp/terraform-plugin-go v0.12.0/go.mod h1:kwhmaWHNDvT1B3QiSJdAtrB/D4RaKSY/v3r2BuoWK4M= -github.com/hashicorp/terraform-plugin-log v0.6.0 h1:/Vq78uSIdUSZ3iqDc9PESKtwt8YqNKN6u+khD+lLjuw= github.com/hashicorp/terraform-plugin-log v0.6.0/go.mod h1:p4R1jWBXRTvL4odmEkFfDdhUjHf9zcs/BCoNHAc7IK4= +github.com/hashicorp/terraform-plugin-log v0.6.1-0.20220724091104-b3ff5d724111 h1:m0u1i1IWGJuhfeWk7pBETkO1lV1c7bFPTUoMgkVuOKM= +github.com/hashicorp/terraform-plugin-log v0.6.1-0.20220724091104-b3ff5d724111/go.mod h1:p4R1jWBXRTvL4odmEkFfDdhUjHf9zcs/BCoNHAc7IK4= github.com/hashicorp/terraform-registry-address v0.0.0-20220623143253-7d51757b572c h1:D8aRO6+mTqHfLsK/BC3j5OAoogv1WLRWzY1AaTo3rBg= github.com/hashicorp/terraform-registry-address v0.0.0-20220623143253-7d51757b572c/go.mod h1:Wn3Na71knbXc1G8Lh+yu/dQWWJeFQEpDeJMtWMtlmNI= github.com/hashicorp/terraform-svchost v0.0.0-20200729002733-f050f53b9734 h1:HKLsbzeOsfXmKNpr3GiT18XAblV0BjCbzL8KQAMZGa0= From cb6d57725e3fe82f5a5dc93f33c4aef8e6fc64ae Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Mon, 25 Jul 2022 09:24:18 +0100 Subject: [PATCH 12/16] Place the req/res body in a dedicated field, and keep the log message short (i.e. "Sending HTTP Request / Received HTTP Response") --- helper/logging/logging_http_transport.go | 73 +++++++++++++------ helper/logging/logging_http_transport_test.go | 35 ++++++--- 2 files changed, 74 insertions(+), 34 deletions(-) diff --git a/helper/logging/logging_http_transport.go b/helper/logging/logging_http_transport.go index 625ac748d6..56086af5a7 100644 --- a/helper/logging/logging_http_transport.go +++ b/helper/logging/logging_http_transport.go @@ -64,32 +64,57 @@ func NewSubsystemLoggingHTTPTransport(subsystem string, t http.RoundTripper) *lo } const ( - // FieldHttpOperationType is the field key used by NewSubsystemLoggingHTTPTransport when logging the type of operation via tflog. + // FieldHttpOperationType is the field key used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging the type of HTTP operation via tflog. FieldHttpOperationType = "tf_http_op_type" - // OperationHttpRequest is the field value used by NewSubsystemLoggingHTTPTransport when logging a request via tflog. + // OperationHttpRequest is the field value used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP request via tflog. OperationHttpRequest = "request" - // FieldHttpRequestMethod is the field key used by NewSubsystemLoggingHTTPTransport when logging a request method via tflog. + // OperationHttpResponse is the field value used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP response via tflog. + OperationHttpResponse = "response" + + // FieldHttpRequestMethod is the field key used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP request method via tflog. FieldHttpRequestMethod = "tf_http_req_method" - // FieldHttpRequestUri is the field key used by NewSubsystemLoggingHTTPTransport when logging a request URI via tflog. + // FieldHttpRequestUri is the field key used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP request URI via tflog. FieldHttpRequestUri = "tf_http_req_uri" - // FieldHttpRequestProtoVersion is the field key used by NewSubsystemLoggingHTTPTransport when logging a request HTTP version via tflog. + // FieldHttpRequestProtoVersion is the field key used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP request HTTP version via tflog. FieldHttpRequestProtoVersion = "tf_http_req_version" - // OperationHttpResponse is the field value used by NewSubsystemLoggingHTTPTransport when logging a response via tflog. - OperationHttpResponse = "response" + // FieldHttpRequestBody is the field key used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP request body via tflog. + FieldHttpRequestBody = "tf_http_req_body" - // FieldHttpResponseProtoVersion is the field key used by NewSubsystemLoggingHTTPTransport when logging a response HTTP protocol version via tflog. + // FieldHttpResponseProtoVersion is the field key used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP response protocol version via tflog. FieldHttpResponseProtoVersion = "tf_http_res_version" - // FieldHttpResponseStatusCode is the field key used by NewSubsystemLoggingHTTPTransport when logging a response status code via tflog. + // FieldHttpResponseStatusCode is the field key used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP response status code via tflog. FieldHttpResponseStatusCode = "tf_http_res_status_code" - // FieldHttpResponseStatusReason is the field key used by NewSubsystemLoggingHTTPTransport when logging a response status reason phrase via tflog. + // FieldHttpResponseStatusReason is the field key used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP response status reason phrase via tflog. FieldHttpResponseStatusReason = "tf_http_res_status_reason" + + // FieldHttpResponseBody is the field key used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP response body via tflog. + FieldHttpResponseBody = "tf_http_res_body" + + // MessageHttpRequest is the message used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP request via tflog. + MessageHttpRequest = "Sending HTTP Request" + + // MessageHttpResponse is the message used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP response via tflog. + MessageHttpResponse = "Received HTTP Response" ) type loggingHttpTransport struct { @@ -101,13 +126,13 @@ func (t *loggingHttpTransport) RoundTrip(req *http.Request) (*http.Response, err ctx := req.Context() // Decompose the request bytes in a message (HTTP body) and fields (HTTP headers), then log it - msg, fields, err := decomposeRequestForLogging(req) + fields, err := decomposeRequestForLogging(req) if err != nil { t.Error(ctx, "Failed to parse request bytes for logging", map[string]interface{}{ "error": err, }) } else { - t.Debug(ctx, msg, fields) + t.Debug(ctx, MessageHttpRequest, fields) } // Invoke the wrapped RoundTrip now @@ -117,13 +142,13 @@ func (t *loggingHttpTransport) RoundTrip(req *http.Request) (*http.Response, err } // Decompose the response bytes in a message (HTTP body) and fields (HTTP headers), then log it - msg, fields, err = decomposeResponseForLogging(res) + fields, err = decomposeResponseForLogging(res) if err != nil { t.Error(ctx, "Failed to parse response bytes for logging", map[string]interface{}{ "error": err, }) } else { - t.Debug(ctx, msg, fields) + t.Debug(ctx, MessageHttpResponse, fields) } return res, nil @@ -145,7 +170,7 @@ func (t *loggingHttpTransport) Error(ctx context.Context, msg string, fields ... } } -func decomposeRequestForLogging(req *http.Request) (string, map[string]interface{}, error) { +func decomposeRequestForLogging(req *http.Request) (map[string]interface{}, error) { fields := make(map[string]interface{}, len(req.Header)+4) fields[FieldHttpOperationType] = OperationHttpRequest @@ -159,7 +184,7 @@ func decomposeRequestForLogging(req *http.Request) (string, map[string]interface // We rely on `httputil.DumpRequestOut` to obtain the actual bytes that will be sent out. reqBytes, err := httputil.DumpRequestOut(req, true) if err != nil { - return "", nil, err + return nil, err } // Create a reader around the request full body @@ -167,15 +192,15 @@ func decomposeRequestForLogging(req *http.Request) (string, map[string]interface err = readHeadersIntoFields(reqReader, fields) if err != nil { - return "", nil, err + return nil, err } - // Read the rest of the body content, - // into what will be the log message - return readRestToString(reqReader), fields, nil + // Read the rest of the body content + fields[FieldHttpRequestBody] = readRestToString(reqReader) + return fields, nil } -func decomposeResponseForLogging(res *http.Response) (string, map[string]interface{}, error) { +func decomposeResponseForLogging(res *http.Response) (map[string]interface{}, error) { fields := make(map[string]interface{}, len(res.Header)+4) fields[FieldHttpOperationType] = OperationHttpResponse @@ -195,7 +220,7 @@ func decomposeResponseForLogging(res *http.Response) (string, map[string]interfa // Read the whole response body resBody, err := io.ReadAll(res.Body) if err != nil { - return "", nil, err + return nil, err } // Make a copy of the response body bytes, to be returned as log message @@ -207,7 +232,9 @@ func decomposeResponseForLogging(res *http.Response) (string, map[string]interfa // http.Client res.Body = io.NopCloser(bytes.NewBuffer(resBody)) - return string(resBody), fields, nil + fields[FieldHttpResponseBody] = string(resBody) + + return fields, nil } func readHeadersIntoFields(reader *textproto.Reader, fields map[string]interface{}) error { diff --git a/helper/logging/logging_http_transport_test.go b/helper/logging/logging_http_transport_test.go index b48781da15..b214ad6588 100644 --- a/helper/logging/logging_http_transport_test.go +++ b/helper/logging/logging_http_transport_test.go @@ -45,12 +45,13 @@ func TestNewLoggingHTTPTransport(t *testing.T) { reqEntry := entries[0] if diff := cmp.Diff(reqEntry, map[string]interface{}{ "@level": "debug", - "@message": "An example multiline request body", + "@message": "Sending HTTP Request", "@module": "provider", "tf_http_op_type": "request", "tf_http_req_method": "GET", "tf_http_req_uri": "/", "tf_http_req_version": "HTTP/1.1", + "tf_http_req_body": "An example multiline request body", "Accept-Encoding": "gzip", "Host": "www.terraform.io", "User-Agent": "Go-http-client/1.1", @@ -63,6 +64,7 @@ func TestNewLoggingHTTPTransport(t *testing.T) { expectedResEntryFields := map[string]interface{}{ "@level": "debug", "@module": "provider", + "@message": "Received HTTP Response", "Content-Type": "text/html", "tf_http_op_type": "response", "tf_http_res_status_code": float64(200), @@ -76,7 +78,7 @@ func TestNewLoggingHTTPTransport(t *testing.T) { } expectedNonEmptyEntryFields := []string{ - "@message", "Etag", "Date", "X-Frame-Options", "Server", + "tf_http_res_body", "Etag", "Date", "X-Frame-Options", "Server", } for _, ek := range expectedNonEmptyEntryFields { if ev, ok := resEntry[ek]; !ok || ev == "" { @@ -119,12 +121,13 @@ func TestNewSubsystemLoggingHTTPTransport(t *testing.T) { reqEntry := entries[0] if diff := cmp.Diff(reqEntry, map[string]interface{}{ "@level": "debug", - "@message": "An example multiline request body", + "@message": "Sending HTTP Request", "@module": "provider.test-subsystem", "tf_http_op_type": "request", "tf_http_req_method": "GET", "tf_http_req_uri": "/", "tf_http_req_version": "HTTP/1.1", + "tf_http_req_body": "An example multiline request body", "Accept-Encoding": "gzip", "Host": "www.terraform.io", "User-Agent": "Go-http-client/1.1", @@ -137,6 +140,7 @@ func TestNewSubsystemLoggingHTTPTransport(t *testing.T) { expectedResEntryFields := map[string]interface{}{ "@level": "debug", "@module": "provider.test-subsystem", + "@message": "Received HTTP Response", "Content-Type": "text/html", "tf_http_op_type": "response", "tf_http_res_status_code": float64(200), @@ -150,7 +154,7 @@ func TestNewSubsystemLoggingHTTPTransport(t *testing.T) { } expectedNonEmptyEntryFields := []string{ - "@message", "Etag", "Date", "X-Frame-Options", "Server", + "tf_http_res_body", "Etag", "Date", "X-Frame-Options", "Server", } for _, ek := range expectedNonEmptyEntryFields { if ev, ok := resEntry[ek]; !ok || ev == "" { @@ -162,7 +166,8 @@ func TestNewSubsystemLoggingHTTPTransport(t *testing.T) { func TestNewLoggingHTTPTransport_LogMasking(t *testing.T) { ctx, loggerOutput := setupRootLogger() ctx = tflog.MaskFieldValuesWithFieldKeys(ctx, "tf_http_op_type") - ctx = tflog.MaskMessageRegexes(ctx, regexp.MustCompile(`.*`)) + ctx = tflog.MaskAllFieldValuesRegexes(ctx, regexp.MustCompile(`.*`)) + ctx = tflog.MaskMessageStrings(ctx, "Request", "Response") transport := logging.NewLoggingHTTPTransport(http.DefaultTransport) client := http.Client{ @@ -186,14 +191,22 @@ func TestNewLoggingHTTPTransport_LogMasking(t *testing.T) { t.Fatalf("unexpected amount of logs produced; expected 2, got %d", len(entries)) } + if diff := cmp.Diff(entries[0]["@message"], "Sending HTTP ***"); diff != "" { + t.Fatalf("unexpected difference for logging message of request:\n%s", diff) + } + + if diff := cmp.Diff(entries[1]["@message"], "Received HTTP ***"); diff != "" { + t.Fatalf("unexpected difference for logging message of response:\n%s", diff) + } + expectedMaskedEntryFields := map[string]interface{}{ - "tf_http_op_type": "***", - "@message": "***", + "tf_http_op_type": "***", + "tf_http_res_body": "***", } for _, entry := range entries { - for ek, ev := range expectedMaskedEntryFields { - if entry[ek] != "" && entry[ek] != ev { - t.Fatalf("Unexpected value for field %q; expected %q, got %q", ek, ev, entry[ek]) + for expectedK, expectedV := range expectedMaskedEntryFields { + if entryV, ok := entry[expectedK]; ok && entryV != expectedV { + t.Fatalf("Unexpected value for field %q; expected %q, got %q", expectedK, expectedV, entry[expectedK]) } } } @@ -201,7 +214,7 @@ func TestNewLoggingHTTPTransport_LogMasking(t *testing.T) { func TestNewLoggingHTTPTransport_LogOmitting(t *testing.T) { ctx, loggerOutput := setupRootLogger() - ctx = tflog.OmitLogWithMessageRegexes(ctx, regexp.MustCompile("(?i)")) + ctx = tflog.OmitLogWithMessageRegexes(ctx, regexp.MustCompile("(?i)rEsPoNsE")) ctx = tflog.OmitLogWithFieldKeys(ctx, "tf_http_req_method") transport := logging.NewLoggingHTTPTransport(http.DefaultTransport) From 3803b155b5f7776d970a128f2ab495eed1b660ce Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Mon, 25 Jul 2022 16:32:43 +0100 Subject: [PATCH 13/16] Bumping dependency to terraform-plugin-log@v0.7.0 --- go.mod | 2 +- go.sum | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/go.mod b/go.mod index 250e24d6c2..0f3f3ee7bf 100644 --- a/go.mod +++ b/go.mod @@ -19,7 +19,7 @@ require ( github.com/hashicorp/terraform-exec v0.17.2 github.com/hashicorp/terraform-json v0.14.0 github.com/hashicorp/terraform-plugin-go v0.12.0 - github.com/hashicorp/terraform-plugin-log v0.6.1-0.20220724091104-b3ff5d724111 + github.com/hashicorp/terraform-plugin-log v0.7.0 github.com/mitchellh/copystructure v1.2.0 github.com/mitchellh/go-testing-interface v1.14.1 github.com/mitchellh/mapstructure v1.5.0 diff --git a/go.sum b/go.sum index 9f57bcdc19..5c003be8d9 100644 --- a/go.sum +++ b/go.sum @@ -128,8 +128,8 @@ github.com/hashicorp/terraform-json v0.14.0/go.mod h1:5A9HIWPkk4e5aeeXIBbkcOvaZb github.com/hashicorp/terraform-plugin-go v0.12.0 h1:6wW9mT1dSs0Xq4LR6HXj1heQ5ovr5GxXNJwkErZzpJw= github.com/hashicorp/terraform-plugin-go v0.12.0/go.mod h1:kwhmaWHNDvT1B3QiSJdAtrB/D4RaKSY/v3r2BuoWK4M= github.com/hashicorp/terraform-plugin-log v0.6.0/go.mod h1:p4R1jWBXRTvL4odmEkFfDdhUjHf9zcs/BCoNHAc7IK4= -github.com/hashicorp/terraform-plugin-log v0.6.1-0.20220724091104-b3ff5d724111 h1:m0u1i1IWGJuhfeWk7pBETkO1lV1c7bFPTUoMgkVuOKM= -github.com/hashicorp/terraform-plugin-log v0.6.1-0.20220724091104-b3ff5d724111/go.mod h1:p4R1jWBXRTvL4odmEkFfDdhUjHf9zcs/BCoNHAc7IK4= +github.com/hashicorp/terraform-plugin-log v0.7.0 h1:SDxJUyT8TwN4l5b5/VkiTIaQgY6R+Y2BQ0sRZftGKQs= +github.com/hashicorp/terraform-plugin-log v0.7.0/go.mod h1:p4R1jWBXRTvL4odmEkFfDdhUjHf9zcs/BCoNHAc7IK4= github.com/hashicorp/terraform-registry-address v0.0.0-20220623143253-7d51757b572c h1:D8aRO6+mTqHfLsK/BC3j5OAoogv1WLRWzY1AaTo3rBg= github.com/hashicorp/terraform-registry-address v0.0.0-20220623143253-7d51757b572c/go.mod h1:Wn3Na71knbXc1G8Lh+yu/dQWWJeFQEpDeJMtWMtlmNI= github.com/hashicorp/terraform-svchost v0.0.0-20200729002733-f050f53b9734 h1:HKLsbzeOsfXmKNpr3GiT18XAblV0BjCbzL8KQAMZGa0= From b075aaf76bf97110be0870621f8819f547c1651a Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Tue, 26 Jul 2022 09:52:11 +0100 Subject: [PATCH 14/16] Remove unnecessary exported constant --- helper/logging/logging_http_transport.go | 11 ++--------- 1 file changed, 2 insertions(+), 9 deletions(-) diff --git a/helper/logging/logging_http_transport.go b/helper/logging/logging_http_transport.go index 56086af5a7..d448d3ef32 100644 --- a/helper/logging/logging_http_transport.go +++ b/helper/logging/logging_http_transport.go @@ -108,13 +108,6 @@ const ( // and NewSubsystemLoggingHTTPTransport when logging an HTTP response body via tflog. FieldHttpResponseBody = "tf_http_res_body" - // MessageHttpRequest is the message used by NewLoggingHTTPTransport - // and NewSubsystemLoggingHTTPTransport when logging an HTTP request via tflog. - MessageHttpRequest = "Sending HTTP Request" - - // MessageHttpResponse is the message used by NewLoggingHTTPTransport - // and NewSubsystemLoggingHTTPTransport when logging an HTTP response via tflog. - MessageHttpResponse = "Received HTTP Response" ) type loggingHttpTransport struct { @@ -132,7 +125,7 @@ func (t *loggingHttpTransport) RoundTrip(req *http.Request) (*http.Response, err "error": err, }) } else { - t.Debug(ctx, MessageHttpRequest, fields) + t.Debug(ctx, "Sending HTTP Request", fields) } // Invoke the wrapped RoundTrip now @@ -148,7 +141,7 @@ func (t *loggingHttpTransport) RoundTrip(req *http.Request) (*http.Response, err "error": err, }) } else { - t.Debug(ctx, MessageHttpResponse, fields) + t.Debug(ctx, "Received HTTP Response", fields) } return res, nil From b54d37651accbc533d4fc633ec52ed777c07af17 Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Tue, 26 Jul 2022 09:53:50 +0100 Subject: [PATCH 15/16] Add a new field to every HTTP transaction: `tf_http_trans_id` This is a UUID, and it's specific to the pair of HTTP Req/Res that 1 HTTP Transaction executes --- helper/logging/logging_http_transport.go | 20 ++++++++++++ helper/logging/logging_http_transport_test.go | 31 +++++++++++++++++++ 2 files changed, 51 insertions(+) diff --git a/helper/logging/logging_http_transport.go b/helper/logging/logging_http_transport.go index d448d3ef32..d1214fa1c6 100644 --- a/helper/logging/logging_http_transport.go +++ b/helper/logging/logging_http_transport.go @@ -11,6 +11,7 @@ import ( "net/textproto" "strings" + "github.com/hashicorp/go-uuid" "github.com/hashicorp/terraform-plugin-log/tflog" ) @@ -108,6 +109,9 @@ const ( // and NewSubsystemLoggingHTTPTransport when logging an HTTP response body via tflog. FieldHttpResponseBody = "tf_http_res_body" + // FieldHttpTransactionId is the field key used by NewLoggingHTTPTransport + // and NewSubsystemLoggingHTTPTransport when logging an HTTP transaction via tflog. + FieldHttpTransactionId = "tf_http_trans_id" ) type loggingHttpTransport struct { @@ -117,6 +121,7 @@ type loggingHttpTransport struct { func (t *loggingHttpTransport) RoundTrip(req *http.Request) (*http.Response, error) { ctx := req.Context() + ctx = t.AddTransactionIdField(ctx) // Decompose the request bytes in a message (HTTP body) and fields (HTTP headers), then log it fields, err := decomposeRequestForLogging(req) @@ -163,6 +168,21 @@ func (t *loggingHttpTransport) Error(ctx context.Context, msg string, fields ... } } +func (t *loggingHttpTransport) AddTransactionIdField(ctx context.Context) context.Context { + tId, err := uuid.GenerateUUID() + + if err != nil { + tId = "Unable to assign Transaction ID: " + err.Error() + } + + if t.subsystem != "" { + return tflog.SubsystemSetField(ctx, t.subsystem, FieldHttpTransactionId, tId) + } else { + return tflog.SetField(ctx, FieldHttpTransactionId, tId) + + } +} + func decomposeRequestForLogging(req *http.Request) (map[string]interface{}, error) { fields := make(map[string]interface{}, len(req.Header)+4) fields[FieldHttpOperationType] = OperationHttpRequest diff --git a/helper/logging/logging_http_transport_test.go b/helper/logging/logging_http_transport_test.go index b214ad6588..e001226e30 100644 --- a/helper/logging/logging_http_transport_test.go +++ b/helper/logging/logging_http_transport_test.go @@ -9,6 +9,7 @@ import ( "time" "github.com/google/go-cmp/cmp" + "github.com/hashicorp/go-uuid" "github.com/hashicorp/terraform-plugin-log/tflog" "github.com/hashicorp/terraform-plugin-log/tflogtest" "github.com/hashicorp/terraform-plugin-sdk/v2/helper/logging" @@ -42,6 +43,19 @@ func TestNewLoggingHTTPTransport(t *testing.T) { t.Fatalf("unexpected amount of logs produced; expected 2, got %d", len(entries)) } + if transId, ok := entries[0]["tf_http_trans_id"]; !ok || transId != entries[1]["tf_http_trans_id"] { + t.Fatalf("expected to find the same 'tf_http_trans_id' in both req/res entries, got %q", transId) + } + + transId, ok := entries[0]["tf_http_trans_id"].(string) + if !ok { + t.Fatalf("expected 'tf_http_trans_id' to be a string, got %T", transId) + } + + if _, err := uuid.ParseUUID(transId); err != nil { + t.Fatalf("expected 'tf_http_trans_id' to be contain a valid UUID, but got an error: %v", err) + } + reqEntry := entries[0] if diff := cmp.Diff(reqEntry, map[string]interface{}{ "@level": "debug", @@ -52,6 +66,7 @@ func TestNewLoggingHTTPTransport(t *testing.T) { "tf_http_req_uri": "/", "tf_http_req_version": "HTTP/1.1", "tf_http_req_body": "An example multiline request body", + "tf_http_trans_id": transId, "Accept-Encoding": "gzip", "Host": "www.terraform.io", "User-Agent": "Go-http-client/1.1", @@ -70,6 +85,7 @@ func TestNewLoggingHTTPTransport(t *testing.T) { "tf_http_res_status_code": float64(200), "tf_http_res_version": "HTTP/2.0", "tf_http_res_status_reason": "200 OK", + "tf_http_trans_id": transId, } for ek, ev := range expectedResEntryFields { if resEntry[ek] != ev { @@ -118,6 +134,19 @@ func TestNewSubsystemLoggingHTTPTransport(t *testing.T) { t.Fatalf("unexpected amount of logs produced; expected 2, got %d", len(entries)) } + if transId, ok := entries[0]["tf_http_trans_id"]; !ok || transId != entries[1]["tf_http_trans_id"] { + t.Fatalf("expected to find the same 'tf_http_trans_id' in both req/res entries, got %q", transId) + } + + transId, ok := entries[0]["tf_http_trans_id"].(string) + if !ok { + t.Fatalf("expected 'tf_http_trans_id' to be a string, got %T", transId) + } + + if _, err := uuid.ParseUUID(transId); err != nil { + t.Fatalf("expected 'tf_http_trans_id' to be contain a valid UUID, but got an error: %v", err) + } + reqEntry := entries[0] if diff := cmp.Diff(reqEntry, map[string]interface{}{ "@level": "debug", @@ -128,6 +157,7 @@ func TestNewSubsystemLoggingHTTPTransport(t *testing.T) { "tf_http_req_uri": "/", "tf_http_req_version": "HTTP/1.1", "tf_http_req_body": "An example multiline request body", + "tf_http_trans_id": transId, "Accept-Encoding": "gzip", "Host": "www.terraform.io", "User-Agent": "Go-http-client/1.1", @@ -146,6 +176,7 @@ func TestNewSubsystemLoggingHTTPTransport(t *testing.T) { "tf_http_res_status_code": float64(200), "tf_http_res_version": "HTTP/2.0", "tf_http_res_status_reason": "200 OK", + "tf_http_trans_id": transId, } for ek, ev := range expectedResEntryFields { if resEntry[ek] != ev { From bc3e299cf7e0e9977fdcf4ca9215d621cbcf8447 Mon Sep 17 00:00:00 2001 From: Ivan De Marino Date: Tue, 26 Jul 2022 09:54:14 +0100 Subject: [PATCH 16/16] Removing unnecessary response body byte buffer copying --- helper/logging/logging_http_transport.go | 78 +++++++++---------- helper/logging/logging_http_transport_test.go | 9 +++ 2 files changed, 46 insertions(+), 41 deletions(-) diff --git a/helper/logging/logging_http_transport.go b/helper/logging/logging_http_transport.go index d1214fa1c6..335e1784e2 100644 --- a/helper/logging/logging_http_transport.go +++ b/helper/logging/logging_http_transport.go @@ -203,54 +203,17 @@ func decomposeRequestForLogging(req *http.Request) (map[string]interface{}, erro // Create a reader around the request full body reqReader := textproto.NewReader(bufio.NewReader(bytes.NewReader(reqBytes))) - err = readHeadersIntoFields(reqReader, fields) + err = fieldHeadersFromRequestReader(reqReader, fields) if err != nil { return nil, err } // Read the rest of the body content - fields[FieldHttpRequestBody] = readRestToString(reqReader) + fields[FieldHttpRequestBody] = bodyFromRestOfRequestReader(reqReader) return fields, nil } -func decomposeResponseForLogging(res *http.Response) (map[string]interface{}, error) { - fields := make(map[string]interface{}, len(res.Header)+4) - fields[FieldHttpOperationType] = OperationHttpResponse - - fields[FieldHttpResponseProtoVersion] = res.Proto - fields[FieldHttpResponseStatusCode] = res.StatusCode - fields[FieldHttpResponseStatusReason] = res.Status - - // Set the headers as fields to log - for k, v := range res.Header { - if len(v) == 1 { - fields[k] = v[0] - } else { - fields[k] = v - } - } - - // Read the whole response body - resBody, err := io.ReadAll(res.Body) - if err != nil { - return nil, err - } - - // Make a copy of the response body bytes, to be returned as log message - msgBytes := make([]byte, len(resBody)) - copy(msgBytes, resBody) - - // Wrap the bytes from the response body, back into an io.ReadCloser, - // to respect the interface of http.Response, as expected by users of the - // http.Client - res.Body = io.NopCloser(bytes.NewBuffer(resBody)) - - fields[FieldHttpResponseBody] = string(resBody) - - return fields, nil -} - -func readHeadersIntoFields(reader *textproto.Reader, fields map[string]interface{}) error { +func fieldHeadersFromRequestReader(reader *textproto.Reader, fields map[string]interface{}) error { // Ignore the first line: it contains non-header content // that we have already captured. // Skipping this step, would cause the following call to `ReadMIMEHeader()` @@ -278,7 +241,7 @@ func readHeadersIntoFields(reader *textproto.Reader, fields map[string]interface return nil } -func readRestToString(reader *textproto.Reader) string { +func bodyFromRestOfRequestReader(reader *textproto.Reader) string { var builder strings.Builder for { line, err := reader.ReadContinuedLine() @@ -290,3 +253,36 @@ func readRestToString(reader *textproto.Reader) string { return builder.String() } + +func decomposeResponseForLogging(res *http.Response) (map[string]interface{}, error) { + fields := make(map[string]interface{}, len(res.Header)+4) + fields[FieldHttpOperationType] = OperationHttpResponse + + fields[FieldHttpResponseProtoVersion] = res.Proto + fields[FieldHttpResponseStatusCode] = res.StatusCode + fields[FieldHttpResponseStatusReason] = res.Status + + // Set the headers as fields to log + for k, v := range res.Header { + if len(v) == 1 { + fields[k] = v[0] + } else { + fields[k] = v + } + } + + // Read the whole response body + resBody, err := io.ReadAll(res.Body) + if err != nil { + return nil, err + } + + // Wrap the bytes from the response body, back into an io.ReadCloser, + // to respect the interface of http.Response, as expected by users of the + // http.Client + res.Body = io.NopCloser(bytes.NewBuffer(resBody)) + + fields[FieldHttpResponseBody] = string(resBody) + + return fields, nil +} diff --git a/helper/logging/logging_http_transport_test.go b/helper/logging/logging_http_transport_test.go index e001226e30..b9c986fe5f 100644 --- a/helper/logging/logging_http_transport_test.go +++ b/helper/logging/logging_http_transport_test.go @@ -3,6 +3,7 @@ package logging_test import ( "bytes" "context" + "io" "net/http" "regexp" "testing" @@ -212,6 +213,10 @@ func TestNewLoggingHTTPTransport_LogMasking(t *testing.T) { t.Fatalf("request failed: %v", err) } defer res.Body.Close() + resBody, err := io.ReadAll(res.Body) + if err != nil { + t.Fatalf("failed to read response body: %v", err) + } entries, err := tflogtest.MultilineJSONDecode(loggerOutput) if err != nil { @@ -241,6 +246,10 @@ func TestNewLoggingHTTPTransport_LogMasking(t *testing.T) { } } } + + if diff := cmp.Diff(entries[1]["tf_http_res_body"], string(resBody)); diff == "" { + t.Fatalf("expected HTTP response body and content of field 'tf_http_res_body' to differ, but they do not") + } } func TestNewLoggingHTTPTransport_LogOmitting(t *testing.T) {