Added duration filter for logs

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:

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
+		core[Overhead] = totalDuration
-		total := time.Now().UTC().Sub(core[StartUTC].(time.Time))
-		core[Duration] = total
-		core[Overhead] = total
 		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
 }
 

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)
+	if len(expected) == 0 {
-		require.NoError(t, err)
+		assert.Zero(t, len(logData))
-
+		t.Log(string(logData))
-		formatErrMessage := fmt.Sprintf(`
+		return
-		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)
 	}
+
+	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()
 }

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"`
+	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"`
+	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