Merge pull request #95 from deploymenttheory/dev

Dev

Author: ShocOne

httpclient/httpclient_auth_bearer_token.go

@@ -9,7 +9,6 @@ import (
 	"net/http"
 	"time"
 
-	"github.com/deploymenttheory/go-api-http-client/errors"
 	"github.com/deploymenttheory/go-api-http-client/logger"
 	"go.uber.org/zap"
 )
@@ -40,21 +39,21 @@ func (c *Client) ObtainToken(log logger.Logger) error {
 
 	req, err := http.NewRequest("POST", authenticationEndpoint, nil)
 	if err != nil {
-		log.Error("Failed to create new request for token", zap.Error(err))
+		log.LogError("POST", authenticationEndpoint, 0, err, "Failed to create new request for token")
 		return err
 	}
 	req.SetBasicAuth(c.BearerTokenAuthCredentials.Username, c.BearerTokenAuthCredentials.Password)
 
 	resp, err := c.httpClient.Do(req)
 	if err != nil {
-		log.Error("Failed to make request for token", zap.Error(err))
+		log.LogError("POST", authenticationEndpoint, 0, err, "Failed to make request for token")
 		return err
 	}
 	defer resp.Body.Close()
 
 	if resp.StatusCode != http.StatusOK {
-		log.Warn("Received non-OK response while obtaining token", zap.Int("StatusCode", resp.StatusCode))
-		return errors.HandleAPIError(resp, log)
+		log.Error("Received non-OK response while obtaining token", zap.Int("StatusCode", resp.StatusCode))
+		return err
 	}
 
 	tokenResp := &TokenResponse{}
@@ -101,7 +100,7 @@ func (c *Client) RefreshToken(log logger.Logger) error {
 
 	if resp.StatusCode != http.StatusOK {
 		log.Warn("Token refresh response status is not OK", zap.Int("StatusCode", resp.StatusCode))
-		return errors.HandleAPIError(resp, log)
+		return err
 	}
 
 	tokenResp := &TokenResponse{}

httpclient/httpclient_mocklogger.go

@@ -2,6 +2,8 @@
 package httpclient
 
 import (
+	"time"
+
 	"github.com/deploymenttheory/go-api-http-client/logger"
 	"github.com/stretchr/testify/mock"
 	"go.uber.org/zap"
@@ -28,6 +30,8 @@ func (m *MockLogger) SetLevel(level logger.LogLevel) {
 	m.Called(level)
 }
 
+// Mock implementations for unstructured logging methods
+
 func (m *MockLogger) Debug(msg string, fields ...zap.Field) {
 	m.Called(msg, fields)
 }
@@ -40,7 +44,6 @@ func (m *MockLogger) Warn(msg string, fields ...zap.Field) {
 	m.Called(msg, fields)
 }
 
-// Error method
 func (m *MockLogger) Error(msg string, fields ...zap.Field) error {
 	args := m.Called(msg, fields)
 	return args.Error(0)
@@ -63,3 +66,29 @@ func (m *MockLogger) GetLogLevel() logger.LogLevel {
 	args := m.Called()
 	return args.Get(0).(logger.LogLevel)
 }
+
+// Mock implementations for structured logging methods
+
+func (m *MockLogger) LogRequestStart(requestID string, userID string, method string, url string, headers map[string][]string) {
+	m.Called(requestID, userID, method, url, headers)
+}
+
+func (m *MockLogger) LogRequestEnd(method string, url string, statusCode int, duration time.Duration) {
+	m.Called(method, url, statusCode, duration)
+}
+
+func (m *MockLogger) LogError(method string, url string, statusCode int, err error, stacktrace string) {
+	m.Called(method, url, statusCode, err, stacktrace)
+}
+
+func (m *MockLogger) LogRetryAttempt(method string, url string, attempt int, reason string, waitDuration time.Duration, err error) {
+	m.Called(method, url, attempt, reason, waitDuration, err)
+}
+
+func (m *MockLogger) LogRateLimiting(method string, url string, retryAfter string, waitDuration time.Duration) {
+	m.Called(method, url, retryAfter, waitDuration)
+}
+
+func (m *MockLogger) LogResponse(method string, url string, statusCode int, responseBody string, responseHeaders map[string][]string, duration time.Duration) {
+	m.Called(method, url, statusCode, responseBody, responseHeaders, duration)
+}

httpclient/httpclient_request.go

@@ -7,8 +7,8 @@ import (
 	"net/http"
 	"time"
 
-	"github.com/deploymenttheory/go-api-http-client/errors"
 	"github.com/deploymenttheory/go-api-http-client/logger"
+	"github.com/deploymenttheory/go-api-http-client/status"
 	"github.com/google/uuid"
 	"go.uber.org/zap"
 )
@@ -153,71 +153,66 @@ func (c *Client) executeRequestWithRetries(method, endpoint string, body, out in
 	headerManager.SetRequestHeaders(endpoint)
 	headerManager.LogHeaders(c)
 
-	// Define a retry deadline based on the client's total retry duration configuration
+	// Calculate the deadline for all retry attempts based on the client configuration.
 	totalRetryDeadline := time.Now().Add(c.clientConfig.ClientOptions.TotalRetryDuration)
 
+	// Execute the HTTP request with retries
 	var resp *http.Response
 	var retryCount int
-	for time.Now().Before(totalRetryDeadline) { // Check if the current time is before the total retry deadline
-		req = req.WithContext(ctx)
+	var requestStartTime = time.Now()
+
+	for time.Now().Before(totalRetryDeadline) {
 		resp, err = c.do(req, log, method, endpoint)
-		// Check for successful status code
-		if err == nil && resp.StatusCode >= 200 && resp.StatusCode < 400 {
-			if resp.StatusCode >= 300 {
-				log.Warn("Redirect response received", zap.Int("status_code", resp.StatusCode), zap.String("location", resp.Header.Get("Location")))
-			}
-			// Handle the response as successful, even if it's a redirect.
+
+		// Successful response handling
+		if err == nil && resp.StatusCode >= 200 && resp.StatusCode < 300 {
+			log.LogRequestEnd(method, endpoint, resp.StatusCode, time.Since(requestStartTime))
 			return resp, c.handleSuccessResponse(resp, out, log, method, endpoint)
 		}
 
-		// Leverage TranslateStatusCode for more descriptive error logging
-		statusMessage := errors.TranslateStatusCode(resp)
-
-		// Check for non-retryable errors
-		if resp != nil && errors.IsNonRetryableStatusCode(resp) {
-			log.Warn("Non-retryable error received", zap.Int("status_code", resp.StatusCode), zap.String("status_message", statusMessage))
-			return resp, errors.HandleAPIError(resp, log)
+		// Log and handle non-retryable errors immediately without retrying
+		if resp != nil && status.IsNonRetryableStatusCode(resp) {
+			log.LogError(method, endpoint, resp.StatusCode, err, status.TranslateStatusCode(resp))
+			return resp, err
 		}
 
-		// Parsing rate limit headers if a rate-limit error is detected
-		if errors.IsRateLimitError(resp) {
+		// Handle rate-limiting errors by parsing the 'Retry-After' header and waiting before the next retry
+		if status.IsRateLimitError(resp) {
 			waitDuration := parseRateLimitHeaders(resp, log)
-			if waitDuration > 0 {
-				log.Warn("Rate limit encountered, waiting before retrying", zap.Duration("waitDuration", waitDuration))
-				time.Sleep(waitDuration)
-				continue // Continue to next iteration after waiting
-			}
+			log.LogRateLimiting(method, endpoint, resp.Header.Get("Retry-After"), waitDuration)
+			time.Sleep(waitDuration)
+			continue
 		}
 
-		// Handling retryable errors with exponential backoff
-		if errors.IsTransientError(resp) {
+		// Retry the request for transient errors using exponential backoff with jitter
+		if status.IsTransientError(resp) {
 			retryCount++
 			if retryCount > c.clientConfig.ClientOptions.MaxRetryAttempts {
-				log.Warn("Max retry attempts reached", zap.String("method", method), zap.String("endpoint", endpoint))
-				break // Stop retrying if max attempts are reached
+				// Log max retry attempts reached with structured logging
+				log.LogError(method, endpoint, resp.StatusCode, err, "Max retry attempts reached")
+				break
 			}
 			waitDuration := calculateBackoff(retryCount)
-			log.Warn("Retrying request due to transient error", zap.String("method", method), zap.String("endpoint", endpoint), zap.Int("retryCount", retryCount), zap.Duration("waitDuration", waitDuration), zap.Error(err))
-			time.Sleep(waitDuration) // Wait before retrying
-			continue                 // Continue to next iteration after waiting
+			log.LogRetryAttempt(method, endpoint, retryCount, "Transient error", waitDuration, err)
+			time.Sleep(waitDuration)
+			continue
 		}
 
-		// Handle error responses
-		if err != nil || !errors.IsRetryableStatusCode(resp.StatusCode) {
-			if apiErr := errors.HandleAPIError(resp, log); apiErr != nil {
-				err = apiErr
-			}
-			log.Error("API error", zap.String("status_message", statusMessage), zap.Error(err))
+		// Log non-retryable API errors and break the retry loop
+		if err != nil || !status.IsRetryableStatusCode(resp.StatusCode) {
+			log.LogError(method, endpoint, resp.StatusCode, err, status.TranslateStatusCode(resp))
 			break
 		}
 	}
 
-	// Handles final non-API error.
+	// Final error handling after all retries are exhausted
 	if err != nil {
+		// Log the final error after retries with structured logging
+		log.LogError(method, endpoint, 0, err, "Final error after retries")
 		return nil, err
 	}
 
-	return resp, errors.HandleAPIError(resp, log)
+	return resp, nil
 }
 
 // executeRequest executes an HTTP request using the specified method, endpoint, and request body without implementing

logger/zaplogger_structured_messaging.go renamed to logger/zaplogger_log_levels.go

@@ -0,0 +1,111 @@
+package logger
+
+import (
+	"time"
+
+	"go.uber.org/zap"
+)
+
+// LogRequestStart logs the initiation of an HTTP request if the current log level permits.
+func (d *defaultLogger) LogRequestStart(requestID string, userID string, method string, url string, headers map[string][]string) {
+	if d.logLevel <= LogLevelInfo {
+		fields := []zap.Field{
+			zap.String("event", "request_start"),
+			zap.String("method", method),
+			zap.String("url", url),
+			zap.String("request_id", requestID),
+			zap.String("user_id", userID),
+			zap.Reflect("headers", headers),
+		}
+		d.logger.Info("HTTP request started", fields...)
+	}
+}
+
+// LogRequestEnd logs the completion of an HTTP request if the current log level permits.
+func (d *defaultLogger) LogRequestEnd(method string, url string, statusCode int, duration time.Duration) {
+	if d.logLevel <= LogLevelInfo {
+		fields := []zap.Field{
+			zap.String("event", "request_end"),
+			zap.String("method", method),
+			zap.String("url", url),
+			zap.Int("status_code", statusCode),
+			zap.Duration("duration", duration),
+		}
+		d.logger.Info("HTTP request completed", fields...)
+	}
+}
+
+// LogError logs an error that occurs during the processing of an HTTP request if the current log level permits.
+func (d *defaultLogger) LogError(method string, url string, statusCode int, err error, stacktrace string) {
+	if d.logLevel <= LogLevelError {
+		fields := []zap.Field{
+			zap.String("event", "request_error"),
+			zap.String("method", method),
+			zap.String("url", url),
+			zap.Int("status_code", statusCode),
+			zap.String("error_message", err.Error()),
+			zap.String("stacktrace", stacktrace),
+		}
+		d.logger.Error("Error during HTTP request", fields...)
+	}
+}
+
+// LogAuthTokenError logs issues encountered during the authentication token acquisition process.
+func (d *defaultLogger) LogAuthTokenError(method string, url string, statusCode int, err error) {
+	if d.logLevel <= LogLevelError {
+		fields := []zap.Field{
+			zap.String("event", "auth_token_error"),
+			zap.String("method", method),
+			zap.String("url", url),
+			zap.Int("status_code", statusCode),
+			zap.String("error_message", err.Error()),
+		}
+		d.logger.Error("Error obtaining authentication token", fields...)
+	}
+}
+
+// LogRetryAttempt logs a retry attempt for an HTTP request if the current log level permits, including wait duration and the error that triggered the retry.
+func (d *defaultLogger) LogRetryAttempt(method string, url string, attempt int, reason string, waitDuration time.Duration, err error) {
+	if d.logLevel <= LogLevelWarn {
+		fields := []zap.Field{
+			zap.String("event", "retry_attempt"),
+			zap.String("method", method),
+			zap.String("url", url),
+			zap.Int("attempt", attempt),
+			zap.String("reason", reason),
+			zap.Duration("waitDuration", waitDuration),
+			zap.String("error_message", err.Error()),
+		}
+		d.logger.Warn("HTTP request retry", fields...)
+	}
+}
+
+// LogRateLimiting logs when an HTTP request is rate-limited, including the HTTP method, URL, the value of the 'Retry-After' header, and the actual wait duration.
+func (d *defaultLogger) LogRateLimiting(method string, url string, retryAfter string, waitDuration time.Duration) {
+	if d.logLevel <= LogLevelWarn {
+		fields := []zap.Field{
+			zap.String("event", "rate_limited"),
+			zap.String("method", method),
+			zap.String("url", url),
+			zap.String("retry_after", retryAfter),
+			zap.Duration("wait_duration", waitDuration),
+		}
+		d.logger.Warn("Rate limit encountered, waiting before retrying", fields...)
+	}
+}
+
+// LogResponse logs details about an HTTP response if the current log level permits.
+func (d *defaultLogger) LogResponse(method string, url string, statusCode int, responseBody string, responseHeaders map[string][]string, duration time.Duration) {
+	if d.logLevel <= LogLevelInfo {
+		fields := []zap.Field{
+			zap.String("event", "response_received"),
+			zap.String("method", method),
+			zap.String("url", url),
+			zap.Int("status_code", statusCode),
+			zap.String("response_body", responseBody),
+			zap.Reflect("response_headers", responseHeaders),
+			zap.Duration("duration", duration),
+		}
+		d.logger.Info("HTTP response details", fields...)
+	}
+}

logger/zaplogger_structured_messaging_test.go renamed to logger/zaplogger_log_levels_test.go

@@ -0,0 +1,2 @@
+// zaplogger_structured_messaging_test.go
+package logger