From 1fbf5b84a2ffe74e76600489c930106e395d5bea Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rodrigo=20D=C3=ADez=20Villamuera?= Date: Mon, 11 Jun 2018 17:40:08 +0100 Subject: [PATCH] Added duration filter for logs --- docs/configuration/logs.md | 13 ++++- middlewares/accesslog/logger.go | 22 +++++--- middlewares/accesslog/logger_test.go | 79 +++++++++++++++++++--------- types/logs.go | 7 ++- 4 files changed, 85 insertions(+), 36 deletions(-) diff --git a/docs/configuration/logs.md b/docs/configuration/logs.md index bd76c4689..06f955fbe 100644 --- a/docs/configuration/logs.md +++ b/docs/configuration/logs.md @@ -18,6 +18,7 @@ logLevel = "INFO" [accessLog.filters] statusCodes = ["200", "300-302"] retryAttempts = true + minDuration = "10ms" [accessLog.fields] defaultMode = "keep" @@ -46,6 +47,7 @@ For more information about the CLI, see the documentation about [Traefik command --accessLog.format="json" --accessLog.filters.statusCodes="200,300-302" --accessLog.filters.retryAttempts="true" +--accessLog.filters.minDuration="10ms" --accessLog.fields.defaultMode="keep" --accessLog.fields.names="Username=drop Hostname=drop" --accessLog.fields.headers.defaultMode="keep" @@ -146,19 +148,26 @@ format = "json" [accessLog.filters] - # statusCodes keep access logs with status codes in the specified range + # statusCodes: keep access logs with status codes in the specified range # # Optional # Default: [] # statusCodes = ["200", "300-302"] - # retryAttempts keep access logs when at least one retry happened + # retryAttempts: keep access logs when at least one retry happened # # Optional # Default: false # retryAttempts = true + + # minDuration: keep access logs when request took longer than the specified duration + # + # Optional + # Default: 0 + # + minDuration = "10ms" ``` To customize logs format: diff --git a/middlewares/accesslog/logger.go b/middlewares/accesslog/logger.go index f8e3756b8..166bb2bdf 100644 --- a/middlewares/accesslog/logger.go +++ b/middlewares/accesslog/logger.go @@ -12,6 +12,7 @@ import ( "sync/atomic" "time" + "github.com/containous/flaeg/parse" "github.com/containous/traefik/log" "github.com/containous/traefik/types" "github.com/sirupsen/logrus" @@ -256,7 +257,11 @@ func (l *LogHandler) logTheRoundTrip(logDataTable *LogData, crr *captureRequestR core[DownstreamStatus] = crw.Status() - if l.keepAccessLog(crw.Status(), retryAttempts) { + // n.b. take care to perform time arithmetic using UTC to avoid errors at DST boundaries + totalDuration := time.Now().UTC().Sub(core[StartUTC].(time.Time)) + core[Duration] = totalDuration + + if l.keepAccessLog(crw.Status(), retryAttempts, totalDuration) { core[DownstreamStatusLine] = fmt.Sprintf("%03d %s", crw.Status(), http.StatusText(crw.Status())) core[DownstreamContentSize] = crw.Size() if original, ok := core[OriginContentSize]; ok { @@ -266,12 +271,9 @@ func (l *LogHandler) logTheRoundTrip(logDataTable *LogData, crr *captureRequestR } } - // n.b. take care to perform time arithmetic using UTC to avoid errors at DST boundaries - total := time.Now().UTC().Sub(core[StartUTC].(time.Time)) - core[Duration] = total - core[Overhead] = total + core[Overhead] = totalDuration if origin, ok := core[OriginDuration]; ok { - core[Overhead] = total - origin.(time.Duration) + core[Overhead] = totalDuration - origin.(time.Duration) } fields := logrus.Fields{} @@ -303,13 +305,13 @@ func (l *LogHandler) redactHeaders(headers http.Header, fields logrus.Fields, pr } } -func (l *LogHandler) keepAccessLog(statusCode, retryAttempts int) bool { +func (l *LogHandler) keepAccessLog(statusCode, retryAttempts int, duration time.Duration) bool { if l.config.Filters == nil { // no filters were specified return true } - if len(l.httpCodeRanges) == 0 && !l.config.Filters.RetryAttempts { + if len(l.httpCodeRanges) == 0 && !l.config.Filters.RetryAttempts && l.config.Filters.MinDuration == 0 { // empty filters were specified, e.g. by passing --accessLog.filters only (without other filter options) return true } @@ -322,6 +324,10 @@ func (l *LogHandler) keepAccessLog(statusCode, retryAttempts int) bool { return true } + if l.config.Filters.MinDuration > 0 && (parse.Duration(duration) > l.config.Filters.MinDuration) { + return true + } + return false } diff --git a/middlewares/accesslog/logger_test.go b/middlewares/accesslog/logger_test.go index d4bce0cf1..0657cfffb 100644 --- a/middlewares/accesslog/logger_test.go +++ b/middlewares/accesslog/logger_test.go @@ -14,6 +14,7 @@ import ( "testing" "time" + "github.com/containous/flaeg/parse" "github.com/containous/traefik/types" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -35,6 +36,7 @@ var ( testReferer = "testReferer" testUserAgent = "testUserAgent" testRetryAttempts = 2 + testStart = time.Now() ) func TestLogRotation(t *testing.T) { @@ -381,6 +383,28 @@ func TestNewLogHandlerOutputStdout(t *testing.T) { }, expectedLog: `TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 23 "testFrontend" "http://127.0.0.1/testBackend" 1ms`, }, + { + desc: "Duration filter not matching", + config: &types.AccessLog{ + FilePath: "", + Format: CommonFormat, + Filters: &types.AccessLogFilters{ + MinDuration: parse.Duration(1 * time.Hour), + }, + }, + expectedLog: ``, + }, + { + desc: "Duration filter matching", + config: &types.AccessLog{ + FilePath: "", + Format: CommonFormat, + Filters: &types.AccessLogFilters{ + MinDuration: parse.Duration(1 * time.Millisecond), + }, + }, + expectedLog: `TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 23 "testFrontend" "http://127.0.0.1/testBackend" 1ms`, + }, { desc: "Retry attempts filter matching", config: &types.AccessLog{ @@ -521,32 +545,37 @@ func TestNewLogHandlerOutputStdout(t *testing.T) { } func assertValidLogData(t *testing.T, expected string, logData []byte) { - if len(expected) > 0 { - result, err := ParseAccessLog(string(logData)) - require.NoError(t, err) - resultExpected, err := ParseAccessLog(expected) - require.NoError(t, err) - - formatErrMessage := fmt.Sprintf(` - Expected: %s - Actual: %s`, expected, string(logData)) - - require.Equal(t, len(resultExpected), len(result), formatErrMessage) - assert.Equal(t, resultExpected[ClientHost], result[ClientHost], formatErrMessage) - assert.Equal(t, resultExpected[ClientUsername], result[ClientUsername], formatErrMessage) - assert.Equal(t, resultExpected[RequestMethod], result[RequestMethod], formatErrMessage) - assert.Equal(t, resultExpected[RequestPath], result[RequestPath], formatErrMessage) - assert.Equal(t, resultExpected[RequestProtocol], result[RequestProtocol], formatErrMessage) - assert.Equal(t, resultExpected[OriginStatus], result[OriginStatus], formatErrMessage) - assert.Equal(t, resultExpected[OriginContentSize], result[OriginContentSize], formatErrMessage) - assert.Equal(t, resultExpected[RequestRefererHeader], result[RequestRefererHeader], formatErrMessage) - assert.Equal(t, resultExpected[RequestUserAgentHeader], result[RequestUserAgentHeader], formatErrMessage) - assert.Regexp(t, regexp.MustCompile("[0-9]*"), result[RequestCount], formatErrMessage) - assert.Equal(t, resultExpected[FrontendName], result[FrontendName], formatErrMessage) - assert.Equal(t, resultExpected[BackendURL], result[BackendURL], formatErrMessage) - assert.Regexp(t, regexp.MustCompile("[0-9]*ms"), result[Duration], formatErrMessage) + if len(expected) == 0 { + assert.Zero(t, len(logData)) + t.Log(string(logData)) + return } + + result, err := ParseAccessLog(string(logData)) + require.NoError(t, err) + + resultExpected, err := ParseAccessLog(expected) + require.NoError(t, err) + + formatErrMessage := fmt.Sprintf(` + Expected: %s + Actual: %s`, expected, string(logData)) + + require.Equal(t, len(resultExpected), len(result), formatErrMessage) + assert.Equal(t, resultExpected[ClientHost], result[ClientHost], formatErrMessage) + assert.Equal(t, resultExpected[ClientUsername], result[ClientUsername], formatErrMessage) + assert.Equal(t, resultExpected[RequestMethod], result[RequestMethod], formatErrMessage) + assert.Equal(t, resultExpected[RequestPath], result[RequestPath], formatErrMessage) + assert.Equal(t, resultExpected[RequestProtocol], result[RequestProtocol], formatErrMessage) + assert.Equal(t, resultExpected[OriginStatus], result[OriginStatus], formatErrMessage) + assert.Equal(t, resultExpected[OriginContentSize], result[OriginContentSize], formatErrMessage) + assert.Equal(t, resultExpected[RequestRefererHeader], result[RequestRefererHeader], formatErrMessage) + assert.Equal(t, resultExpected[RequestUserAgentHeader], result[RequestUserAgentHeader], formatErrMessage) + assert.Regexp(t, regexp.MustCompile("[0-9]*"), result[RequestCount], formatErrMessage) + assert.Equal(t, resultExpected[FrontendName], result[FrontendName], formatErrMessage) + assert.Equal(t, resultExpected[BackendURL], result[BackendURL], formatErrMessage) + assert.Regexp(t, regexp.MustCompile("[0-9]*ms"), result[Duration], formatErrMessage) } func captureStdout(t *testing.T) (out *os.File, restoreStdout func()) { @@ -608,4 +637,6 @@ func logWriterTestHandlerFunc(rw http.ResponseWriter, r *http.Request) { logDataTable.Core[OriginStatus] = testStatus logDataTable.Core[OriginContentSize] = testContentSize logDataTable.Core[RetryAttempts] = testRetryAttempts + logDataTable.Core[StartUTC] = testStart.UTC() + logDataTable.Core[StartLocal] = testStart.Local() } diff --git a/types/logs.go b/types/logs.go index 22266bff8..374d3f700 100644 --- a/types/logs.go +++ b/types/logs.go @@ -3,6 +3,8 @@ package types import ( "fmt" "strings" + + "github.com/containous/flaeg/parse" ) const ( @@ -31,8 +33,9 @@ type AccessLog struct { // AccessLogFilters holds filters configuration type AccessLogFilters struct { - StatusCodes StatusCodes `json:"statusCodes,omitempty" description:"Keep access logs with status codes in the specified range" export:"true"` - RetryAttempts bool `json:"retryAttempts,omitempty" description:"Keep access logs when at least one retry happened" export:"true"` + StatusCodes StatusCodes `json:"statusCodes,omitempty" description:"Keep access logs with status codes in the specified range" export:"true"` + RetryAttempts bool `json:"retryAttempts,omitempty" description:"Keep access logs when at least one retry happened" export:"true"` + MinDuration parse.Duration `json:"duration,omitempty" description:"Keep access logs when request took longer than the specified duration" export:"true"` } // FieldHeaders holds configuration for access log headers