diff --git a/middlewares/accesslog/logdata.go b/middlewares/accesslog/logdata.go index a89701950..55c364b40 100644 --- a/middlewares/accesslog/logdata.go +++ b/middlewares/accesslog/logdata.go @@ -68,6 +68,8 @@ const ( GzipRatio = "GzipRatio" // Overhead is the map key used for the processing time overhead caused by Traefik. Overhead = "Overhead" + // RetryAttempts is the map key used for the amount of attempts the request was retried. + RetryAttempts = "RetryAttempts" ) // These are written out in the default case when no config is provided to specify keys of interest. @@ -110,6 +112,7 @@ func init() { allCoreKeys[GzipRatio] = struct{}{} allCoreKeys[StartLocal] = struct{}{} allCoreKeys[Overhead] = struct{}{} + allCoreKeys[RetryAttempts] = struct{}{} } // CoreLogData holds the fields computed from the request/response. diff --git a/middlewares/accesslog/logger.go b/middlewares/accesslog/logger.go index 5c4ff3427..fc5d52adf 100644 --- a/middlewares/accesslog/logger.go +++ b/middlewares/accesslog/logger.go @@ -180,9 +180,11 @@ func usernameIfPresent(theURL *url.URL) string { // Logging handler to log frontend name, backend name, and elapsed time func (l *LogHandler) logTheRoundTrip(logDataTable *LogData, crr *captureRequestReader, crw *captureResponseWriter) { - core := logDataTable.Core + if core[RetryAttempts] == nil { + core[RetryAttempts] = 0 + } if crr != nil { core[RequestContentSize] = crr.count } diff --git a/middlewares/accesslog/logger_test.go b/middlewares/accesslog/logger_test.go index 87fd37119..e6854a539 100644 --- a/middlewares/accesslog/logger_test.go +++ b/middlewares/accesslog/logger_test.go @@ -33,6 +33,7 @@ var ( testMethod = "POST" testReferer = "testReferer" testUserAgent = "testUserAgent" + testRetryAttempts = 2 ) func TestLoggerCLF(t *testing.T) { @@ -91,6 +92,7 @@ func TestLoggerJSON(t *testing.T) { RequestCount, Duration, Overhead, + RetryAttempts, "time", "StartLocal", "StartUTC", @@ -150,6 +152,8 @@ func TestLoggerJSON(t *testing.T) { assertCount++ assert.NotZero(t, jsonData[Overhead].(float64)) assertCount++ + assert.Equal(t, float64(testRetryAttempts), jsonData[RetryAttempts].(float64)) + assertCount++ assert.NotEqual(t, "", jsonData["time"].(string)) assertCount++ assert.NotEqual(t, "", jsonData["StartLocal"].(string)) @@ -275,4 +279,5 @@ func logWriterTestHandlerFunc(rw http.ResponseWriter, r *http.Request) { logDataTable.Core[BackendURL] = testBackendName logDataTable.Core[OriginStatus] = testStatus logDataTable.Core[OriginContentSize] = testContentSize + logDataTable.Core[RetryAttempts] = testRetryAttempts } diff --git a/middlewares/accesslog/save_retries.go b/middlewares/accesslog/save_retries.go new file mode 100644 index 000000000..56b19a14b --- /dev/null +++ b/middlewares/accesslog/save_retries.go @@ -0,0 +1,19 @@ +package accesslog + +import ( + "net/http" +) + +// SaveRetries is an implementation of RetryListener that stores RetryAttempts in the LogDataTable. +type SaveRetries struct{} + +// Retried implements the RetryListener interface and will be called for each retry that happens. +func (s *SaveRetries) Retried(req *http.Request, attempt int) { + // it is the request attempt x, but the retry attempt is x-1 + if attempt > 0 { + attempt-- + } + + table := GetLogDataTable(req) + table.Core[RetryAttempts] = attempt +} diff --git a/middlewares/accesslog/save_retries_test.go b/middlewares/accesslog/save_retries_test.go new file mode 100644 index 000000000..add4cc28f --- /dev/null +++ b/middlewares/accesslog/save_retries_test.go @@ -0,0 +1,48 @@ +package accesslog + +import ( + "context" + "fmt" + "net/http" + "net/http/httptest" + "testing" +) + +func TestSaveRetries(t *testing.T) { + tests := []struct { + requestAttempt int + wantRetryAttemptsInLog int + }{ + { + requestAttempt: 0, + wantRetryAttemptsInLog: 0, + }, + { + requestAttempt: 1, + wantRetryAttemptsInLog: 0, + }, + { + requestAttempt: 3, + wantRetryAttemptsInLog: 2, + }, + } + + for _, test := range tests { + test := test + + t.Run(fmt.Sprintf("%d retries", test.requestAttempt), func(t *testing.T) { + t.Parallel() + saveRetries := &SaveRetries{} + + logDataTable := &LogData{Core: make(CoreLogData)} + req := httptest.NewRequest(http.MethodGet, "/some/path", nil) + reqWithDataTable := req.WithContext(context.WithValue(req.Context(), DataTableKey, logDataTable)) + + saveRetries.Retried(reqWithDataTable, test.requestAttempt) + + if logDataTable.Core[RetryAttempts] != test.wantRetryAttemptsInLog { + t.Errorf("got %v in logDataTable, want %v", logDataTable.Core[RetryAttempts], test.wantRetryAttemptsInLog) + } + }) + } +} diff --git a/middlewares/metrics.go b/middlewares/metrics.go index e83a0460f..c76c7f0ad 100644 --- a/middlewares/metrics.go +++ b/middlewares/metrics.go @@ -56,6 +56,6 @@ type MetricsRetryListener struct { } // Retried tracks the retry in the RequestMetrics implementation. -func (m *MetricsRetryListener) Retried(attempt int) { +func (m *MetricsRetryListener) Retried(req *http.Request, attempt int) { m.retryMetrics.RetriesCounter().With("backend", m.backendName).Add(1) } diff --git a/middlewares/metrics_test.go b/middlewares/metrics_test.go index 483da765e..21a3e255b 100644 --- a/middlewares/metrics_test.go +++ b/middlewares/metrics_test.go @@ -1,6 +1,8 @@ package middlewares import ( + "net/http" + "net/http/httptest" "reflect" "testing" @@ -8,10 +10,11 @@ import ( ) func TestMetricsRetryListener(t *testing.T) { + req := httptest.NewRequest(http.MethodGet, "/", nil) retryMetrics := newCollectingRetryMetrics() retryListener := NewMetricsRetryListener(retryMetrics, "backendName") - retryListener.Retried(1) - retryListener.Retried(2) + retryListener.Retried(req, 1) + retryListener.Retried(req, 2) wantCounterValue := float64(2) if retryMetrics.retryCounter.counterValue != wantCounterValue { diff --git a/middlewares/retry.go b/middlewares/retry.go index 4f2720173..71a608899 100644 --- a/middlewares/retry.go +++ b/middlewares/retry.go @@ -60,7 +60,7 @@ func (retry *Retry) ServeHTTP(rw http.ResponseWriter, r *http.Request) { } attempts++ log.Debugf("New attempt %d for request: %v", attempts, r.URL) - retry.listener.Retried(attempts) + retry.listener.Retried(r, attempts) } } @@ -93,7 +93,18 @@ func (DefaultNetErrorRecorder) Record(ctx context.Context) { type RetryListener interface { // Retried will be called when a retry happens, with the request attempt passed to it. // For the first retry this will be attempt 2. - Retried(attempt int) + Retried(req *http.Request, attempt int) +} + +// RetryListeners is a convenience type to construct a list of RetryListener and notify +// each of them about a retry attempt. +type RetryListeners []RetryListener + +// Retried exists to implement the RetryListener interface. It calls Retried on each of its slice entries. +func (l RetryListeners) Retried(req *http.Request, attempt int) { + for _, retryListener := range l { + retryListener.Retried(req, attempt) + } } // retryResponseRecorder is an implementation of http.ResponseWriter that diff --git a/middlewares/retry_test.go b/middlewares/retry_test.go index fca396da3..b38163dbe 100644 --- a/middlewares/retry_test.go +++ b/middlewares/retry_test.go @@ -89,6 +89,21 @@ func TestDefaultNetErrorRecorderNilValue(t *testing.T) { } } +func TestRetryListeners(t *testing.T) { + req := httptest.NewRequest(http.MethodGet, "/", nil) + retryListeners := RetryListeners{&countingRetryListener{}, &countingRetryListener{}} + + retryListeners.Retried(req, 1) + retryListeners.Retried(req, 1) + + for _, retryListener := range retryListeners { + listener := retryListener.(*countingRetryListener) + if listener.timesCalled != 2 { + t.Errorf("retry listener was called %d times, want %d", listener.timesCalled, 2) + } + } +} + // networkFailingHTTPHandler is an http.Handler implementation you can use to test retries. type networkFailingHTTPHandler struct { netErrorRecorder NetErrorRecorder @@ -116,6 +131,6 @@ type countingRetryListener struct { timesCalled int } -func (l *countingRetryListener) Retried(attempt int) { +func (l *countingRetryListener) Retried(req *http.Request, attempt int) { l.timesCalled++ } diff --git a/server/server.go b/server/server.go index 1069588ca..0cc19e053 100644 --- a/server/server.go +++ b/server/server.go @@ -908,9 +908,10 @@ func (server *Server) loadConfig(configurations types.Configurations, globalConf } if globalConfiguration.Retry != nil { - retryListener := middlewares.NewMetricsRetryListener(server.metricsRegistry, frontend.Backend) - lb = registerRetryMiddleware(lb, globalConfiguration, config, frontend.Backend, retryListener) + countServers := len(config.Backends[frontend.Backend].Servers) + lb = server.buildRetryMiddleware(lb, globalConfiguration, countServers, frontend.Backend) } + if server.metricsRegistry.IsEnabled() { n.Use(middlewares.NewMetricsWrapper(server.metricsRegistry, frontend.Backend)) } @@ -1187,20 +1188,21 @@ func stopMetricsClients() { metrics.StopStatsd() } -func registerRetryMiddleware( - httpHandler http.Handler, - globalConfig configuration.GlobalConfiguration, - config *types.Configuration, - backend string, - listener middlewares.RetryListener, -) http.Handler { - retries := len(config.Backends[backend].Servers) - if globalConfig.Retry.Attempts > 0 { - retries = globalConfig.Retry.Attempts +func (server *Server) buildRetryMiddleware(handler http.Handler, globalConfig configuration.GlobalConfiguration, countServers int, backendName string) http.Handler { + retryListeners := middlewares.RetryListeners{} + if server.metricsRegistry.IsEnabled() { + retryListeners = append(retryListeners, middlewares.NewMetricsRetryListener(server.metricsRegistry, backendName)) + } + if server.accessLoggerMiddleware != nil { + retryListeners = append(retryListeners, &accesslog.SaveRetries{}) } - httpHandler = middlewares.NewRetry(retries, httpHandler, listener) - log.Debugf("Creating retries max attempts %d", retries) + retryAttempts := countServers + if globalConfig.Retry.Attempts > 0 { + retryAttempts = globalConfig.Retry.Attempts + } - return httpHandler + log.Debugf("Creating retries max attempts %d", retryAttempts) + + return middlewares.NewRetry(retryAttempts, handler, retryListeners) } diff --git a/server/server_test.go b/server/server_test.go index a6fb23e1d..876837b3b 100644 --- a/server/server_test.go +++ b/server/server_test.go @@ -495,74 +495,6 @@ func TestConfigureBackends(t *testing.T) { } } -func TestRegisterRetryMiddleware(t *testing.T) { - testCases := []struct { - name string - globalConfig configuration.GlobalConfiguration - countServers int - expectedRetries int - }{ - { - name: "configured retry attempts", - globalConfig: configuration.GlobalConfiguration{ - Retry: &configuration.Retry{ - Attempts: 3, - }, - }, - expectedRetries: 3, - }, - { - name: "retry attempts defaults to server amount", - globalConfig: configuration.GlobalConfiguration{ - Retry: &configuration.Retry{}, - }, - expectedRetries: 2, - }, - } - - for _, tc := range testCases { - tc := tc - t.Run(tc.name, func(t *testing.T) { - t.Parallel() - - var retryListener middlewares.RetryListener - httpHandler := okHTTPHandler{} - dynamicConfig := &types.Configuration{ - Backends: map[string]*types.Backend{ - "backend": { - Servers: map[string]types.Server{ - "server": { - URL: "http://localhost", - }, - "server2": { - URL: "http://localhost", - }, - }, - }, - }, - } - - httpHandlerWithRetry := registerRetryMiddleware(httpHandler, tc.globalConfig, dynamicConfig, "backend", retryListener) - - retry, ok := httpHandlerWithRetry.(*middlewares.Retry) - if !ok { - t.Fatalf("httpHandler was not decorated with retry httpHandler, got %#v", httpHandlerWithRetry) - } - - expectedRetry := middlewares.NewRetry(tc.expectedRetries, httpHandler, retryListener) - if !reflect.DeepEqual(retry, expectedRetry) { - t.Errorf("retry httpHandler was not instantiated correctly, got %#v want %#v", retry, expectedRetry) - } - }) - } -} - -type okHTTPHandler struct{} - -func (okHTTPHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) -} - func TestServerEntrypointWhitelistConfig(t *testing.T) { tests := []struct { desc string