Implemented new logging system (#562)

* Implemented new logging system for resty migration

* Address PR Comments

* Moved template creation and parsing to top level vars

* Cleaned up doRequest and broke it up into helpers

* Addressed more PR comments

client.go

@@ -17,6 +17,7 @@ import (
 	"strconv"
 	"strings"
 	"sync"
+	"text/template"
 	"time"
 
 	"github.com/go-resty/resty/v2"
@@ -48,6 +49,20 @@ const (
 	APIDefaultCacheExpiration = time.Minute * 15
 )
 
+//nolint:unused
+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}}`))
+)
+
 var envDebug = false
 
 // Client is a wrapper around the Resty client
@@ -118,59 +133,169 @@ type RequestParams struct {
 	Response any
 }
 
-// Generic helper to execute HTTP requests using the
+// Generic helper to execute HTTP requests using the net/http package
 //
-//nolint:unused
+// nolint:unused
 func (c *httpClient) doRequest(ctx context.Context, method, url string, params RequestParams, mutators ...func(req *http.Request) error) error {
-	// Create a new HTTP request
+	req, bodyBuffer, err := c.createRequest(ctx, method, url, params)
+	if err != nil {
+		return err
+	}
+
+	if err := c.applyMutators(req, mutators); err != nil {
+		return err
+	}
+
+	if c.debug && c.logger != nil {
+		c.logRequest(req, method, url, bodyBuffer)
+	}
+
+	resp, err := c.sendRequest(req)
+	if err != nil {
+		return err
+	}
+	defer resp.Body.Close()
+
+	if err := c.checkHTTPError(resp); err != nil {
+		return err
+	}
+
+	if c.debug && c.logger != nil {
+		resp, err = c.logResponse(resp)
+		if err != nil {
+			return err
+		}
+	}
+
+	if params.Response != nil {
+		if err := c.decodeResponseBody(resp, params.Response); err != nil {
+			return err
+		}
+	}
+
+	return nil
+}
+
+// nolint:unused
+func (c *httpClient) createRequest(ctx context.Context, method, url string, params RequestParams) (*http.Request, *bytes.Buffer, error) {
 	var bodyReader io.Reader
+	var bodyBuffer *bytes.Buffer
+
 	if params.Body != nil {
-		buf := new(bytes.Buffer)
-		if err := json.NewEncoder(buf).Encode(params.Body); err != nil {
-			return fmt.Errorf("failed to encode body: %w", err)
+		bodyBuffer = new(bytes.Buffer)
+		if err := json.NewEncoder(bodyBuffer).Encode(params.Body); err != nil {
+			if c.debug && c.logger != nil {
+				c.logger.Errorf("failed to encode body: %v", err)
+			}
+			return nil, nil, fmt.Errorf("failed to encode body: %w", err)
 		}
-		bodyReader = buf
+		bodyReader = bodyBuffer
 	}
 
 	req, err := http.NewRequestWithContext(ctx, method, url, bodyReader)
 	if err != nil {
-		return fmt.Errorf("failed to create request: %w", err)
+		if c.debug && c.logger != nil {
+			c.logger.Errorf("failed to create request: %v", err)
+		}
+		return nil, nil, fmt.Errorf("failed to create request: %w", err)
 	}
 
-	// Set default headers
 	req.Header.Set("Content-Type", "application/json")
 	req.Header.Set("Accept", "application/json")
 	if c.userAgent != "" {
 		req.Header.Set("User-Agent", c.userAgent)
 	}
 
-	// Apply mutators
+	return req, bodyBuffer, nil
+}
+
+// nolint:unused
+func (c *httpClient) applyMutators(req *http.Request, mutators []func(req *http.Request) error) error {
 	for _, mutate := range mutators {
 		if err := mutate(req); err != nil {
+			if c.debug && c.logger != nil {
+				c.logger.Errorf("failed to mutate request: %v", err)
+			}
 			return fmt.Errorf("failed to mutate request: %w", err)
 		}
 	}
+	return nil
+}
+
+// nolint:unused
+func (c *httpClient) logRequest(req *http.Request, method, url string, bodyBuffer *bytes.Buffer) {
+	var reqBody string
+	if bodyBuffer != nil {
+		reqBody = bodyBuffer.String()
+	} else {
+		reqBody = "nil"
+	}
+
+	var logBuf bytes.Buffer
+	err := reqLogTemplate.Execute(&logBuf, map[string]interface{}{
+		"Method":  method,
+		"URL":     url,
+		"Headers": req.Header,
+		"Body":    reqBody,
+	})
+	if err == nil {
+		c.logger.Debugf(logBuf.String())
+	}
+}
 
-	// Send the request
+// nolint:unused
+func (c *httpClient) sendRequest(req *http.Request) (*http.Response, error) {
 	resp, err := c.httpClient.Do(req)
 	if err != nil {
-		return fmt.Errorf("failed to send request: %w", err)
+		if c.debug && c.logger != nil {
+			c.logger.Errorf("failed to send request: %v", err)
+		}
+		return nil, fmt.Errorf("failed to send request: %w", err)
 	}
-	defer resp.Body.Close()
+	return resp, nil
+}
 
-	// Check for HTTP errors
-	resp, err = coupleAPIErrorsHTTP(resp, err)
+// nolint:unused
+func (c *httpClient) checkHTTPError(resp *http.Response) error {
+	_, err := coupleAPIErrorsHTTP(resp, nil)
 	if err != nil {
+		if c.debug && c.logger != nil {
+			c.logger.Errorf("received HTTP error: %v", err)
+		}
 		return err
 	}
+	return nil
+}
 
-	// Decode the response body
-	if params.Response != nil {
-		if err := json.NewDecoder(resp.Body).Decode(params.Response); err != nil {
-			return fmt.Errorf("failed to decode response: %w", err)
-		}
+// nolint:unused
+func (c *httpClient) logResponse(resp *http.Response) (*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)
 	}
 
+	var logBuf bytes.Buffer
+	err := respLogTemplate.Execute(&logBuf, map[string]interface{}{
+		"Status":  resp.Status,
+		"Headers": resp.Header,
+		"Body":    respBody.String(),
+	})
+	if err == nil {
+		c.logger.Debugf(logBuf.String())
+	}
+
+	resp.Body = io.NopCloser(bytes.NewReader(respBody.Bytes()))
+	return resp, nil
+}
+
+// nolint:unused
+func (c *httpClient) decodeResponseBody(resp *http.Response, response interface{}) error {
+	if err := json.NewDecoder(resp.Body).Decode(response); err != nil {
+		if c.debug && c.logger != nil {
+			c.logger.Errorf("failed to decode response: %v", err)
+		}
+		return fmt.Errorf("failed to decode response: %w", err)
+	}
 	return nil
 }
 
@@ -199,6 +324,20 @@ func (c *Client) SetLogger(logger Logger) *Client {
 	return c
 }
 
+//nolint:unused
+func (c *httpClient) httpSetDebug(debug bool) *httpClient {
+	c.debug = debug
+
+	return c
+}
+
+//nolint:unused
+func (c *httpClient) httpSetLogger(logger httpLogger) *httpClient {
+	c.logger = logger
+
+	return c
+}
+
 // OnBeforeRequest adds a handler to the request body to run before the request is sent
 func (c *Client) OnBeforeRequest(m func(request *Request) error) {
 	c.resty.OnBeforeRequest(func(_ *resty.Client, req *resty.Request) error {

client_http.go

@@ -45,4 +45,6 @@ type httpClient struct {
 	cachedEntries map[string]clientCacheEntry
 	//nolint:unused
 	cachedEntryLock *sync.RWMutex
+	//nolint:unused
+	logger httpLogger
 }

client_test.go

@@ -336,3 +336,93 @@ func TestDoRequest_MutatorError(t *testing.T) {
 		t.Fatalf("expected error %q, got: %v", expectedErr, err)
 	}
 }
+
+func TestDoRequestLogging_Success(t *testing.T) {
+	var logBuffer bytes.Buffer
+	logger := createLogger()
+	logger.l.SetOutput(&logBuffer) // Redirect log output to buffer
+
+	client := &httpClient{
+		httpClient: http.DefaultClient,
+		debug:      true,
+		logger:     logger,
+	}
+
+	handler := func(w http.ResponseWriter, r *http.Request) {
+		w.WriteHeader(http.StatusOK)
+		w.Header().Set("Content-Type", "application/json")
+		_, _ = w.Write([]byte(`{"message":"success"}`))
+	}
+	server := httptest.NewServer(http.HandlerFunc(handler))
+	defer server.Close()
+
+	params := RequestParams{
+		Response: &map[string]string{},
+	}
+
+	err := client.doRequest(context.Background(), http.MethodGet, server.URL, params)
+	if err != nil {
+		t.Fatal(cmp.Diff(nil, err))
+	}
+
+	logInfo := logBuffer.String()
+	logInfoWithoutTimestamps := removeTimestamps(logInfo)
+
+	// Expected logs with templates filled in
+	expectedRequestLog := "DEBUG RESTY Sending request:\nMethod: GET\nURL: " + server.URL + "\nHeaders: map[Accept:[application/json] Content-Type:[application/json]]\nBody: "
+	expectedResponseLog := "DEBUG RESTY Received response:\nStatus: 200 OK\nHeaders: map[Content-Length:[21] Content-Type:[text/plain; charset=utf-8]]\nBody: {\"message\":\"success\"}"
+
+	if !strings.Contains(logInfo, expectedRequestLog) {
+		t.Fatalf("expected log %q not found in logs", expectedRequestLog)
+	}
+	if !strings.Contains(logInfoWithoutTimestamps, expectedResponseLog) {
+		t.Fatalf("expected log %q not found in logs", expectedResponseLog)
+	}
+}
+
+func TestDoRequestLogging_Error(t *testing.T) {
+	var logBuffer bytes.Buffer
+	logger := createLogger()
+	logger.l.SetOutput(&logBuffer) // Redirect log output to buffer
+
+	client := &httpClient{
+		httpClient: http.DefaultClient,
+		debug:      true,
+		logger:     logger,
+	}
+
+	params := RequestParams{
+		Body: map[string]interface{}{
+			"invalid": func() {},
+		},
+	}
+
+	err := client.doRequest(context.Background(), http.MethodPost, "http://example.com", params)
+	expectedErr := "failed to encode body"
+	if err == nil || !strings.Contains(err.Error(), expectedErr) {
+		t.Fatalf("expected error %q, got: %v", expectedErr, err)
+	}
+
+	logInfo := logBuffer.String()
+	expectedLog := "ERROR RESTY failed to encode body"
+
+	if !strings.Contains(logInfo, expectedLog) {
+		t.Fatalf("expected log %q not found in logs", expectedLog)
+	}
+}
+
+func removeTimestamps(log string) string {
+	lines := strings.Split(log, "\n")
+	var filteredLines []string
+	for _, line := range lines {
+		// Find the index of the "Date:" substring
+		if index := strings.Index(line, "Date:"); index != -1 {
+			// Cut off everything after "Date:"
+			trimmedLine := strings.TrimSpace(line[:index])
+			filteredLines = append(filteredLines, trimmedLine+"]")
+		} else {
+			filteredLines = append(filteredLines, line)
+		}
+	}
+	return strings.Join(filteredLines, "\n")
+}

logger.go

@@ -0,0 +1,51 @@
+package linodego
+
+import (
+	"log"
+	"os"
+)
+
+//nolint:unused
+type httpLogger interface {
+	Errorf(format string, v ...interface{})
+	Warnf(format string, v ...interface{})
+	Debugf(format string, v ...interface{})
+}
+
+//nolint:unused
+type logger struct {
+	l *log.Logger
+}
+
+//nolint:unused
+func createLogger() *logger {
+	l := &logger{l: log.New(os.Stderr, "", log.Ldate|log.Lmicroseconds)}
+	return l
+}
+
+//nolint:unused
+var _ httpLogger = (*logger)(nil)
+
+//nolint:unused
+func (l *logger) Errorf(format string, v ...interface{}) {
+	l.output("ERROR RESTY "+format, v...)
+}
+
+//nolint:unused
+func (l *logger) Warnf(format string, v ...interface{}) {
+	l.output("WARN RESTY "+format, v...)
+}
+
+//nolint:unused
+func (l *logger) Debugf(format string, v ...interface{}) {
+	l.output("DEBUG RESTY "+format, v...)
+}
+
+//nolint:unused
+func (l *logger) output(format string, v ...interface{}) { //nolint:goprintffuncname
+	if len(v) == 0 {
+		l.l.Print(format)
+		return
+	}
+	l.l.Printf(format, v...)
+}