baalajimaestro/traefik
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages 1 Wiki Activity Actions

Switch access logging to logrus

Browse source
This commit is contained in:
Richard Shepherd 2017-05-22 20:39:29 +01:00 committed by Emile Vauge
parent 2643271053
commit 64e8b31d49
7 changed files with 175 additions and 263 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

3
cmd/traefik/traefik.go
View file

@ -19,7 +19,6 @@ import (
"github.com/containous/traefik/acme"
"github.com/containous/traefik/cluster"
"github.com/containous/traefik/log"
"github.com/containous/traefik/middlewares"
"github.com/containous/traefik/provider/kubernetes"
"github.com/containous/traefik/safe"
"github.com/containous/traefik/server"
@ -179,8 +178,6 @@ func run(traefikConfiguration *server.TraefikConfiguration) {
if globalConfiguration.InsecureSkipVerify {
http.DefaultTransport.(*http.Transport).TLSClientConfig = &tls.Config{InsecureSkipVerify: true}
}
loggerMiddleware := middlewares.NewLogger(globalConfiguration.AccessLogsFile)
defer loggerMiddleware.Close()
if globalConfiguration.File != nil && len(globalConfiguration.File.Filename) == 0 {
// no filename, setting to global config file

10
integration/access_log_test.go
View file

@ -78,12 +78,12 @@ func (s *AccessLogSuite) TestAccessLog(c *check.C) {
count++
tokens, err := shellwords.Parse(line)
c.Assert(err, checker.IsNil)
c.Assert(len(tokens), checker.Equals, 13)
c.Assert(len(tokens), checker.Equals, 14)
c.Assert(regexp.MustCompile(`^\d{3}$`).MatchString(tokens[6]), checker.True)
c.Assert(tokens[9], checker.Equals, fmt.Sprintf("%d", i+1))
c.Assert(strings.HasPrefix(tokens[10], "frontend"), checker.True)
c.Assert(strings.HasPrefix(tokens[11], "http://127.0.0.1:808"), checker.True)
c.Assert(regexp.MustCompile(`^\d+ms$`).MatchString(tokens[12]), checker.True)
c.Assert(tokens[10], checker.Equals, fmt.Sprintf("%d", i+1))
c.Assert(strings.HasPrefix(tokens[11], "frontend"), checker.True)
c.Assert(strings.HasPrefix(tokens[12], "http://127.0.0.1:808"), checker.True)
c.Assert(regexp.MustCompile(`^\d+ms$`).MatchString(tokens[13]), checker.True)
}
}
c.Assert(count, checker.GreaterOrEqualThan, 3)

57
middlewares/accesslog/logger.go
View file

@ -2,12 +2,17 @@ package accesslog
import (
"context"
"errors"
"fmt"
"net"
"net/http"
"net/url"
"os"
"path/filepath"
"sync/atomic"
"time"
"github.com/Sirupsen/logrus"
)
type key string
@ -19,15 +24,35 @@ const (
)
// LogHandler will write each request and its response to the access log.
// It gets some information from the logInfoResponseWriter set up by previous middleware.
// Note: Current implementation collects log data but does not have the facility to
// write anywhere.
type LogHandler struct {
logger *logrus.Logger
file *os.File
}
// NewLogHandler creates a new LogHandler
func NewLogHandler() *LogHandler {
return &LogHandler{}
func NewLogHandler(filePath string) (*LogHandler, error) {
if len(filePath) == 0 {
return nil, errors.New("Empty file name specified for accessLogsFile")
}
dir := filepath.Dir(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)
if err != nil {
return nil, fmt.Errorf("error opening file: %s %s", dir, err)
}
logger := &logrus.Logger{
Out: file,
Formatter: new(CommonLogFormatter),
Hooks: make(logrus.LevelHooks),
Level: logrus.InfoLevel,
}
return &LogHandler{logger: logger, file: file}, nil
}
// GetLogDataTable gets the request context object that contains logging data. This accretes
@ -85,7 +110,7 @@ func (l *LogHandler) ServeHTTP(rw http.ResponseWriter, req *http.Request, next h
// Close closes the Logger (i.e. the file etc).
func (l *LogHandler) Close() error {
return nil
return l.file.Close()
}
func silentSplitHostPort(value string) (host string, port string) {
@ -133,6 +158,26 @@ func (l *LogHandler) logTheRoundTrip(logDataTable *LogData, crr *captureRequestR
} else {
core[Overhead] = total
}
fields := logrus.Fields{}
for k, v := range logDataTable.Core {
fields[k] = v
}
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.logger.WithFields(fields).Println()
}
//-------------------------------------------------------------------------------------------------

68
middlewares/accesslog/logger_formatters.go Normal file
View file

@ -0,0 +1,68 @@
package accesslog
import (
"bytes"
"fmt"
"time"
"github.com/Sirupsen/logrus"
)
// default format for time presentation
const commonLogTimeFormat = "02/Jan/2006:15:04:05 -0700"
// CommonLogFormatter provides formatting in the Traefik common log format
type CommonLogFormatter struct {
}
//Format formats the log entry in the Traefik 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
_, err := fmt.Fprintf(b, "%s - %s [%s] \"%s %s %s\" %d %d %s %s %d %s %s %dms\n",
entry.Data[ClientHost],
entry.Data[ClientUsername],
timestamp,
entry.Data[RequestMethod],
entry.Data[RequestPath],
entry.Data[RequestProtocol],
entry.Data[OriginStatus],
entry.Data[OriginContentSize],
toLogString(entry.Data["request_Referer"]),
toLogString(entry.Data["request_User-Agent"]),
entry.Data[RequestCount],
toLogString(entry.Data[FrontendName]),
toLogString(entry.Data[BackendURL]),
elapsedMillis)
return b.Bytes(), err
}
func toLogString(v interface{}) string {
defaultValue := "-"
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 defaultValue
}
}
func quoted(s string, defaultValue string) string {
if len(s) == 0 {
return defaultValue
}
return `"` + s + `"`
}

38
middlewares/logger_test.go → middlewares/accesslog/logger_test.go
View file

@ -1,7 +1,6 @@
package middlewares
package accesslog
import (
"context"
"fmt"
"io/ioutil"
"net/http"
@ -10,32 +9,29 @@ import (
"path/filepath"
"testing"
"github.com/containous/traefik/middlewares/accesslog"
shellwords "github.com/mattn/go-shellwords"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
)
type logtestResponseWriter struct{}
var (
logger *Logger
logger *LogHandler
logfileNameSuffix = "/traefik/logger/test.log"
helloWorld = "Hello, World"
testBackendName = "http://127.0.0.1/testBackend"
testFrontendName = "testFrontend"
testStatus = 123
testContentSize int64 = 12
testHostname = "TestHost"
testUsername = "TestUser"
testPath = "http://testpath"
testPath = "testpath"
testPort = 8181
testProto = "HTTP/0.0"
testMethod = "POST"
testReferer = "testReferer"
testUserAgent = "testUserAgent"
testBackend2FrontendMap = map[string]string{
testBackendName: testFrontendName,
}
printedLogdata bool
)
func TestLogger(t *testing.T) {
@ -47,16 +43,15 @@ func TestLogger(t *testing.T) {
logfilePath := filepath.Join(tmp, logfileNameSuffix)
logger = NewLogger(logfilePath)
logger, err = NewLogHandler(logfilePath)
require.NoError(t, err)
defer logger.Close()
if _, err := os.Stat(logfilePath); os.IsNotExist(err) {
t.Fatalf("logger should create %s", logfilePath)
}
SetBackend2FrontendMap(&testBackend2FrontendMap)
r := &http.Request{
req := &http.Request{
Header: map[string][]string{
"User-Agent": {testUserAgent},
"Referer": {testReferer},
@ -71,14 +66,6 @@ func TestLogger(t *testing.T) {
},
}
// Temporary - until new access logger is fully implemented
// create the data table and populate frontend and backend
core := make(accesslog.CoreLogData)
logDataTable := &accesslog.LogData{Core: core, Request: r.Header}
logDataTable.Core[accesslog.FrontendName] = testFrontendName
logDataTable.Core[accesslog.BackendURL] = testBackendName
req := r.WithContext(context.WithValue(r.Context(), accesslog.DataTableKey, logDataTable))
logger.ServeHTTP(&logtestResponseWriter{}, req, LogWriterTestHandlerFunc)
if logdata, err := ioutil.ReadFile(logfilePath); err != nil {
@ -105,14 +92,19 @@ func printLogdata(logdata []byte) string {
return fmt.Sprintf(
"\nExpected: %s\n"+
"Actual: %s",
"TestHost - TestUser [13/Apr/2016:07:14:19 -0700] \"POST http://testpath HTTP/0.0\" 123 12 \"testReferer\" \"testUserAgent\" 1 \"testFrontend\" \"http://127.0.0.1/testBackend\" 1ms",
"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",
string(logdata))
}
func LogWriterTestHandlerFunc(rw http.ResponseWriter, r *http.Request) {
rw.Write([]byte(helloWorld))
rw.WriteHeader(testStatus)
saveBackendNameForLogger(r, testBackendName)
logDataTable := GetLogDataTable(r)
logDataTable.Core[FrontendName] = testFrontendName
logDataTable.Core[BackendURL] = testBackendName
logDataTable.Core[OriginStatus] = testStatus
logDataTable.Core[OriginContentSize] = testContentSize
}
func (lrw *logtestResponseWriter) Header() http.Header {

209
middlewares/logger.go
View file

@ -1,209 +0,0 @@
package middlewares
import (
"bufio"
"fmt"
"io"
"net"
"net/http"
"os"
"path/filepath"
"strconv"
"strings"
"sync/atomic"
"time"
"github.com/containous/traefik/log"
"github.com/containous/traefik/middlewares/accesslog"
"github.com/streamrail/concurrent-map"
)
const (
loggerReqidHeader = "X-Traefik-Reqid"
)
/*
Logger writes each request and its response to the access log.
It gets some information from the logInfoResponseWriter set up by previous middleware.
*/
type Logger struct {
file *os.File
}
// Logging handler to log frontend name, backend name, and elapsed time
type frontendBackendLoggingHandler struct {
reqid string
writer io.Writer
handlerFunc http.HandlerFunc
}
var (
reqidCounter uint64 // Request ID
infoRwMap = cmap.New() // Map of reqid to response writer
backend2FrontendMap *map[string]string
)
// logInfoResponseWriter is a wrapper of type http.ResponseWriter
// that tracks frontend and backend names and request status and size
type logInfoResponseWriter struct {
rw http.ResponseWriter
backend string
frontend string
status int
size int
}
// NewLogger returns a new Logger instance.
func NewLogger(file string) *Logger {
if len(file) > 0 {
dir := filepath.Dir(file)
err := os.MkdirAll(dir, 0755)
if err != nil {
log.Errorf("Failed to create log path %s: %s", dir, err)
}
fi, err := os.OpenFile(file, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)
if err != nil {
log.Error("Error opening file", err)
}
return &Logger{fi}
}
return &Logger{nil}
}
// SetBackend2FrontendMap is called by server.go to set up frontend translation
func SetBackend2FrontendMap(newMap *map[string]string) {
backend2FrontendMap = newMap
}
func (l *Logger) ServeHTTP(rw http.ResponseWriter, r *http.Request, next http.HandlerFunc) {
if l.file == nil {
next(rw, r)
} else {
reqid := strconv.FormatUint(atomic.AddUint64(&reqidCounter, 1), 10)
r.Header[loggerReqidHeader] = []string{reqid}
defer deleteReqid(r, reqid)
frontendBackendLoggingHandler{reqid, l.file, next}.ServeHTTP(rw, r)
}
}
// Delete a reqid from the map and the request's headers
func deleteReqid(r *http.Request, reqid string) {
infoRwMap.Remove(reqid)
delete(r.Header, loggerReqidHeader)
}
// Save the backend name for the Logger
func saveBackendNameForLogger(r *http.Request, backendName string) {
if reqidHdr := r.Header[loggerReqidHeader]; len(reqidHdr) == 1 {
reqid := reqidHdr[0]
if infoRw, ok := infoRwMap.Get(reqid); ok {
infoRw.(*logInfoResponseWriter).SetBackend(backendName)
infoRw.(*logInfoResponseWriter).SetFrontend((*backend2FrontendMap)[backendName])
}
}
}
// Close closes the Logger (i.e. the file).
func (l *Logger) Close() {
if l.file != nil {
l.file.Close()
}
}
// Logging handler to log frontend name, backend name, and elapsed time
func (fblh frontendBackendLoggingHandler) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
startTime := time.Now()
infoRw := &logInfoResponseWriter{rw: rw}
infoRwMap.Set(fblh.reqid, infoRw)
fblh.handlerFunc(infoRw, req)
username := "-"
url := *req.URL
if url.User != nil {
if name := url.User.Username(); name != "" {
username = name
}
}
host, _, err := net.SplitHostPort(req.RemoteAddr)
if err != nil {
host = req.RemoteAddr
}
ts := startTime.Format("02/Jan/2006:15:04:05 -0700")
method := req.Method
uri := url.RequestURI()
if qmIndex := strings.Index(uri, "?"); qmIndex > 0 {
uri = uri[0:qmIndex]
}
proto := req.Proto
referer := req.Referer()
agent := req.UserAgent()
logTable := accesslog.GetLogDataTable(req)
frontend := logTable.Core[accesslog.FrontendName]
backend := logTable.Core[accesslog.BackendURL]
status := infoRw.GetStatus()
size := infoRw.GetSize()
elapsed := time.Now().UTC().Sub(startTime.UTC())
elapsedMillis := elapsed.Nanoseconds() / 1000000
fmt.Fprintf(fblh.writer, `%s - %s [%s] "%s %s %s" %d %d "%s" "%s" %s "%s" "%s" %dms%s`,
host, username, ts, method, uri, proto, status, size, referer, agent, fblh.reqid, frontend, backend, elapsedMillis, "\n")
}
func (lirw *logInfoResponseWriter) Header() http.Header {
return lirw.rw.Header()
}
func (lirw *logInfoResponseWriter) Write(b []byte) (int, error) {
if lirw.status == 0 {
lirw.status = http.StatusOK
}
size, err := lirw.rw.Write(b)
lirw.size += size
return size, err
}
func (lirw *logInfoResponseWriter) WriteHeader(s int) {
lirw.rw.WriteHeader(s)
lirw.status = s
}
func (lirw *logInfoResponseWriter) Flush() {
f, ok := lirw.rw.(http.Flusher)
if ok {
f.Flush()
}
}
func (lirw *logInfoResponseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) {
return lirw.rw.(http.Hijacker).Hijack()
}
func (lirw *logInfoResponseWriter) GetStatus() int {
return lirw.status
}
func (lirw *logInfoResponseWriter) GetSize() int {
return lirw.size
}
func (lirw *logInfoResponseWriter) GetBackend() string {
return lirw.backend
}
func (lirw *logInfoResponseWriter) GetFrontend() string {
return lirw.frontend
}
func (lirw *logInfoResponseWriter) SetBackend(backend string) {
lirw.backend = backend
}
func (lirw *logInfoResponseWriter) SetFrontend(frontend string) {
lirw.frontend = frontend
}

53
server/server.go
View file

@ -48,7 +48,6 @@ type Server struct {
providers []provider.Provider
currentConfigurations safe.Safe
globalConfiguration GlobalConfiguration
loggerMiddleware *middlewares.Logger
accessLoggerMiddleware *accesslog.LogHandler
routinesPool *safe.Pool
leadership *cluster.Leadership
@ -83,14 +82,17 @@ func NewServer(globalConfiguration GlobalConfiguration) *Server {
currentConfigurations := make(configs)
server.currentConfigurations.Set(currentConfigurations)
server.globalConfiguration = globalConfiguration
server.loggerMiddleware = middlewares.NewLogger(globalConfiguration.AccessLogsFile)
server.accessLoggerMiddleware = accesslog.NewLogHandler()
server.routinesPool = safe.NewPool(context.Background())
if globalConfiguration.Cluster != nil {
// leadership creation if cluster mode
server.leadership = cluster.NewLeadership(server.routinesPool.Ctx(), globalConfiguration.Cluster)
}
var err error
server.accessLoggerMiddleware, err = accesslog.NewLogHandler(globalConfiguration.AccessLogsFile)
if err != nil {
log.Warn("Unable to create log handler: %s", err)
}
return server
}
@ -156,8 +158,11 @@ func (server *Server) Close() {
signal.Stop(server.signals)
close(server.signals)
close(server.stopChan)
server.loggerMiddleware.Close()
server.accessLoggerMiddleware.Close()
if server.accessLoggerMiddleware != nil {
if err := server.accessLoggerMiddleware.Close(); err != nil {
log.Errorf("Error closing access log file: %s", err)
}
}
cancel()
}
@ -177,7 +182,10 @@ func (server *Server) startHTTPServers() {
server.serverEntryPoints = server.buildEntryPoints(server.globalConfiguration)
for newServerEntryPointName, newServerEntryPoint := range server.serverEntryPoints {
serverMiddlewares := []negroni.Handler{middlewares.NegroniRecoverHandler(), server.accessLoggerMiddleware, server.loggerMiddleware, metrics}
serverMiddlewares := []negroni.Handler{middlewares.NegroniRecoverHandler(), metrics}
if server.accessLoggerMiddleware != nil {
serverMiddlewares = append(serverMiddlewares, server.accessLoggerMiddleware)
}
if server.globalConfiguration.Web != nil && server.globalConfiguration.Web.Metrics != nil {
if server.globalConfiguration.Web.Metrics.Prometheus != nil {
metricsMiddleware := middlewares.NewMetricsWrapper(middlewares.NewPrometheus(newServerEntryPointName, server.globalConfiguration.Web.Metrics.Prometheus))
@ -544,7 +552,6 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo
redirectHandlers := make(map[string]negroni.Handler)
backends := map[string]http.Handler{}
backendsHealthcheck := map[string]*healthcheck.BackendHealthCheck{}
backend2FrontendMap := map[string]string{}
for _, configuration := range configurations {
frontendNames := sortedFrontendNamesForConfig(configuration)
@ -595,16 +602,27 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo
log.Errorf("Skipping frontend %s...", frontendName)
continue frontend
} else {
saveFrontend := accesslog.NewSaveNegroniFrontend(handler, frontendName)
negroni.Use(saveFrontend)
redirectHandlers[entryPointName] = saveFrontend
if server.accessLoggerMiddleware != nil {
saveFrontend := accesslog.NewSaveNegroniFrontend(handler, frontendName)
negroni.Use(saveFrontend)
redirectHandlers[entryPointName] = saveFrontend
} else {
negroni.Use(handler)
redirectHandlers[entryPointName] = handler
}
}
}
if backends[entryPointName+frontend.Backend] == nil {
log.Debugf("Creating backend %s", frontend.Backend)
saveBackend := accesslog.NewSaveBackend(fwd, frontend.Backend)
saveFrontend := accesslog.NewSaveFrontend(saveBackend, frontendName)
rr, _ := roundrobin.New(saveFrontend)
var rr *roundrobin.RoundRobin
var saveFrontend http.Handler
if server.accessLoggerMiddleware != nil {
saveBackend := accesslog.NewSaveBackend(fwd, frontend.Backend)
saveFrontend = accesslog.NewSaveFrontend(saveBackend, frontendName)
rr, _ = roundrobin.New(saveFrontend)
} else {
rr, _ = roundrobin.New(fwd)
}
if configuration.Backends[frontend.Backend] == nil {
log.Errorf("Undefined backend '%s' for frontend %s", frontend.Backend, frontendName)
log.Errorf("Skipping frontend %s...", frontendName)
@ -643,7 +661,6 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo
log.Errorf("Skipping frontend %s...", frontendName)
continue frontend
}
backend2FrontendMap[url.String()] = frontendName
log.Debugf("Creating server %s at %s with weight %d", serverName, url.String(), server.Weight)
if err := rebalancer.UpsertServer(url, roundrobin.Weight(server.Weight)); err != nil {
log.Errorf("Error adding server %s to load balancer: %v", server.URL, err)
@ -660,7 +677,11 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo
log.Debugf("Creating load-balancer wrr")
if stickysession {
log.Debugf("Sticky session with cookie %v", cookiename)
rr, _ = roundrobin.New(saveFrontend, roundrobin.EnableStickySession(sticky))
if server.accessLoggerMiddleware != nil {
rr, _ = roundrobin.New(saveFrontend, roundrobin.EnableStickySession(sticky))
} else {
rr, _ = roundrobin.New(fwd, roundrobin.EnableStickySession(sticky))
}
}
lb = rr
for serverName, server := range configuration.Backends[frontend.Backend].Servers {
@ -670,7 +691,6 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo
log.Errorf("Skipping frontend %s...", frontendName)
continue frontend
}
backend2FrontendMap[url.String()] = frontendName
log.Debugf("Creating server %s at %s with weight %d", serverName, url.String(), server.Weight)
if err := rr.UpsertServer(url, roundrobin.Weight(server.Weight)); err != nil {
log.Errorf("Error adding server %s to load balancer: %v", server.URL, err)
@ -770,7 +790,6 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo
}
}
healthcheck.GetHealthCheck().SetBackendsConfiguration(server.routinesPool.Ctx(), backendsHealthcheck)
middlewares.SetBackend2FrontendMap(&backend2FrontendMap)
//sort routes
for _, serverEntryPoint := range serverEntryPoints {
serverEntryPoint.httpRouter.GetHandler().SortRoutes()