Skip to content

Commit

Permalink
Place the req/res body in a dedicated field, and keep the log message…
Browse files Browse the repository at this point in the history 
… short (i.e. "Sending HTTP Request / Received HTTP Response")
  • Loading branch information
Ivan De Marino committed Jul 25, 2022
1 parent 5583b6c commit cb6d577
Show file tree
Hide file tree
Showing 2 changed files with 74 additions and 34 deletions.
73 changes: 50 additions & 23 deletions helper/logging/logging_http_transport.go
View file
Expand Up @@ -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 {
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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

Expand All @@ -159,23 +184,23 @@ 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
reqReader := textproto.NewReader(bufio.NewReader(bytes.NewReader(reqBytes)))

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

Expand All @@ -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
Expand All @@ -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 {
Expand Down
35 changes: 24 additions & 11 deletions helper/logging/logging_http_transport_test.go
View file
Expand Up @@ -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",
Expand All @@ -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),
Expand All @@ -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 == "" {
Expand Down Expand Up @@ -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",
Expand All @@ -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),
Expand All @@ -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 == "" {
Expand All @@ -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(`<html>.*</html>`))
ctx = tflog.MaskAllFieldValuesRegexes(ctx, regexp.MustCompile(`<html>.*</html>`))
ctx = tflog.MaskMessageStrings(ctx, "Request", "Response")

transport := logging.NewLoggingHTTPTransport(http.DefaultTransport)
client := http.Client{
Expand All @@ -186,22 +191,30 @@ 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": "<!DOCTYPE html>***",
"tf_http_op_type": "***",
"tf_http_res_body": "<!DOCTYPE html>***",
}
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])
}
}
}
}

func TestNewLoggingHTTPTransport_LogOmitting(t *testing.T) {
ctx, loggerOutput := setupRootLogger()
ctx = tflog.OmitLogWithMessageRegexes(ctx, regexp.MustCompile("(?i)<html>"))
ctx = tflog.OmitLogWithMessageRegexes(ctx, regexp.MustCompile("(?i)rEsPoNsE"))
ctx = tflog.OmitLogWithFieldKeys(ctx, "tf_http_req_method")

transport := logging.NewLoggingHTTPTransport(http.DefaultTransport)
Expand Down

0 comments on commit cb6d577

Please sign in to comment.