From 095e493e2d355759dc094c7fa35fc4bec6bb54d4 Mon Sep 17 00:00:00 2001 From: ezilber-akamai Date: Fri, 25 Oct 2024 14:34:26 -0400 Subject: [PATCH] Updated log formatting to more closely resemble Resty's --- client.go | 149 +++++++++++++++++++++++++++++++++++++++---------- client_test.go | 59 ++++++++------------ 2 files changed, 141 insertions(+), 67 deletions(-) diff --git a/client.go b/client.go index 9fd3cde0..b94a048b 100644 --- a/client.go +++ b/client.go @@ -51,30 +51,41 @@ const ( ) var ( - reqLogTemplate = template.Must(template.New("request").Parse(`Sending request: -Method: {{.Method}} -URL: {{.URL}} -Headers: {{.Headers}} -Body: {{.Body}}`)) - - respLogTemplate = template.Must(template.New("response").Parse(`Received response: -Status: {{.Status}} -Headers: {{.Headers}} -Body: {{.Body}}`)) + reqLogTemplate = template.Must(template.New("request").Parse(` +============================================================================================ +~~~ REQUEST ~~~ +{{.Request}} +HOST: {{.Host}} +HEADERS: {{.Headers}} +BODY: {{.Body}} +--------------------------------------------------------------------------------------------`)) + + respLogTemplate = template.Must(template.New("response").Parse(` +============================================================================================ +~~~ RESPONSE ~~~ +STATUS: {{.Status}} +PROTO: {{.Proto}} +RECEIVED AT: {{.ReceivedAt}} +TIME DURATION: {{.TimeDuration}} +HEADERS: {{.Headers}} +BODY: {{.Body}} +--------------------------------------------------------------------------------------------`)) ) type RequestLog struct { - Method string - URL string + Request string + Host string Headers http.Header Body string } type ResponseLog struct { - Method string - URL string - Headers http.Header - Body string + Status string + Proto string + ReceivedAt string + TimeDuration string + Headers http.Header + Body string } var envDebug = false @@ -192,10 +203,10 @@ func (c *Client) doRequest(ctx context.Context, method, endpoint string, params } if c.debug && c.logger != nil { - c.logRequest(req, method, endpoint, bodyBuffer) + c.logRequest(req, bodyBuffer) } - processResponse := func() error { + processResponse := func(start, end time.Time) error { defer func() { closeErr := resp.Body.Close() if closeErr != nil && err == nil { @@ -207,7 +218,7 @@ func (c *Client) doRequest(ctx context.Context, method, endpoint string, params } if c.debug && c.logger != nil { var logErr error - resp, logErr = c.logResponse(resp) + resp, logErr = c.logResponse(resp, start, end) if logErr != nil { return logErr } @@ -226,9 +237,11 @@ func (c *Client) doRequest(ctx context.Context, method, endpoint string, params return nil } + startTime := time.Now() resp, err = c.sendRequest(req) + endTime := time.Now() if err == nil { - if err = processResponse(); err == nil { + if err = processResponse(startTime, endTime); err == nil { return nil } } @@ -327,7 +340,7 @@ func (c *Client) applyAfterResponse(resp *http.Response) error { return nil } -func (c *Client) logRequest(req *http.Request, method, url string, bodyBuffer *bytes.Buffer) { +func (c *Client) logRequest(req *http.Request, bodyBuffer *bytes.Buffer) { var reqBody string if bodyBuffer != nil { reqBody = bodyBuffer.String() @@ -336,8 +349,8 @@ func (c *Client) logRequest(req *http.Request, method, url string, bodyBuffer *b } reqLog := &RequestLog{ - Method: method, - URL: url, + Request: strings.Join([]string{req.Method, req.URL.Path, req.Proto}, " "), + Host: req.Host, Headers: req.Header, Body: reqBody, } @@ -347,18 +360,64 @@ func (c *Client) logRequest(req *http.Request, method, url string, bodyBuffer *b _ = c.ErrorAndLogf("failed to mutate after response: %v", e.Error()) } + body, jsonErr := formatBody(reqLog.Body) + if jsonErr != nil { + if c.debug && c.logger != nil { + c.logger.Errorf("%v", jsonErr) + } + } + var logBuf bytes.Buffer err := reqLogTemplate.Execute(&logBuf, map[string]interface{}{ - "Method": reqLog.Method, - "URL": reqLog.URL, - "Headers": reqLog.Headers, - "Body": reqLog.Body, + "Request": reqLog.Request, + "Host": reqLog.Host, + "Headers": formatHeaders(reqLog.Headers), + "Body": body, }) if err == nil { c.logger.Debugf(logBuf.String()) } } +func formatHeaders(headers map[string][]string) string { + var builder strings.Builder + builder.WriteString("\n") + + for key, values := range headers { + builder.WriteString(fmt.Sprintf(" %s: %s\n", key, strings.Join(values, ", "))) + } + return strings.TrimSuffix(builder.String(), "\n") +} + +func formatBody(body string) (string, error) { + body = strings.TrimSpace(body) + if body == "null" || body == "nil" || body == "" { + return "", nil + } + + var jsonData map[string]interface{} + err := json.Unmarshal([]byte(body), &jsonData) + if err != nil { + return "", fmt.Errorf("error unmarshalling JSON: %w", err) + } + + prettyJSON, err := json.MarshalIndent(jsonData, "", " ") + if err != nil { + return "", fmt.Errorf("error marshalling JSON: %w", err) + } + + return "\n" + string(prettyJSON), nil +} + +func formatDate(dateStr string) (string, error) { + parsedTime, err := time.Parse(time.RFC1123, dateStr) + if err != nil { + return "", fmt.Errorf("error parsing date: %v", err) + } + formattedDate := parsedTime.In(time.Local).Format("2006-01-02T15:04:05-07:00") // nolint:gosmopolitan + return formattedDate, nil +} + func (c *Client) sendRequest(req *http.Request) (*http.Response, error) { resp, err := c.httpClient.Do(req) if err != nil { @@ -376,17 +435,45 @@ func (c *Client) checkHTTPError(resp *http.Response) error { return nil } -func (c *Client) logResponse(resp *http.Response) (*http.Response, error) { +func (c *Client) logResponse(resp *http.Response, start, end time.Time) (*http.Response, error) { var respBody bytes.Buffer if _, err := io.Copy(&respBody, resp.Body); err != nil { c.logger.Errorf("failed to read response body: %v", err) } + receivedAt, dateErr := formatDate(resp.Header.Get("Date")) + if dateErr != nil { + if c.debug && c.logger != nil { + c.logger.Errorf("failed to format date: %v", dateErr) + } + } + + duration := end.Sub(start).String() + + respLog := &ResponseLog{ + Status: resp.Status, + Proto: resp.Proto, + ReceivedAt: receivedAt, + TimeDuration: duration, + Headers: resp.Header, + Body: respBody.String(), + } + + body, jsonErr := formatBody(respLog.Body) + if jsonErr != nil { + if c.debug && c.logger != nil { + c.logger.Errorf("%v", jsonErr) + } + } + var logBuf bytes.Buffer err := respLogTemplate.Execute(&logBuf, map[string]interface{}{ - "Status": resp.Status, - "Headers": resp.Header, - "Body": respBody.String(), + "Status": respLog.Status, + "Proto": respLog.Proto, + "ReceivedAt": respLog.ReceivedAt, + "TimeDuration": respLog.TimeDuration, + "Headers": formatHeaders(respLog.Headers), + "Body": body, }) if err == nil { c.logger.Debugf(logBuf.String()) diff --git a/client_test.go b/client_test.go index 6af45369..1ee37de5 100644 --- a/client_test.go +++ b/client_test.go @@ -442,48 +442,35 @@ func TestDoRequestLogging_Success(t *testing.T) { } logInfo := logBuffer.String() - logInfoWithoutTimestamps := removeTimestamps(logInfo) - // Expected logs with templates filled in - expectedRequestLog := "DEBUG Sending request:\nMethod: GET\nURL: " + server.URL + "\nHeaders: map[Accept:[application/json] Authorization:[Bearer *******************************] Content-Type:[application/json] User-Agent:[linodego/dev https://github.com/linode/linodego]]\nBody: " - expectedResponseLog := "DEBUG Received response:\nStatus: 200 OK\nHeaders: map[Content-Length:[21] Content-Type:[text/plain; charset=utf-8]]\nBody: {\"message\":\"success\"}" + expectedRequestParts := []string{ + "GET /v4/" + server.URL + " " + "HTTP/1.1", + "Accept: application/json", + "Authorization: Bearer *******************************", + "Content-Type: application/json", + "User-Agent: linodego/dev https://github.com/linode/linodego", + } - if !strings.Contains(logInfo, expectedRequestLog) { - t.Fatalf("expected log %q not found in logs", expectedRequestLog) + expectedResponseParts := []string{ + "STATUS: 200 OK", + "PROTO: HTTP/1.1", + "Content-Length: 21", + "Content-Type: application/json", + `"message": "success"`, } - if !strings.Contains(logInfoWithoutTimestamps, expectedResponseLog) { - t.Fatalf("expected log %q not found in logs", expectedResponseLog) + + for _, part := range expectedRequestParts { + if !strings.Contains(logInfo, part) { + t.Fatalf("expected request part %q not found in logs", part) + } + } + for _, part := range expectedResponseParts { + if !strings.Contains(logInfo, part) { + t.Fatalf("expected response part %q not found in logs", part) + } } } -// func TestDoRequestLogging_Error(t *testing.T) { -// var logBuffer bytes.Buffer -// logger := createLogger() -// logger.l.SetOutput(&logBuffer) // Redirect log output to buffer -// -// client := NewClient(nil) -// client.SetDebug(true) -// client.SetLogger(logger) -// -// params := requestParams{ -// Body: map[string]interface{}{ -// "invalid": func() {}, -// }, -// } -// -// err := client.doRequest(context.Background(), http.MethodPost, "/foo/bar", params, nil) -// expectedErr := "failed to read body: params.Body is not a *bytes.Reader" -// if err == nil || !strings.Contains(err.Error(), expectedErr) { -// t.Fatalf("expected error %q, got: %v", expectedErr, err) -// } -// -// logInfo := logBuffer.String() -// expectedLog := "ERROR failed to read body: params.Body is not a *bytes.Reader" -// -// if !strings.Contains(logInfo, expectedLog) { -// t.Fatalf("expected log %q not found in logs", expectedLog) -// } -// } func TestDoRequestLogging_Error(t *testing.T) { var logBuffer bytes.Buffer logger := createLogger()