From 8bea266f03fdb400aa94e546211454c3ee581b58 Mon Sep 17 00:00:00 2001 From: Amirhossein Khalili Date: Mon, 21 Sep 2026 22:19:00 +0330 Subject: [PATCH] fix(logger): add logging for request retries --- backend/cmd/api/main.go | 1 + backend/internal/zarinhub/client.go | 49 ++++++++++++ backend/internal/zarinhub/client_test.go | 97 ++++++++++++++++++++++++ 3 files changed, 147 insertions(+) diff --git a/backend/cmd/api/main.go b/backend/cmd/api/main.go index e864871..2a411bb 100644 --- a/backend/cmd/api/main.go +++ b/backend/cmd/api/main.go @@ -80,6 +80,7 @@ func run(logger *slog.Logger) error { config.ZarinHubEndpoint, tokenManager, config.ZarinHubRetries, + logger, ) cardService := service.NewCardService(zarinHubClient) auditRepository := repository.NewAuditRepository(db) diff --git a/backend/internal/zarinhub/client.go b/backend/internal/zarinhub/client.go index eeb065a..1ad06fa 100644 --- a/backend/internal/zarinhub/client.go +++ b/backend/internal/zarinhub/client.go @@ -7,6 +7,7 @@ import ( "errors" "fmt" "io" + "log/slog" "net" "net/http" "time" @@ -27,6 +28,7 @@ type Client struct { tokenProvider TokenProvider maxRetries int retryWait func(ctx context.Context, delay time.Duration) bool + logger *slog.Logger } var _ service.CardToIBANClient = (*Client)(nil) @@ -41,20 +43,34 @@ func NewClient( endpointURL string, tokenProvider TokenProvider, maxRetries int, + loggers ...*slog.Logger, ) *Client { if maxRetries < 0 { maxRetries = 0 } + var logger *slog.Logger + if len(loggers) > 0 && loggers[0] != nil { + logger = loggers[0] + } + return &Client{ httpClient: httpClient, endpointURL: endpointURL, tokenProvider: tokenProvider, maxRetries: maxRetries, retryWait: waitForRetry, + logger: logger, } } +func (c *Client) log() *slog.Logger { + if c.logger != nil { + return c.logger + } + return slog.New(slog.NewTextHandler(io.Discard, nil)) +} + func isRetryable(err error) bool { return errors.Is(err, ErrTimeout) || errors.Is(err, ErrUnavailable) @@ -105,6 +121,22 @@ func (c *Client) Convert( } for attempt := 0; attempt <= c.maxRetries; attempt++ { + if attempt > 0 { + c.log().InfoContext( + ctx, + fmt.Sprintf("[RETRY] zarinhub request attempt %d", attempt), + "is_retry", true, + "retry_count", attempt, + ) + } else { + c.log().InfoContext( + ctx, + "[INITIAL] zarinhub request", + "is_retry", false, + "retry_count", 0, + ) + } + result, err = c.convertOnce( ctx, cardNumber, @@ -121,6 +153,15 @@ func (c *Client) Convert( // We already used all configured retries. if attempt == c.maxRetries { + if attempt > 0 { + c.log().ErrorContext( + ctx, + "[RETRY] zarinhub request failed: all retries exhausted", + "is_retry", true, + "retry_count", attempt, + "error", err, + ) + } return result, err } @@ -133,6 +174,14 @@ func (c *Client) Convert( } delay := retryDelay(attempt) + c.log().WarnContext( + ctx, + fmt.Sprintf("[RETRY] zarinhub request failed, retrying in %v (retry %d)", delay, attempt+1), + "is_retry", true, + "next_retry", attempt + 1, + "delay_ms", delay.Milliseconds(), + "error", err, + ) if !waitFn(ctx, delay) { if errors.Is(ctx.Err(), context.Canceled) { diff --git a/backend/internal/zarinhub/client_test.go b/backend/internal/zarinhub/client_test.go index 3e1fbc3..13f7333 100644 --- a/backend/internal/zarinhub/client_test.go +++ b/backend/internal/zarinhub/client_test.go @@ -1,12 +1,15 @@ package zarinhub import ( + "bytes" "context" "encoding/json" "errors" "fmt" + "log/slog" "net/http" "net/http/httptest" + "strings" "testing" "time" ) @@ -667,3 +670,97 @@ func TestClientStopsRetryOnContextCancellation(t *testing.T) { t.Errorf("request count = %d, want 1", requestCount) } } + +func TestClientRetryLogging(t *testing.T) { + const expectedIBAN = "IR820540102680020817909002" + requestCount := 0 + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + requestCount++ + if requestCount == 1 { + w.WriteHeader(http.StatusServiceUnavailable) + fmt.Fprint(w, `{"error":"temporary outage"}`) + return + } + + w.Header().Set("Content-Type", "application/json") + fmt.Fprintf(w, `{ + "data":{"iban":%q}, + "meta":{"isSuccess":true,"errors":[]} + }`, expectedIBAN) + })) + defer server.Close() + + var logBuf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&logBuf, nil)) + + client := NewClient( + &http.Client{Timeout: time.Second}, + server.URL, + &fakeTokenProvider{tokens: []string{"test-token"}}, + 2, + logger, + ) + client.retryWait = func(ctx context.Context, delay time.Duration) bool { + return true + } + + result, err := client.Convert(context.Background(), "6037997512345678") + if err != nil { + t.Fatalf("Convert() unexpected error = %v", err) + } + if result.IBAN != expectedIBAN { + t.Errorf("IBAN = %q, want %q", result.IBAN, expectedIBAN) + } + + logs := logBuf.String() + + if !strings.Contains(logs, "[INITIAL] zarinhub request") { + t.Errorf("expected logs to contain '[INITIAL] zarinhub request', got:\n%s", logs) + } + if !strings.Contains(logs, `"is_retry":false`) { + t.Errorf("expected logs to contain '\"is_retry\":false', got:\n%s", logs) + } + + if !strings.Contains(logs, "[RETRY] zarinhub request attempt 1") { + t.Errorf("expected logs to contain '[RETRY] zarinhub request attempt 1', got:\n%s", logs) + } + if !strings.Contains(logs, "[RETRY] zarinhub request failed, retrying in") { + t.Errorf("expected logs to contain '[RETRY] zarinhub request failed, retrying in', got:\n%s", logs) + } + if !strings.Contains(logs, `"is_retry":true`) { + t.Errorf("expected logs to contain '\"is_retry\":true', got:\n%s", logs) + } +} + +func TestClientRetryLoggingExhausted(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusServiceUnavailable) + fmt.Fprint(w, `{"error":"down"}`) + })) + defer server.Close() + + var logBuf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&logBuf, nil)) + + client := NewClient( + &http.Client{Timeout: time.Second}, + server.URL, + &fakeTokenProvider{tokens: []string{"test-token"}}, + 1, + logger, + ) + client.retryWait = func(ctx context.Context, delay time.Duration) bool { + return true + } + + _, err := client.Convert(context.Background(), "6037997512345678") + if !errors.Is(err, ErrUnavailable) { + t.Fatalf("error = %v, want ErrUnavailable", err) + } + + logs := logBuf.String() + if !strings.Contains(logs, "[RETRY] zarinhub request failed: all retries exhausted") { + t.Errorf("expected logs to contain exhausted retries message, got:\n%s", logs) + } +}