1
0
Fork 0

Ultimate Access log filter

This commit is contained in:
Michael 2018-03-14 14:12:04 +01:00 committed by Traefiker Bot
parent f99363674b
commit 8d468925d3
24 changed files with 1722 additions and 683 deletions

View file

@ -44,6 +44,10 @@ const (
RequestLine = "RequestLine"
// RequestContentSize is the map key used for the number of bytes in the request entity (a.k.a. body) sent by the client.
RequestContentSize = "RequestContentSize"
// RequestRefererHeader is the Referer header in the request
RequestRefererHeader = "request_Referer"
// RequestUserAgentHeader is the User-Agent header in the request
RequestUserAgentHeader = "request_User-Agent"
// OriginDuration is the map key used for the time taken by the origin server ('upstream') to return its response.
OriginDuration = "OriginDuration"
// OriginContentSize is the map key used for the content length specified by the origin server, or 0 if unspecified.

View file

@ -12,6 +12,7 @@ import (
"sync/atomic"
"time"
"github.com/containous/traefik/log"
"github.com/containous/traefik/types"
"github.com/sirupsen/logrus"
)
@ -32,10 +33,12 @@ const (
// LogHandler will write each request and its response to the access log.
type LogHandler struct {
logger *logrus.Logger
file *os.File
filePath string
mu sync.Mutex
logger *logrus.Logger
file *os.File
filePath string
mu sync.Mutex
httpCodeRanges types.HTTPCodeRanges
fields *types.AccessLogFields
}
// NewLogHandler creates a new LogHandler
@ -66,7 +69,24 @@ func NewLogHandler(config *types.AccessLog) (*LogHandler, error) {
Hooks: make(logrus.LevelHooks),
Level: logrus.InfoLevel,
}
return &LogHandler{logger: logger, file: file, filePath: config.FilePath}, nil
logHandler := &LogHandler{
logger: logger,
file: file,
filePath: config.FilePath,
fields: config.Fields,
}
if config.Filters != nil {
httpCodeRanges, err := types.NewHTTPCodeRanges(config.Filters.StatusCodes)
if err != nil {
log.Errorf("Failed to create new HTTP code ranges: %s", err)
} else if httpCodeRanges != nil {
logHandler.httpCodeRanges = httpCodeRanges
}
}
return logHandler, nil
}
func openAccessLogFile(filePath string) (*os.File, error) {
@ -198,45 +218,65 @@ func (l *LogHandler) logTheRoundTrip(logDataTable *LogData, crr *captureRequestR
}
core[DownstreamStatus] = crw.Status()
core[DownstreamStatusLine] = fmt.Sprintf("%03d %s", crw.Status(), http.StatusText(crw.Status()))
core[DownstreamContentSize] = crw.Size()
if original, ok := core[OriginContentSize]; ok {
o64 := original.(int64)
if o64 != crw.Size() && 0 != crw.Size() {
core[GzipRatio] = float64(o64) / float64(crw.Size())
if l.keepAccessLog(crw.Status()) {
core[DownstreamStatusLine] = fmt.Sprintf("%03d %s", crw.Status(), http.StatusText(crw.Status()))
core[DownstreamContentSize] = crw.Size()
if original, ok := core[OriginContentSize]; ok {
o64 := original.(int64)
if o64 != crw.Size() && 0 != crw.Size() {
core[GzipRatio] = float64(o64) / float64(crw.Size())
}
}
// 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
if origin, ok := core[OriginDuration]; ok {
core[Overhead] = total - origin.(time.Duration)
}
fields := logrus.Fields{}
for k, v := range logDataTable.Core {
if l.fields.Keep(k) {
fields[k] = v
}
}
l.redactHeaders(logDataTable.Request, fields, "request_")
l.redactHeaders(logDataTable.OriginResponse, fields, "origin_")
l.redactHeaders(logDataTable.DownstreamResponse, fields, "downstream_")
l.mu.Lock()
defer l.mu.Unlock()
l.logger.WithFields(fields).Println()
}
}
func (l *LogHandler) redactHeaders(headers http.Header, fields logrus.Fields, prefix string) {
for k := range headers {
v := l.fields.KeepHeader(k)
if v == types.AccessLogKeep {
fields[prefix+k] = headers.Get(k)
} else if v == types.AccessLogRedact {
fields[prefix+k] = "REDACTED"
}
}
}
// 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
if origin, ok := core[OriginDuration]; ok {
core[Overhead] = total - origin.(time.Duration)
} else {
core[Overhead] = total
func (l *LogHandler) keepAccessLog(status int) bool {
if l.httpCodeRanges == nil {
return true
}
fields := logrus.Fields{}
for k, v := range logDataTable.Core {
fields[k] = v
for _, block := range l.httpCodeRanges {
if status >= block[0] && status <= block[1] {
return true
}
}
for k := range logDataTable.Request {
fields["request_"+k] = logDataTable.Request.Get(k)
}
for k := range logDataTable.OriginResponse {
fields["origin_"+k] = logDataTable.OriginResponse.Get(k)
}
for k := range logDataTable.DownstreamResponse {
fields["downstream_"+k] = logDataTable.DownstreamResponse.Get(k)
}
l.mu.Lock()
defer l.mu.Unlock()
l.logger.WithFields(fields).Println()
return false
}
//-------------------------------------------------------------------------------------------------

View file

@ -14,56 +14,69 @@ const (
defaultValue = "-"
)
// CommonLogFormatter provides formatting in the Traefik common log format
// CommonLogFormatter provides formatting in the Træfik common log format
type CommonLogFormatter struct{}
//Format formats the log entry in the Traefik common log format
// Format formats the log entry in the Træfik common log format
func (f *CommonLogFormatter) Format(entry *logrus.Entry) ([]byte, error) {
b := &bytes.Buffer{}
timestamp := entry.Data[StartUTC].(time.Time).Format(commonLogTimeFormat)
elapsedMillis := entry.Data[Duration].(time.Duration).Nanoseconds() / 1000000
var timestamp = defaultValue
if v, ok := entry.Data[StartUTC]; ok {
timestamp = v.(time.Time).Format(commonLogTimeFormat)
}
var elapsedMillis int64
if v, ok := entry.Data[Duration]; ok {
elapsedMillis = v.(time.Duration).Nanoseconds() / 1000000
}
_, err := fmt.Fprintf(b, "%s - %s [%s] \"%s %s %s\" %v %v %s %s %v %s %s %dms\n",
entry.Data[ClientHost],
entry.Data[ClientUsername],
toLog(entry.Data, ClientHost, defaultValue, false),
toLog(entry.Data, ClientUsername, defaultValue, false),
timestamp,
entry.Data[RequestMethod],
entry.Data[RequestPath],
entry.Data[RequestProtocol],
toLog(entry.Data[OriginStatus], defaultValue),
toLog(entry.Data[OriginContentSize], defaultValue),
toLog(entry.Data["request_Referer"], `"-"`),
toLog(entry.Data["request_User-Agent"], `"-"`),
toLog(entry.Data[RequestCount], defaultValue),
toLog(entry.Data[FrontendName], defaultValue),
toLog(entry.Data[BackendURL], defaultValue),
toLog(entry.Data, RequestMethod, defaultValue, false),
toLog(entry.Data, RequestPath, defaultValue, false),
toLog(entry.Data, RequestProtocol, defaultValue, false),
toLog(entry.Data, OriginStatus, defaultValue, true),
toLog(entry.Data, OriginContentSize, defaultValue, true),
toLog(entry.Data, "request_Referer", `"-"`, true),
toLog(entry.Data, "request_User-Agent", `"-"`, true),
toLog(entry.Data, RequestCount, defaultValue, true),
toLog(entry.Data, FrontendName, defaultValue, true),
toLog(entry.Data, BackendURL, defaultValue, true),
elapsedMillis)
return b.Bytes(), err
}
func toLog(v interface{}, defaultValue string) interface{} {
if v == nil {
return defaultValue
}
switch s := v.(type) {
case string:
return quoted(s, defaultValue)
case fmt.Stringer:
return quoted(s.String(), defaultValue)
default:
return v
func toLog(fields logrus.Fields, key string, defaultValue string, quoted bool) interface{} {
if v, ok := fields[key]; ok {
if v == nil {
return defaultValue
}
switch s := v.(type) {
case string:
return toLogEntry(s, defaultValue, quoted)
case fmt.Stringer:
return toLogEntry(s.String(), defaultValue, quoted)
default:
return v
}
}
return defaultValue
}
func quoted(s string, defaultValue string) string {
func toLogEntry(s string, defaultValue string, quote bool) string {
if len(s) == 0 {
return defaultValue
}
return `"` + s + `"`
if quote {
return `"` + s + `"`
}
return s
}

View file

@ -20,20 +20,20 @@ func TestCommonLogFormatter_Format(t *testing.T) {
{
name: "OriginStatus & OriginContentSize are nil",
data: map[string]interface{}{
StartUTC: time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC),
Duration: 123 * time.Second,
ClientHost: "10.0.0.1",
ClientUsername: "Client",
RequestMethod: http.MethodGet,
RequestPath: "/foo",
RequestProtocol: "http",
OriginStatus: nil,
OriginContentSize: nil,
"request_Referer": "",
"request_User-Agent": "",
RequestCount: 0,
FrontendName: "",
BackendURL: "",
StartUTC: time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC),
Duration: 123 * time.Second,
ClientHost: "10.0.0.1",
ClientUsername: "Client",
RequestMethod: http.MethodGet,
RequestPath: "/foo",
RequestProtocol: "http",
OriginStatus: nil,
OriginContentSize: nil,
RequestRefererHeader: "",
RequestUserAgentHeader: "",
RequestCount: 0,
FrontendName: "",
BackendURL: "",
},
expectedLog: `10.0.0.1 - Client [10/Nov/2009:23:00:00 +0000] "GET /foo http" - - "-" "-" 0 - - 123000ms
`,
@ -41,20 +41,20 @@ func TestCommonLogFormatter_Format(t *testing.T) {
{
name: "all data",
data: map[string]interface{}{
StartUTC: time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC),
Duration: 123 * time.Second,
ClientHost: "10.0.0.1",
ClientUsername: "Client",
RequestMethod: http.MethodGet,
RequestPath: "/foo",
RequestProtocol: "http",
OriginStatus: 123,
OriginContentSize: 132,
"request_Referer": "referer",
"request_User-Agent": "agent",
RequestCount: nil,
FrontendName: "foo",
BackendURL: "http://10.0.0.2/toto",
StartUTC: time.Date(2009, time.November, 10, 23, 0, 0, 0, time.UTC),
Duration: 123 * time.Second,
ClientHost: "10.0.0.1",
ClientUsername: "Client",
RequestMethod: http.MethodGet,
RequestPath: "/foo",
RequestProtocol: "http",
OriginStatus: 123,
OriginContentSize: 132,
RequestRefererHeader: "referer",
RequestUserAgentHeader: "agent",
RequestCount: nil,
FrontendName: "foo",
BackendURL: "http://10.0.0.2/toto",
},
expectedLog: `10.0.0.1 - Client [10/Nov/2009:23:00:00 +0000] "GET /foo http" 123 132 "referer" "agent" - "foo" "http://10.0.0.2/toto" 123000ms
`,
@ -80,33 +80,59 @@ func TestCommonLogFormatter_Format(t *testing.T) {
func Test_toLog(t *testing.T) {
testCases := []struct {
name string
value interface{}
expectedLog interface{}
desc string
fields logrus.Fields
fieldName string
defaultValue string
quoted bool
expectedLog interface{}
}{
{
name: "",
value: 1,
expectedLog: 1,
desc: "Should return int 1",
fields: logrus.Fields{
"Powpow": 1,
},
fieldName: "Powpow",
defaultValue: defaultValue,
quoted: false,
expectedLog: 1,
},
{
name: "",
value: "foo",
expectedLog: `"foo"`,
desc: "Should return string foo",
fields: logrus.Fields{
"Powpow": "foo",
},
fieldName: "Powpow",
defaultValue: defaultValue,
quoted: true,
expectedLog: `"foo"`,
},
{
name: "",
value: nil,
expectedLog: "-",
desc: "Should return defaultValue if fieldName does not exist",
fields: logrus.Fields{
"Powpow": "foo",
},
fieldName: "",
defaultValue: defaultValue,
quoted: false,
expectedLog: "-",
},
{
desc: "Should return defaultValue if fields is nil",
fields: nil,
fieldName: "",
defaultValue: defaultValue,
quoted: false,
expectedLog: "-",
},
}
for _, test := range testCases {
test := test
t.Run(test.name, func(t *testing.T) {
t.Run(test.desc, func(t *testing.T) {
t.Parallel()
lg := toLog(test.value, defaultValue)
lg := toLog(test.fields, test.fieldName, defaultValue, test.quoted)
assert.Equal(t, test.expectedLog, lg)
})

View file

@ -15,7 +15,6 @@ import (
"time"
"github.com/containous/traefik/types"
shellwords "github.com/mattn/go-shellwords"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
)
@ -127,156 +126,392 @@ func TestLoggerCLF(t *testing.T) {
logData, err := ioutil.ReadFile(logFilePath)
require.NoError(t, err)
assertValidLogData(t, logData)
expectedLog := ` TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 1 "testFrontend" "http://127.0.0.1/testBackend" 1ms`
assertValidLogData(t, expectedLog, logData)
}
func assertString(exp string) func(t *testing.T, actual interface{}) {
return func(t *testing.T, actual interface{}) {
t.Helper()
assert.Equal(t, exp, actual)
}
}
func assertNotEqual(exp string) func(t *testing.T, actual interface{}) {
return func(t *testing.T, actual interface{}) {
t.Helper()
assert.NotEqual(t, exp, actual)
}
}
func assertFloat64(exp float64) func(t *testing.T, actual interface{}) {
return func(t *testing.T, actual interface{}) {
t.Helper()
assert.Equal(t, exp, actual)
}
}
func assertFloat64NotZero() func(t *testing.T, actual interface{}) {
return func(t *testing.T, actual interface{}) {
t.Helper()
assert.NotZero(t, actual)
}
}
func TestLoggerJSON(t *testing.T) {
tmpDir := createTempDir(t, JSONFormat)
defer os.RemoveAll(tmpDir)
logFilePath := filepath.Join(tmpDir, logFileNameSuffix)
config := &types.AccessLog{FilePath: logFilePath, Format: JSONFormat}
doLogging(t, config)
logData, err := ioutil.ReadFile(logFilePath)
require.NoError(t, err)
jsonData := make(map[string]interface{})
err = json.Unmarshal(logData, &jsonData)
require.NoError(t, err)
expectedKeys := []string{
RequestHost,
RequestAddr,
RequestMethod,
RequestPath,
RequestProtocol,
RequestPort,
RequestLine,
DownstreamStatus,
DownstreamStatusLine,
DownstreamContentSize,
OriginContentSize,
OriginStatus,
"request_Referer",
"request_User-Agent",
FrontendName,
BackendURL,
ClientUsername,
ClientHost,
ClientPort,
ClientAddr,
"level",
"msg",
"downstream_Content-Type",
RequestCount,
Duration,
Overhead,
RetryAttempts,
"time",
"StartLocal",
"StartUTC",
testCases := []struct {
desc string
config *types.AccessLog
expected map[string]func(t *testing.T, value interface{})
}{
{
desc: "default config",
config: &types.AccessLog{
FilePath: "",
Format: JSONFormat,
},
expected: map[string]func(t *testing.T, value interface{}){
RequestHost: assertString(testHostname),
RequestAddr: assertString(testHostname),
RequestMethod: assertString(testMethod),
RequestPath: assertString(testPath),
RequestProtocol: assertString(testProto),
RequestPort: assertString("-"),
RequestLine: assertString(fmt.Sprintf("%s %s %s", testMethod, testPath, testProto)),
DownstreamStatus: assertFloat64(float64(testStatus)),
DownstreamStatusLine: assertString(fmt.Sprintf("%d ", testStatus)),
DownstreamContentSize: assertFloat64(float64(len(testContent))),
OriginContentSize: assertFloat64(float64(len(testContent))),
OriginStatus: assertFloat64(float64(testStatus)),
RequestRefererHeader: assertString(testReferer),
RequestUserAgentHeader: assertString(testUserAgent),
FrontendName: assertString(testFrontendName),
BackendURL: assertString(testBackendName),
ClientUsername: assertString(testUsername),
ClientHost: assertString(testHostname),
ClientPort: assertString(fmt.Sprintf("%d", testPort)),
ClientAddr: assertString(fmt.Sprintf("%s:%d", testHostname, testPort)),
"level": assertString("info"),
"msg": assertString(""),
"downstream_Content-Type": assertString("text/plain; charset=utf-8"),
RequestCount: assertFloat64NotZero(),
Duration: assertFloat64NotZero(),
Overhead: assertFloat64NotZero(),
RetryAttempts: assertFloat64(float64(testRetryAttempts)),
"time": assertNotEqual(""),
"StartLocal": assertNotEqual(""),
"StartUTC": assertNotEqual(""),
},
},
{
desc: "default config drop all fields",
config: &types.AccessLog{
FilePath: "",
Format: JSONFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
},
},
expected: map[string]func(t *testing.T, value interface{}){
"level": assertString("info"),
"msg": assertString(""),
"time": assertNotEqual(""),
"downstream_Content-Type": assertString("text/plain; charset=utf-8"),
RequestRefererHeader: assertString(testReferer),
RequestUserAgentHeader: assertString(testUserAgent),
},
},
{
desc: "default config drop all fields and headers",
config: &types.AccessLog{
FilePath: "",
Format: JSONFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
Headers: &types.FieldHeaders{
DefaultMode: "drop",
},
},
},
expected: map[string]func(t *testing.T, value interface{}){
"level": assertString("info"),
"msg": assertString(""),
"time": assertNotEqual(""),
},
},
{
desc: "default config drop all fields and redact headers",
config: &types.AccessLog{
FilePath: "",
Format: JSONFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
Headers: &types.FieldHeaders{
DefaultMode: "redact",
},
},
},
expected: map[string]func(t *testing.T, value interface{}){
"level": assertString("info"),
"msg": assertString(""),
"time": assertNotEqual(""),
"downstream_Content-Type": assertString("REDACTED"),
RequestRefererHeader: assertString("REDACTED"),
RequestUserAgentHeader: assertString("REDACTED"),
},
},
{
desc: "default config drop all fields and headers but kept someone",
config: &types.AccessLog{
FilePath: "",
Format: JSONFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
Names: types.FieldNames{
RequestHost: "keep",
},
Headers: &types.FieldHeaders{
DefaultMode: "drop",
Names: types.FieldHeaderNames{
"Referer": "keep",
},
},
},
},
expected: map[string]func(t *testing.T, value interface{}){
RequestHost: assertString(testHostname),
"level": assertString("info"),
"msg": assertString(""),
"time": assertNotEqual(""),
RequestRefererHeader: assertString(testReferer),
},
},
}
containsKeys(t, expectedKeys, jsonData)
var assertCount int
assert.Equal(t, testHostname, jsonData[RequestHost])
assertCount++
assert.Equal(t, testHostname, jsonData[RequestAddr])
assertCount++
assert.Equal(t, testMethod, jsonData[RequestMethod])
assertCount++
assert.Equal(t, testPath, jsonData[RequestPath])
assertCount++
assert.Equal(t, testProto, jsonData[RequestProtocol])
assertCount++
assert.Equal(t, "-", jsonData[RequestPort])
assertCount++
assert.Equal(t, fmt.Sprintf("%s %s %s", testMethod, testPath, testProto), jsonData[RequestLine])
assertCount++
assert.Equal(t, float64(testStatus), jsonData[DownstreamStatus])
assertCount++
assert.Equal(t, fmt.Sprintf("%d ", testStatus), jsonData[DownstreamStatusLine])
assertCount++
assert.Equal(t, float64(len(testContent)), jsonData[DownstreamContentSize])
assertCount++
assert.Equal(t, float64(len(testContent)), jsonData[OriginContentSize])
assertCount++
assert.Equal(t, float64(testStatus), jsonData[OriginStatus])
assertCount++
assert.Equal(t, testReferer, jsonData["request_Referer"])
assertCount++
assert.Equal(t, testUserAgent, jsonData["request_User-Agent"])
assertCount++
assert.Equal(t, testFrontendName, jsonData[FrontendName])
assertCount++
assert.Equal(t, testBackendName, jsonData[BackendURL])
assertCount++
assert.Equal(t, testUsername, jsonData[ClientUsername])
assertCount++
assert.Equal(t, testHostname, jsonData[ClientHost])
assertCount++
assert.Equal(t, fmt.Sprintf("%d", testPort), jsonData[ClientPort])
assertCount++
assert.Equal(t, fmt.Sprintf("%s:%d", testHostname, testPort), jsonData[ClientAddr])
assertCount++
assert.Equal(t, "info", jsonData["level"])
assertCount++
assert.Equal(t, "", jsonData["msg"])
assertCount++
assert.Equal(t, "text/plain; charset=utf-8", jsonData["downstream_Content-Type"].(string))
assertCount++
assert.NotZero(t, jsonData[RequestCount].(float64))
assertCount++
assert.NotZero(t, jsonData[Duration].(float64))
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))
assertCount++
assert.NotEqual(t, "", jsonData["StartUTC"].(string))
assertCount++
for _, test := range testCases {
test := test
t.Run(test.desc, func(t *testing.T) {
t.Parallel()
assert.Equal(t, len(jsonData), assertCount, string(logData))
tmpDir := createTempDir(t, JSONFormat)
defer os.RemoveAll(tmpDir)
logFilePath := filepath.Join(tmpDir, logFileNameSuffix)
test.config.FilePath = logFilePath
doLogging(t, test.config)
logData, err := ioutil.ReadFile(logFilePath)
require.NoError(t, err)
jsonData := make(map[string]interface{})
err = json.Unmarshal(logData, &jsonData)
require.NoError(t, err)
assert.Equal(t, len(test.expected), len(jsonData))
for field, assertion := range test.expected {
assertion(t, jsonData[field])
}
})
}
}
func TestNewLogHandlerOutputStdout(t *testing.T) {
file, restoreStdout := captureStdout(t)
defer restoreStdout()
testCases := []struct {
desc string
config *types.AccessLog
expectedLog string
}{
{
desc: "default config",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
},
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: "Status code filter not matching",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Filters: &types.AccessLogFilters{
StatusCodes: []string{"200"},
},
},
expectedLog: ``,
},
{
desc: "Status code filter matching",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Filters: &types.AccessLogFilters{
StatusCodes: []string{"123"},
},
},
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: "Default mode keep",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "keep",
},
},
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: "Default mode keep with override",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "keep",
Names: types.FieldNames{
ClientHost: "drop",
},
},
},
expectedLog: `- - 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: "Default mode drop",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
},
},
expectedLog: `- - - [-] "- - -" - - "testReferer" "testUserAgent" - - - 0ms`,
},
{
desc: "Default mode drop with override",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
Names: types.FieldNames{
ClientHost: "drop",
ClientUsername: "keep",
},
},
},
expectedLog: `- - TestUser [-] "- - -" - - "testReferer" "testUserAgent" - - - 0ms`,
},
{
desc: "Default mode drop with header dropped",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
Names: types.FieldNames{
ClientHost: "drop",
ClientUsername: "keep",
},
Headers: &types.FieldHeaders{
DefaultMode: "drop",
},
},
},
expectedLog: `- - TestUser [-] "- - -" - - "-" "-" - - - 0ms`,
},
{
desc: "Default mode drop with header redacted",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
Names: types.FieldNames{
ClientHost: "drop",
ClientUsername: "keep",
},
Headers: &types.FieldHeaders{
DefaultMode: "redact",
},
},
},
expectedLog: `- - TestUser [-] "- - -" - - "REDACTED" "REDACTED" - - - 0ms`,
},
{
desc: "Default mode drop with header redacted",
config: &types.AccessLog{
FilePath: "",
Format: CommonFormat,
Fields: &types.AccessLogFields{
DefaultMode: "drop",
Names: types.FieldNames{
ClientHost: "drop",
ClientUsername: "keep",
},
Headers: &types.FieldHeaders{
DefaultMode: "keep",
Names: types.FieldHeaderNames{
"Referer": "redact",
},
},
},
},
expectedLog: `- - TestUser [-] "- - -" - - "REDACTED" "testUserAgent" - - - 0ms`,
},
}
config := &types.AccessLog{FilePath: "", Format: CommonFormat}
doLogging(t, config)
for _, test := range testCases {
test := test
t.Run(test.desc, func(t *testing.T) {
written, err := ioutil.ReadFile(file.Name())
require.NoError(t, err, "unable to read captured stdout from file")
require.NotZero(t, len(written), "expected access log message on stdout")
assertValidLogData(t, written)
// NOTE: It is not possible to run these cases in parallel because we capture Stdout
file, restoreStdout := captureStdout(t)
defer restoreStdout()
doLogging(t, test.config)
written, err := ioutil.ReadFile(file.Name())
require.NoError(t, err, "unable to read captured stdout from file")
assertValidLogData(t, test.expectedLog, written)
})
}
}
func assertValidLogData(t *testing.T, logData []byte) {
tokens, err := shellwords.Parse(string(logData))
require.NoError(t, err)
func assertValidLogData(t *testing.T, expected string, logData []byte) {
if len(expected) > 0 {
result, err := ParseAccessLog(string(logData))
require.NoError(t, err)
formatErrMessage := fmt.Sprintf(`
Expected: TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 1 "testFrontend" "http://127.0.0.1/testBackend" 1ms
Actual: %s
`,
string(logData))
require.Equal(t, 14, len(tokens), formatErrMessage)
assert.Equal(t, testHostname, tokens[0], formatErrMessage)
assert.Equal(t, testUsername, tokens[2], formatErrMessage)
assert.Equal(t, fmt.Sprintf("%s %s %s", testMethod, testPath, testProto), tokens[5], formatErrMessage)
assert.Equal(t, fmt.Sprintf("%d", testStatus), tokens[6], formatErrMessage)
assert.Equal(t, fmt.Sprintf("%d", len(testContent)), tokens[7], formatErrMessage)
assert.Equal(t, testReferer, tokens[8], formatErrMessage)
assert.Equal(t, testUserAgent, tokens[9], formatErrMessage)
assert.Regexp(t, regexp.MustCompile("[0-9]*"), tokens[10], formatErrMessage)
assert.Equal(t, testFrontendName, tokens[11], formatErrMessage)
assert.Equal(t, testBackendName, tokens[12], formatErrMessage)
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()) {
@ -328,28 +563,6 @@ func doLogging(t *testing.T, config *types.AccessLog) {
logger.ServeHTTP(httptest.NewRecorder(), req, logWriterTestHandlerFunc)
}
func containsKeys(t *testing.T, expectedKeys []string, data map[string]interface{}) {
for key, value := range data {
if !contains(expectedKeys, key) {
t.Errorf("Unexpected log key: %s [value: %s]", key, value)
}
}
for _, k := range expectedKeys {
if _, ok := data[k]; !ok {
t.Errorf("the expected key '%s' is not present in the map. %+v", k, data)
}
}
}
func contains(values []string, value string) bool {
for _, v := range values {
if value == v {
return true
}
}
return false
}
func logWriterTestHandlerFunc(rw http.ResponseWriter, r *http.Request) {
rw.Write([]byte(testContent))
rw.WriteHeader(testStatus)

View file

@ -0,0 +1,54 @@
package accesslog
import (
"bytes"
"regexp"
)
// ParseAccessLog parse line of access log and return a map with each fields
func ParseAccessLog(data string) (map[string]string, error) {
var buffer bytes.Buffer
buffer.WriteString(`(\S+)`) // 1 - ClientHost
buffer.WriteString(`\s-\s`) // - - Spaces
buffer.WriteString(`(\S+)\s`) // 2 - ClientUsername
buffer.WriteString(`\[([^]]+)\]\s`) // 3 - StartUTC
buffer.WriteString(`"(\S*)\s?`) // 4 - RequestMethod
buffer.WriteString(`((?:[^"]*(?:\\")?)*)\s`) // 5 - RequestPath
buffer.WriteString(`([^"]*)"\s`) // 6 - RequestProtocol
buffer.WriteString(`(\S+)\s`) // 7 - OriginStatus
buffer.WriteString(`(\S+)\s`) // 8 - OriginContentSize
buffer.WriteString(`("?\S+"?)\s`) // 9 - Referrer
buffer.WriteString(`("\S+")\s`) // 10 - User-Agent
buffer.WriteString(`(\S+)\s`) // 11 - RequestCount
buffer.WriteString(`("[^"]*"|-)\s`) // 12 - FrontendName
buffer.WriteString(`("[^"]*"|-)\s`) // 13 - BackendURL
buffer.WriteString(`(\S+)`) // 14 - Duration
regex, err := regexp.Compile(buffer.String())
if err != nil {
return nil, err
}
submatch := regex.FindStringSubmatch(data)
result := make(map[string]string)
// Need to be > 13 to match CLF format
if len(submatch) > 13 {
result[ClientHost] = submatch[1]
result[ClientUsername] = submatch[2]
result[StartUTC] = submatch[3]
result[RequestMethod] = submatch[4]
result[RequestPath] = submatch[5]
result[RequestProtocol] = submatch[6]
result[OriginStatus] = submatch[7]
result[OriginContentSize] = submatch[8]
result[RequestRefererHeader] = submatch[9]
result[RequestUserAgentHeader] = submatch[10]
result[RequestCount] = submatch[11]
result[FrontendName] = submatch[12]
result[BackendURL] = submatch[13]
result[Duration] = submatch[14]
}
return result, nil
}

View file

@ -0,0 +1,75 @@
package accesslog
import (
"testing"
"github.com/stretchr/testify/assert"
)
func TestParseAccessLog(t *testing.T) {
testCases := []struct {
desc string
value string
expected map[string]string
}{
{
desc: "full log",
value: `TestHost - TestUser [13/Apr/2016:07:14:19 -0700] "POST testpath HTTP/0.0" 123 12 "testReferer" "testUserAgent" 1 "testFrontend" "http://127.0.0.1/testBackend" 1ms`,
expected: map[string]string{
ClientHost: "TestHost",
ClientUsername: "TestUser",
StartUTC: "13/Apr/2016:07:14:19 -0700",
RequestMethod: "POST",
RequestPath: "testpath",
RequestProtocol: "HTTP/0.0",
OriginStatus: "123",
OriginContentSize: "12",
RequestRefererHeader: `"testReferer"`,
RequestUserAgentHeader: `"testUserAgent"`,
RequestCount: "1",
FrontendName: `"testFrontend"`,
BackendURL: `"http://127.0.0.1/testBackend"`,
Duration: "1ms",
},
},
{
desc: "log with space",
value: `127.0.0.1 - - [09/Mar/2018:10:51:32 +0000] "GET / HTTP/1.1" 401 17 "-" "Go-http-client/1.1" 1 "testFrontend with space" - 0ms`,
expected: map[string]string{
ClientHost: "127.0.0.1",
ClientUsername: "-",
StartUTC: "09/Mar/2018:10:51:32 +0000",
RequestMethod: "GET",
RequestPath: "/",
RequestProtocol: "HTTP/1.1",
OriginStatus: "401",
OriginContentSize: "17",
RequestRefererHeader: `"-"`,
RequestUserAgentHeader: `"Go-http-client/1.1"`,
RequestCount: "1",
FrontendName: `"testFrontend with space"`,
BackendURL: `-`,
Duration: "0ms",
},
},
{
desc: "bad log",
value: `bad`,
expected: map[string]string{},
},
}
for _, test := range testCases {
test := test
t.Run(test.desc, func(t *testing.T) {
t.Parallel()
result, err := ParseAccessLog(test.value)
assert.NoError(t, err)
assert.Equal(t, len(test.expected), len(result))
for key, value := range test.expected {
assert.Equal(t, value, result[key])
}
})
}
}

View file

@ -19,7 +19,7 @@ var _ Stateful = &errorPagesResponseRecorderWithCloseNotify{}
//ErrorPagesHandler is a middleware that provides the custom error pages
type ErrorPagesHandler struct {
HTTPCodeRanges [][2]int
HTTPCodeRanges types.HTTPCodeRanges
BackendURL string
errorPageForwarder *forward.Forwarder
}
@ -31,27 +31,13 @@ func NewErrorPagesHandler(errorPage *types.ErrorPage, backendURL string) (*Error
return nil, err
}
//Break out the http status code ranges into a low int and high int
//for ease of use at runtime
var blocks [][2]int
for _, block := range errorPage.Status {
codes := strings.Split(block, "-")
//if only a single HTTP code was configured, assume the best and create the correct configuration on the user's behalf
if len(codes) == 1 {
codes = append(codes, codes[0])
}
lowCode, err := strconv.Atoi(codes[0])
if err != nil {
return nil, err
}
highCode, err := strconv.Atoi(codes[1])
if err != nil {
return nil, err
}
blocks = append(blocks, [2]int{lowCode, highCode})
httpCodeRanges, err := types.NewHTTPCodeRanges(errorPage.Status)
if err != nil {
return nil, err
}
return &ErrorPagesHandler{
HTTPCodeRanges: blocks,
HTTPCodeRanges: httpCodeRanges,
BackendURL: backendURL + errorPage.Query,
errorPageForwarder: fwd},
nil