From a9216e24f56ee488d570fbf05a6241cfcaede76b Mon Sep 17 00:00:00 2001 From: Richard Shepherd Date: Thu, 25 May 2017 12:25:53 +0100 Subject: [PATCH] Add JSON as access logging format --- docs/toml.md | 19 +++ middlewares/accesslog/logger.go | 30 +++- middlewares/accesslog/logger_test.go | 222 +++++++++++++++++++++------ server/configuration.go | 11 +- server/server.go | 14 +- traefik.sample.toml | 25 +++ types/types.go | 6 + 7 files changed, 268 insertions(+), 59 deletions(-) diff --git a/docs/toml.md b/docs/toml.md index 463188aa5..59456257c 100644 --- a/docs/toml.md +++ b/docs/toml.md @@ -42,6 +42,7 @@ # Access logs file # +# Deprecated - see [accessLog] lower down # Optional # # accessLogsFile = "log/access.log" @@ -151,6 +152,24 @@ Supported filters: # constraints = ["tag==api", "tag!=v*-beta"] ``` +## Access log definition + +The standard access log uses the textual Common Log Format (CLF), extended with additional fields. +Alternatively logs can be written in JSON. +Using the default CLF option is simple, e.g. + +```toml +[accessLog] + filePath = "/path/to/access.log" +``` + +To write JSON format logs, specify `json` as the format: +```toml +[accessLog] + filePath = "/path/to/access.log" + format = "json" +``` + ## Entrypoints definition ```toml diff --git a/middlewares/accesslog/logger.go b/middlewares/accesslog/logger.go index 36d723688..2ba48a947 100644 --- a/middlewares/accesslog/logger.go +++ b/middlewares/accesslog/logger.go @@ -13,6 +13,7 @@ import ( "time" "github.com/Sirupsen/logrus" + "github.com/containous/traefik/types" ) type key string @@ -21,6 +22,12 @@ const ( // DataTableKey is the key within the request context used to // store the Log Data Table DataTableKey key = "LogDataTable" + + // CommonFormat is the common logging format (CLF) + CommonFormat = "common" + + // JSONFormat is the JSON logging format + JSONFormat = "json" ) // LogHandler will write each request and its response to the access log. @@ -30,25 +37,36 @@ type LogHandler struct { } // NewLogHandler creates a new LogHandler -func NewLogHandler(filePath string) (*LogHandler, error) { - if len(filePath) == 0 { - return nil, errors.New("Empty file name specified for accessLogsFile") +func NewLogHandler(config *types.AccessLog) (*LogHandler, error) { + if len(config.FilePath) == 0 { + return nil, errors.New("Empty file path specified for accessLogsFile") } - dir := filepath.Dir(filePath) + dir := filepath.Dir(config.FilePath) if err := os.MkdirAll(dir, 0755); err != nil { return nil, fmt.Errorf("failed to create log path %s: %s", dir, err) } - file, err := os.OpenFile(filePath, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0664) + file, err := os.OpenFile(config.FilePath, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0664) if err != nil { return nil, fmt.Errorf("error opening file: %s %s", dir, err) } + var formatter logrus.Formatter + + switch config.Format { + case CommonFormat: + formatter = new(CommonLogFormatter) + case JSONFormat: + formatter = new(logrus.JSONFormatter) + default: + return nil, fmt.Errorf("unsupported access log format: %s", config.Format) + } + logger := &logrus.Logger{ Out: file, - Formatter: new(CommonLogFormatter), + Formatter: formatter, Hooks: make(logrus.LevelHooks), Level: logrus.InfoLevel, } diff --git a/middlewares/accesslog/logger_test.go b/middlewares/accesslog/logger_test.go index c131b1e81..e470f24b2 100644 --- a/middlewares/accesslog/logger_test.go +++ b/middlewares/accesslog/logger_test.go @@ -1,24 +1,25 @@ package accesslog import ( + "encoding/json" "fmt" "io/ioutil" "net/http" + "net/http/httptest" "net/url" "os" "path/filepath" "testing" + "github.com/containous/traefik/types" shellwords "github.com/mattn/go-shellwords" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) -type logtestResponseWriter struct{} - var ( logger *LogHandler - logfileNameSuffix = "/traefik/logger/test.log" + logFileNameSuffix = "/traefik/logger/test.log" helloWorld = "Hello, World" testBackendName = "http://127.0.0.1/testBackend" testFrontendName = "testFrontend" @@ -34,21 +35,174 @@ var ( testUserAgent = "testUserAgent" ) -func TestLogger(t *testing.T) { - tmp, err := ioutil.TempDir("", "testlogger") +func TestLoggerCLF(t *testing.T) { + tmpDir, logFilePath := doLogging(t, CommonFormat) + defer os.RemoveAll(tmpDir) + + logData, err := ioutil.ReadFile(logFilePath) + require.NoError(t, err) + + tokens, err := shellwords.Parse(string(logData)) + require.NoError(t, err) + + assert.Equal(t, 14, len(tokens), printLogData(logData)) + assert.Equal(t, testHostname, tokens[0], printLogData(logData)) + assert.Equal(t, testUsername, tokens[2], printLogData(logData)) + assert.Equal(t, fmt.Sprintf("%s %s %s", testMethod, testPath, testProto), tokens[5], printLogData(logData)) + assert.Equal(t, fmt.Sprintf("%d", testStatus), tokens[6], printLogData(logData)) + assert.Equal(t, fmt.Sprintf("%d", len(helloWorld)), tokens[7], printLogData(logData)) + assert.Equal(t, testReferer, tokens[8], printLogData(logData)) + assert.Equal(t, testUserAgent, tokens[9], printLogData(logData)) + assert.Equal(t, "1", tokens[10], printLogData(logData)) + assert.Equal(t, testFrontendName, tokens[11], printLogData(logData)) + assert.Equal(t, testBackendName, tokens[12], printLogData(logData)) +} + +func TestLoggerJSON(t *testing.T) { + tmpDir, logFilePath := doLogging(t, JSONFormat) + defer os.RemoveAll(tmpDir) + + 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, + "time", + "StartLocal", + "StartUTC", + } + 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(helloWorld)), jsonData[DownstreamContentSize]) + assertCount++ + assert.Equal(t, float64(len(helloWorld)), 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.NotEqual(t, "", jsonData["time"].(string)) + assertCount++ + assert.NotEqual(t, "", jsonData["StartLocal"].(string)) + assertCount++ + assert.NotEqual(t, "", jsonData["StartUTC"].(string)) + assertCount++ + + assert.Equal(t, len(jsonData), assertCount, string(logData)) +} + +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 doLogging(t *testing.T, format string) (string, string) { + tmp, err := ioutil.TempDir("", format) if err != nil { t.Fatalf("failed to create temp dir: %s", err) } - defer os.RemoveAll(tmp) - logfilePath := filepath.Join(tmp, logfileNameSuffix) + logFilePath := filepath.Join(tmp, logFileNameSuffix) - logger, err = NewLogHandler(logfilePath) - require.NoError(t, err) + config := types.AccessLog{FilePath: logFilePath, Format: format} + + logger, err = NewLogHandler(&config) defer logger.Close() + require.NoError(t, err) - if _, err := os.Stat(logfilePath); os.IsNotExist(err) { - t.Fatalf("logger should create %s", logfilePath) + if _, err := os.Stat(logFilePath); os.IsNotExist(err) { + t.Fatalf("logger should create %s", logFilePath) } req := &http.Request{ @@ -66,37 +220,20 @@ func TestLogger(t *testing.T) { }, } - logger.ServeHTTP(&logtestResponseWriter{}, req, LogWriterTestHandlerFunc) - - if logdata, err := ioutil.ReadFile(logfilePath); err != nil { - fmt.Printf("%s\n%s\n", string(logdata), err.Error()) - assert.NoError(t, err) - } else if tokens, err := shellwords.Parse(string(logdata)); err != nil { - fmt.Printf("%s\n", err.Error()) - assert.NoError(t, err) - } else if assert.Equal(t, 14, len(tokens), printLogdata(logdata)) { - assert.Equal(t, testHostname, tokens[0], printLogdata(logdata)) - assert.Equal(t, testUsername, tokens[2], printLogdata(logdata)) - assert.Equal(t, fmt.Sprintf("%s %s %s", testMethod, testPath, testProto), tokens[5], printLogdata(logdata)) - assert.Equal(t, fmt.Sprintf("%d", testStatus), tokens[6], printLogdata(logdata)) - assert.Equal(t, fmt.Sprintf("%d", len(helloWorld)), tokens[7], printLogdata(logdata)) - assert.Equal(t, testReferer, tokens[8], printLogdata(logdata)) - assert.Equal(t, testUserAgent, tokens[9], printLogdata(logdata)) - assert.Equal(t, "1", tokens[10], printLogdata(logdata)) - assert.Equal(t, testFrontendName, tokens[11], printLogdata(logdata)) - assert.Equal(t, testBackendName, tokens[12], printLogdata(logdata)) - } + rw := httptest.NewRecorder() + logger.ServeHTTP(rw, req, logWriterTestHandlerFunc) + return tmp, logFilePath } -func printLogdata(logdata []byte) string { - return fmt.Sprintf( - "\nExpected: %s\n"+ - "Actual: %s", - "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", +func printLogData(logdata []byte) string { + return 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)) } -func LogWriterTestHandlerFunc(rw http.ResponseWriter, r *http.Request) { +func logWriterTestHandlerFunc(rw http.ResponseWriter, r *http.Request) { rw.Write([]byte(helloWorld)) rw.WriteHeader(testStatus) @@ -106,14 +243,3 @@ func LogWriterTestHandlerFunc(rw http.ResponseWriter, r *http.Request) { logDataTable.Core[OriginStatus] = testStatus logDataTable.Core[OriginContentSize] = testContentSize } - -func (lrw *logtestResponseWriter) Header() http.Header { - return map[string][]string{} -} - -func (lrw *logtestResponseWriter) Write(b []byte) (int, error) { - return len(b), nil -} - -func (lrw *logtestResponseWriter) WriteHeader(s int) { -} diff --git a/server/configuration.go b/server/configuration.go index c71afe3c6..ec53ce36f 100644 --- a/server/configuration.go +++ b/server/configuration.go @@ -11,6 +11,7 @@ import ( "github.com/containous/flaeg" "github.com/containous/traefik/acme" + "github.com/containous/traefik/middlewares/accesslog" "github.com/containous/traefik/provider/boltdb" "github.com/containous/traefik/provider/consul" "github.com/containous/traefik/provider/docker" @@ -42,7 +43,8 @@ type GlobalConfiguration struct { GraceTimeOut flaeg.Duration `short:"g" description:"Duration to give active requests a chance to finish during hot-reload"` Debug bool `short:"d" description:"Enable debug mode"` CheckNewVersion bool `description:"Periodically check if a new version has been released"` - AccessLogsFile string `description:"Access logs file"` + AccessLogsFile string `description:"(Deprecated) Access logs file"` // Deprecated + AccessLog *types.AccessLog `description:"Access log settings"` TraefikLogsFile string `description:"Traefik logs file"` LogLevel string `short:"l" description:"Log level"` EntryPoints EntryPoints `description:"Entrypoints definition using format: --entryPoints='Name:http Address::8000 Redirect.EntryPoint:https' --entryPoints='Name:https Address::4442 TLS:tests/traefik.crt,tests/traefik.key;prod/traefik.crt,prod/traefik.key'"` @@ -456,6 +458,12 @@ func NewTraefikDefaultPointersConfiguration() *TraefikConfiguration { defaultDynamoDB.TableName = "traefik" defaultDynamoDB.Watch = true + // default AccessLog + defaultAccessLog := types.AccessLog{ + Format: accesslog.CommonFormat, + FilePath: "", + } + defaultConfiguration := GlobalConfiguration{ Docker: &defaultDocker, File: &defaultFile, @@ -473,6 +481,7 @@ func NewTraefikDefaultPointersConfiguration() *TraefikConfiguration { DynamoDB: &defaultDynamoDB, Retry: &Retry{}, HealthCheck: &HealthCheckConfig{}, + AccessLog: &defaultAccessLog, } //default Rancher diff --git a/server/server.go b/server/server.go index 1734c63f2..1a95ebab7 100644 --- a/server/server.go +++ b/server/server.go @@ -88,10 +88,16 @@ func NewServer(globalConfiguration GlobalConfiguration) *Server { server.leadership = cluster.NewLeadership(server.routinesPool.Ctx(), globalConfiguration.Cluster) } - var err error - server.accessLoggerMiddleware, err = accesslog.NewLogHandler(globalConfiguration.AccessLogsFile) - if err != nil { - log.Warnf("Unable to create log handler: %s", err) + if globalConfiguration.AccessLogsFile != "" { + globalConfiguration.AccessLog = &types.AccessLog{FilePath: globalConfiguration.AccessLogsFile, Format: accesslog.CommonFormat} + } + + if globalConfiguration.AccessLog != nil { + var err error + server.accessLoggerMiddleware, err = accesslog.NewLogHandler(globalConfiguration.AccessLog) + if err != nil { + log.Warnf("Unable to create log handler: %s", err) + } } return server } diff --git a/traefik.sample.toml b/traefik.sample.toml index 3beeb018e..f29d68e0b 100644 --- a/traefik.sample.toml +++ b/traefik.sample.toml @@ -36,6 +36,7 @@ # Access logs file # # Optional +# Deprecated - see [accessLog] lower down # # accessLogsFile = "log/access.log" @@ -219,6 +220,30 @@ # main = "local4.com" +# Set access log options +# +# Optional +# +# [accessLog] + +# Sets the file path for the access log. If none is given (the default) +# no access logs are produced. Intermediate directories are created if +# necessary. +# +# Optional +# Default: "" +# +# filePath = "/path/to/log/log.txt" +# + +# Format is either "json" or "common". +# +# Optional +# Default: "common" +# +# format = "common" +# + # Entrypoints definition # # Optional diff --git a/types/types.go b/types/types.go index 955f4e0aa..3bffff7f4 100644 --- a/types/types.go +++ b/types/types.go @@ -303,3 +303,9 @@ func (b *Buckets) String() string { return fmt.Sprintf("%v", *b) } func (b *Buckets) SetValue(val interface{}) { *b = Buckets(val.(Buckets)) } + +// AccessLog holds the configuration settings for the access logger (middlewares/accesslog). +type AccessLog struct { + FilePath string `json:"file,omitempty" description:"Access log file path"` + Format string `json:"format,omitempty" description:"Access log format: json | common"` +}