Skip to content

Commit

Permalink
Introduce NewLoggingHTTPTransport and deprecate NewTransport (#1006)
Browse files Browse the repository at this point in the history
* .gitignore JetBrains IDE project files

* Removing `fmtcheck` target in `Makefile`, and instead add `lint` to trigger GolangCI-Lint (what we use today)

* Introducing `helper/logging` `NewLoggingHTTPTransport`

This deprecated the `NewTransport` facility.

* Set golangci-lint GH Action to always pick the latest version of golangci-lint executable

* Added test coverage to confirm request-body is captured, as well as log masking and filtering

* Adding CHANGELOG entry

* Place the req/res body in a dedicated field, and keep the log message short (i.e. "Sending HTTP Request / Received HTTP Response")

* Bumping dependency to terraform-plugin-log@v0.7.0

* 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
  • Loading branch information
Ivan De Marino committed Jul 26, 2022
1 parent 06cd54f commit 426ae64
Show file tree
Hide file tree
Showing 10 changed files with 608 additions and 12 deletions.
7 changes: 7 additions & 0 deletions .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()`
```
4 changes: 3 additions & 1 deletion .github/workflows/ci-go.yml
Expand Up @@ -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:
Expand Down
6 changes: 5 additions & 1 deletion .gitignore
@@ -1,2 +1,6 @@
node_modules
website-preview
website-preview

# Jetbrains IDEs
.idea/
*.iws
12 changes: 6 additions & 6 deletions Makefile
Expand Up @@ -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:
Expand All @@ -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
.PHONY: default fmt lint generate test website website/local website/build-local
2 changes: 1 addition & 1 deletion go.mod
Expand Up @@ -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.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
Expand Down
3 changes: 2 additions & 1 deletion go.sum
Expand Up @@ -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.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=
Expand Down
288 changes: 288 additions & 0 deletions helper/logging/logging_http_transport.go
@@ -0,0 +1,288 @@
package logging

import (
"bufio"
"bytes"
"context"
"errors"
"io"
"net/http"
"net/http/httputil"
"net/textproto"
"strings"

"github.com/hashicorp/go-uuid"
"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{"", 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.
//
// 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, t}
}

const (
// 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 NewLoggingHTTPTransport
// and NewSubsystemLoggingHTTPTransport when logging an HTTP request via tflog.
OperationHttpRequest = "request"

// 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 NewLoggingHTTPTransport
// and NewSubsystemLoggingHTTPTransport when logging an HTTP request URI via tflog.
FieldHttpRequestUri = "tf_http_req_uri"

// FieldHttpRequestProtoVersion is the field key used by NewLoggingHTTPTransport
// and NewSubsystemLoggingHTTPTransport when logging an HTTP request HTTP version via tflog.
FieldHttpRequestProtoVersion = "tf_http_req_version"

// 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 NewLoggingHTTPTransport
// and NewSubsystemLoggingHTTPTransport when logging an HTTP response protocol version via tflog.
FieldHttpResponseProtoVersion = "tf_http_res_version"

// 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 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"

// 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 {
subsystem string
transport http.RoundTripper
}

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)
if err != nil {
t.Error(ctx, "Failed to parse request bytes for logging", map[string]interface{}{
"error": err,
})
} else {
t.Debug(ctx, "Sending HTTP Request", fields)
}

// Invoke the wrapped RoundTrip now
res, err := t.transport.RoundTrip(req)
if err != nil {
return res, err
}

// Decompose the response bytes in a message (HTTP body) and fields (HTTP headers), then log it
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, "Received HTTP Response", fields)
}

return res, nil
}

func (t *loggingHttpTransport) Debug(ctx context.Context, msg string, fields ...map[string]interface{}) {
if t.subsystem != "" {
tflog.SubsystemDebug(ctx, t.subsystem, msg, fields...)
} else {
tflog.Debug(ctx, msg, fields...)
}
}

func (t *loggingHttpTransport) Error(ctx context.Context, msg string, fields ...map[string]interface{}) {
if t.subsystem != "" {
tflog.SubsystemError(ctx, t.subsystem, msg, fields...)
} else {
tflog.Error(ctx, msg, 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

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)))

err = fieldHeadersFromRequestReader(reqReader, fields)
if err != nil {
return nil, err
}

// Read the rest of the body content
fields[FieldHttpRequestBody] = bodyFromRestOfRequestReader(reqReader)
return fields, nil
}

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()`
// to fail as it cannot parse the first line.
_, err := reader.ReadLine()
if err != nil {
return err
}

// Read the MIME-style headers
mimeHeader, err := reader.ReadMIMEHeader()
if err != nil {
return 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
}
}

return nil
}

func bodyFromRestOfRequestReader(reader *textproto.Reader) string {
var builder strings.Builder
for {
line, err := reader.ReadContinuedLine()
if errors.Is(err, io.EOF) {
break
}
builder.WriteString(line)
}

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
}

0 comments on commit 426ae64

Please sign in to comment.