add RetryAttempts to AccessLog in JSON format

This commit is contained in:
Marco Jantke 2017-08-28 12:50:02 +02:00 committed by Traefiker
parent 23cdb37165
commit dae7e7a80a
11 changed files with 130 additions and 90 deletions

View file

@ -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.

View file

@ -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
}

View file

@ -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
}

View file

@ -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
}

View file

@ -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)
}
})
}
}

View file

@ -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)
}

View file

@ -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 {

View file

@ -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

View file

@ -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++
}

View file

@ -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)
}

View file

@ -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