add debug log formatter feature (#966)

Author: jeevatkm

client.go

@@ -89,10 +89,6 @@ type (
 	// ResponseMiddleware type is for response middleware, called after a response has been received
 	ResponseMiddleware func(*Client, *Response) error
 
-	// DebugLogCallback type is for request and response debug log callback purpose.
-	// It gets called before Resty logs it
-	DebugLogCallback func(*DebugLog)
-
 	// ErrorHook type is for reacting to request errors, called after all retries were attempted
 	ErrorHook func(*Request, error)
 
@@ -207,8 +203,8 @@ type Client struct {
 	ctx                      context.Context
 	httpClient               *http.Client
 	proxyURL                 *url.URL
-	requestDebugLog          DebugLogCallback
-	responseDebugLog         DebugLogCallback
+	debugLogFormatter        DebugLogFormatterFunc
+	debugLogCallback         DebugLogCallbackFunc
 	generateCurlCmd          bool
 	debugLogCurlCmd          bool
 	unescapeQueryParams      bool
@@ -1021,29 +1017,36 @@ func (c *Client) SetDebugBodyLimit(sl int) *Client {
 	return c
 }
 
-// OnRequestDebugLog method sets the request debug log callback to the client instance.
+func (c *Client) debugLogCallbackFunc() DebugLogCallbackFunc {
+	c.lock.RLock()
+	defer c.lock.RUnlock()
+	return c.debugLogCallback
+}
+
+// OnDebugLog method sets the debug log callback function to the client instance.
 // Registered callback gets called before the Resty logs the information.
-func (c *Client) OnRequestDebugLog(dlc DebugLogCallback) *Client {
+func (c *Client) OnDebugLog(dlc DebugLogCallbackFunc) *Client {
 	c.lock.Lock()
 	defer c.lock.Unlock()
-	if c.requestDebugLog != nil {
-		c.log.Warnf("Overwriting an existing on-request-debug-log callback from=%s to=%s",
-			functionName(c.requestDebugLog), functionName(dlc))
+	if c.debugLogCallback != nil {
+		c.log.Warnf("Overwriting an existing on-debug-log callback from=%s to=%s",
+			functionName(c.debugLogCallback), functionName(dlc))
 	}
-	c.requestDebugLog = dlc
+	c.debugLogCallback = dlc
 	return c
 }
 
-// OnResponseDebugLog method sets the response debug log callback to the client instance.
-// Registered callback gets called before the Resty logs the information.
-func (c *Client) OnResponseDebugLog(dlc DebugLogCallback) *Client {
+func (c *Client) debugLogFormatterFunc() DebugLogFormatterFunc {
+	c.lock.RLock()
+	defer c.lock.RUnlock()
+	return c.debugLogFormatter
+}
+
+// SetDebugLogFormatter method sets the Resty debug log formatter to the client instance.
+func (c *Client) SetDebugLogFormatter(df DebugLogFormatterFunc) *Client {
 	c.lock.Lock()
 	defer c.lock.Unlock()
-	if c.responseDebugLog != nil {
-		c.log.Warnf("Overwriting an existing on-response-debug-log callback from=%s to=%s",
-			functionName(c.responseDebugLog), functionName(dlc))
-	}
-	c.responseDebugLog = dlc
+	c.debugLogFormatter = df
 	return c
 }
 
@@ -2245,7 +2248,7 @@ func (c *Client) execute(req *Request) (*Response, error) {
 		req.RawRequest.Host = hostHeader
 	}
 
-	requestDebugLogger(c, req)
+	prepareRequestDebugInfo(c, req)
 
 	req.Time = time.Now()
 	resp, err := c.Client().Do(req.withTimeout())
@@ -2278,7 +2281,7 @@ func (c *Client) execute(req *Request) (*Response, error) {
 		}
 	}
 
-	responseDebugLogger(c, response)
+	debugLogger(c, response)
 
 	// Apply Response middleware
 	for _, f := range c.responseMiddlewares() {

client_test.go

@@ -898,13 +898,14 @@ func TestClientLogCallbacks(t *testing.T) {
 
 	c, lb := dcldb()
 
-	c.OnRequestDebugLog(func(r *DebugLog) {
+	c.OnDebugLog(func(dl *DebugLog) {
+		// request
 		// masking authorization header
-		r.Header.Set("Authorization", "Bearer *******************************")
-	})
-	c.OnResponseDebugLog(func(r *DebugLog) {
-		r.Header.Add("X-Debug-Response-Log", "Modified :)")
-		r.Body += "\nModified the response body content"
+		dl.Request.Header.Set("Authorization", "Bearer *******************************")
+
+		// response
+		dl.Response.Header.Add("X-Debug-Response-Log", "Modified :)")
+		dl.Response.Body += "\nModified the response body content"
 	})
 
 	c.SetTLSClientConfig(&tls.Config{InsecureSkipVerify: true}).
@@ -924,28 +925,16 @@ func TestClientLogCallbacks(t *testing.T) {
 	assertEqual(t, true, strings.Contains(logInfo, "Modified the response body content"))
 
 	// overwrite scenario
-	c.OnRequestDebugLog(func(r *DebugLog) {
-		// overwrite request debug log
-	})
-	resp, err = c.R().
-		SetAuthToken("004DDB79-6801-4587-B976-F093E6AC44FF-Request").
-		Get(ts.URL + "/profile")
-	assertNil(t, err)
-	assertNotNil(t, resp)
-	assertEqual(t, int64(50), resp.Size())
-	assertEqual(t, true, strings.Contains(lb.String(), "Overwriting an existing on-request-debug-log callback from=resty.dev/v3.TestClientLogCallbacks.func1 to=resty.dev/v3.TestClientLogCallbacks.func3"))
-
-	c.OnRequestDebugLog(nil)
-	c.OnResponseDebugLog(func(r *DebugLog) {
-		// overwrite response debug log
+	c.OnDebugLog(func(dl *DebugLog) {
+		// overwrite debug log
 	})
 	resp, err = c.R().
 		SetAuthToken("004DDB79-6801-4587-B976-F093E6AC44FF-Request").
 		Get(ts.URL + "/profile")
 	assertNil(t, err)
 	assertNotNil(t, resp)
 	assertEqual(t, int64(50), resp.Size())
-	assertEqual(t, true, strings.Contains(lb.String(), "Overwriting an existing on-response-debug-log callback from=resty.dev/v3.TestClientLogCallbacks.func2 to=resty.dev/v3.TestClientLogCallbacks.func4"))
+	assertEqual(t, true, strings.Contains(lb.String(), "Overwriting an existing on-debug-log callback from=resty.dev/v3.TestClientLogCallbacks.func1 to=resty.dev/v3.TestClientLogCallbacks.func2"))
 }
 
 func TestDebugLogSimultaneously(t *testing.T) {

debug.go

@@ -0,0 +1,181 @@
+// Copyright (c) 2015-present Jeevanandam M ([email protected]), All rights reserved.
+// resty source code and usage is governed by a MIT style
+// license that can be found in the LICENSE file.
+// SPDX-License-Identifier: MIT
+
+package resty
+
+import (
+	"fmt"
+	"net/http"
+	"time"
+)
+
+type (
+	// DebugLogCallbackFunc function type is for request and response debug log callback purposes.
+	// It gets called before Resty logs it
+	DebugLogCallbackFunc func(*DebugLog)
+
+	// DebugLogFormatterFunc function type is used to implement debug log formatting.
+	// See out of the box [DebugLogStringFormatter], [DebugLogJSONFormatter]
+	DebugLogFormatterFunc func(*DebugLog) string
+
+	// DebugLog struct is used to collect details from Resty request and response
+	// for debug logging callback purposes.
+	DebugLog struct {
+		Request   *DebugLogRequest  `json:"request"`
+		Response  *DebugLogResponse `json:"response"`
+		TraceInfo *TraceInfo        `json:"trace_info"`
+	}
+
+	// DebugLogRequest type used to capture debug info about the [Request].
+	DebugLogRequest struct {
+		Host         string      `json:"host"`
+		URI          string      `json:"uri"`
+		Method       string      `json:"method"`
+		Proto        string      `json:"proto"`
+		Header       http.Header `json:"header"`
+		CurlCmd      string      `json:"curl_cmd"`
+		RetryTraceID string      `json:"retry_trace_id"`
+		Attempt      int         `json:"attempt"`
+		Body         string      `json:"body"`
+	}
+
+	// DebugLogResponse type used to capture debug info about the [Response].
+	DebugLogResponse struct {
+		StatusCode int           `json:"status_code"`
+		Status     string        `json:"status"`
+		Proto      string        `json:"proto"`
+		ReceivedAt time.Time     `json:"received_at"`
+		Duration   time.Duration `json:"duration"`
+		Size       int64         `json:"size"`
+		Header     http.Header   `json:"header"`
+		Body       string        `json:"body"`
+	}
+)
+
+// DebugLogFormatter function formats the given debug log info in human readable
+// format.
+//
+// This is the default debug log formatter in the Resty.
+func DebugLogFormatter(dl *DebugLog) string {
+	debugLog := "\n==============================================================================\n"
+
+	req := dl.Request
+	if len(req.CurlCmd) > 0 {
+		debugLog += "~~~ REQUEST(CURL) ~~~\n" +
+			fmt.Sprintf("	%v\n", req.CurlCmd)
+	}
+	debugLog += "~~~ REQUEST ~~~\n" +
+		fmt.Sprintf("%s  %s  %s\n", req.Method, req.URI, req.Proto) +
+		fmt.Sprintf("HOST   : %s\n", req.Host) +
+		fmt.Sprintf("HEADERS:\n%s\n", composeHeaders(req.Header)) +
+		fmt.Sprintf("BODY   :\n%v\n", req.Body) +
+		"------------------------------------------------------------------------------\n"
+	if len(req.RetryTraceID) > 0 {
+		debugLog += fmt.Sprintf("RETRY TRACE ID: %s\n", req.RetryTraceID) +
+			fmt.Sprintf("ATTEMPT       : %d\n", req.Attempt) +
+			"------------------------------------------------------------------------------\n"
+	}
+
+	res := dl.Response
+	debugLog += "~~~ RESPONSE ~~~\n" +
+		fmt.Sprintf("STATUS       : %s\n", res.Status) +
+		fmt.Sprintf("PROTO        : %s\n", res.Proto) +
+		fmt.Sprintf("RECEIVED AT  : %v\n", res.ReceivedAt.Format(time.RFC3339Nano)) +
+		fmt.Sprintf("DURATION     : %v\n", res.Duration) +
+		"HEADERS      :\n" +
+		composeHeaders(res.Header) + "\n" +
+		fmt.Sprintf("BODY         :\n%v\n", res.Body)
+	if dl.TraceInfo != nil {
+		debugLog += "------------------------------------------------------------------------------\n"
+		debugLog += fmt.Sprintf("%v\n", dl.TraceInfo)
+	}
+	debugLog += "==============================================================================\n"
+
+	return debugLog
+}
+
+// DebugLogJSONFormatter function formats the given debug log info in JSON format.
+func DebugLogJSONFormatter(dl *DebugLog) string {
+	return toJSON(dl)
+}
+
+func debugLogger(c *Client, res *Response) {
+	req := res.Request
+	if !req.Debug {
+		return
+	}
+
+	rdl := &DebugLogResponse{
+		StatusCode: res.StatusCode(),
+		Status:     res.Status(),
+		Proto:      res.Proto(),
+		ReceivedAt: res.ReceivedAt(),
+		Duration:   res.Time(),
+		Size:       res.Size(),
+		Header:     sanitizeHeaders(res.Header().Clone()),
+		Body:       res.fmtBodyString(res.Request.DebugBodyLimit),
+	}
+
+	dl := &DebugLog{
+		Request:  req.values[debugRequestLogKey].(*DebugLogRequest),
+		Response: rdl,
+	}
+
+	if res.Request.IsTrace {
+		ti := req.TraceInfo()
+		dl.TraceInfo = &ti
+	}
+
+	dblCallback := c.debugLogCallbackFunc()
+	if dblCallback != nil {
+		dblCallback(dl)
+	}
+
+	formatterFunc := c.debugLogFormatterFunc()
+	if formatterFunc != nil {
+		debugLog := formatterFunc(dl)
+		req.log.Debugf("%s", debugLog)
+	}
+}
+
+const debugRequestLogKey = "__restyDebugRequestLog"
+
+func prepareRequestDebugInfo(c *Client, r *Request) {
+	if !r.Debug {
+		return
+	}
+
+	rr := r.RawRequest
+	rh := rr.Header.Clone()
+	if c.Client().Jar != nil {
+		for _, cookie := range c.Client().Jar.Cookies(r.RawRequest.URL) {
+			s := fmt.Sprintf("%s=%s", cookie.Name, cookie.Value)
+			if c := rh.Get(hdrCookieKey); isStringEmpty(c) {
+				rh.Set(hdrCookieKey, s)
+			} else {
+				rh.Set(hdrCookieKey, c+"; "+s)
+			}
+		}
+	}
+
+	rdl := &DebugLogRequest{
+		Host:   rr.URL.Host,
+		URI:    rr.URL.RequestURI(),
+		Method: r.Method,
+		Proto:  rr.Proto,
+		Header: sanitizeHeaders(rh),
+		Body:   r.fmtBodyString(r.DebugBodyLimit),
+	}
+	if r.generateCurlCmd && r.debugLogCurlCmd {
+		rdl.CurlCmd = r.resultCurlCmd
+	}
+	if len(r.RetryTraceID) > 0 {
+		rdl.Attempt = r.Attempt
+		rdl.RetryTraceID = r.RetryTraceID
+	}
+
+	r.initValuesMap()
+	r.values[debugRequestLogKey] = rdl
+}

middleware.go

@@ -21,8 +21,6 @@ import (
 	"strings"
 )
 
-const debugRequestLogKey = "__restyDebugRequestLog"
-
 //‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾‾
 // Request Middleware(s)
 //_______________________________________________________________________

request_test.go

@@ -1850,6 +1850,24 @@ func TestTraceInfo(t *testing.T) {
 		assertEqual(t, len(requestURLs), len(matches))
 	})
 
+	t.Run("enable trace and debug on request json formatter", func(t *testing.T) {
+		c, logBuf := dcldb()
+		c.SetBaseURL(ts.URL)
+		c.SetDebugLogFormatter(DebugLogJSONFormatter)
+
+		requestURLs := []string{"/", "/json", "/long-text", "/long-json"}
+		for _, u := range requestURLs {
+			resp, err := c.R().EnableTrace().EnableDebug().Get(u)
+			assertNil(t, err)
+			assertNotNil(t, resp)
+		}
+
+		logContent := logBuf.String()
+		regexTraceInfoHeader := regexp.MustCompile(`"trace_info":{"`)
+		matches := regexTraceInfoHeader.FindAllStringIndex(logContent, -1)
+		assertEqual(t, len(requestURLs), len(matches))
+	})
+
 	// for sake of hook funcs
 	_, _ = client.R().SetTrace(true).Get("https://httpbin.org/get")
 }

response.go

@@ -185,6 +185,10 @@ func (r *Response) fmtBodyString(sl int) string {
 		return "***** DO NOT PARSE RESPONSE - Enabled *****"
 	}
 
+	if r.Request.IsSaveResponse {
+		return "***** RESPONSE WRITTEN INTO FILE *****"
+	}
+
 	bl := len(r.bodyBytes)
 	if r.IsRead && bl == 0 {
 		return "***** RESPONSE BODY IS ALREADY READ - see Response.{Result()/Error()} *****"

resty.go

@@ -182,6 +182,7 @@ func createClient(hc *http.Client) *Client {
 
 	// Logger
 	c.SetLogger(createLogger())
+	c.SetDebugLogFormatter(DebugLogFormatter)
 
 	c.AddContentTypeEncoder(jsonKey, encodeJSON)
 	c.AddContentTypeEncoder(xmlKey, encodeXML)