Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Updated log formatting to more closely resemble Resty's #595

Open
wants to merge 1 commit into
base: proj/resty-migration
Choose a base branch
from
Open

Updated log formatting to more closely resemble Resty's #595

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
149 changes: 118 additions & 31 deletions client.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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 {
Expand All @@ -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
}
Expand All @@ -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
}
}
Expand Down Expand Up @@ -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()
Expand All @@ -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,
}
Expand All @@ -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 {
Expand All @@ -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())
Expand Down
59 changes: 23 additions & 36 deletions client_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down