2017-05-09 12:02:44 +00:00
|
|
|
package accesslog
|
|
|
|
|
|
|
|
import (
|
|
|
|
"context"
|
|
|
|
"fmt"
|
|
|
|
"net"
|
|
|
|
"net/http"
|
|
|
|
"net/url"
|
2017-05-22 19:39:29 +00:00
|
|
|
"os"
|
|
|
|
"path/filepath"
|
2017-09-15 13:02:03 +00:00
|
|
|
"sync"
|
2017-05-09 12:02:44 +00:00
|
|
|
"sync/atomic"
|
|
|
|
"time"
|
2017-05-22 19:39:29 +00:00
|
|
|
|
2018-06-11 16:40:08 +00:00
|
|
|
"github.com/containous/flaeg/parse"
|
2018-03-14 13:12:04 +00:00
|
|
|
"github.com/containous/traefik/log"
|
2017-05-25 11:25:53 +00:00
|
|
|
"github.com/containous/traefik/types"
|
2018-01-22 11:16:03 +00:00
|
|
|
"github.com/sirupsen/logrus"
|
2017-05-09 12:02:44 +00:00
|
|
|
)
|
|
|
|
|
|
|
|
type key string
|
|
|
|
|
|
|
|
const (
|
|
|
|
// DataTableKey is the key within the request context used to
|
|
|
|
// store the Log Data Table
|
|
|
|
DataTableKey key = "LogDataTable"
|
2017-05-25 11:25:53 +00:00
|
|
|
|
|
|
|
// CommonFormat is the common logging format (CLF)
|
|
|
|
CommonFormat = "common"
|
|
|
|
|
|
|
|
// JSONFormat is the JSON logging format
|
|
|
|
JSONFormat = "json"
|
2017-05-09 12:02:44 +00:00
|
|
|
)
|
|
|
|
|
2018-05-23 14:46:04 +00:00
|
|
|
type logHandlerParams struct {
|
|
|
|
logDataTable *LogData
|
|
|
|
crr *captureRequestReader
|
|
|
|
crw *captureResponseWriter
|
|
|
|
}
|
|
|
|
|
2017-05-09 12:02:44 +00:00
|
|
|
// LogHandler will write each request and its response to the access log.
|
|
|
|
type LogHandler struct {
|
2018-03-23 08:28:03 +00:00
|
|
|
config *types.AccessLog
|
2018-03-14 13:12:04 +00:00
|
|
|
logger *logrus.Logger
|
|
|
|
file *os.File
|
|
|
|
mu sync.Mutex
|
|
|
|
httpCodeRanges types.HTTPCodeRanges
|
2018-05-23 14:46:04 +00:00
|
|
|
logHandlerChan chan logHandlerParams
|
|
|
|
wg sync.WaitGroup
|
2017-05-09 12:02:44 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
// NewLogHandler creates a new LogHandler
|
2017-05-25 11:25:53 +00:00
|
|
|
func NewLogHandler(config *types.AccessLog) (*LogHandler, error) {
|
2017-05-30 10:06:49 +00:00
|
|
|
file := os.Stdout
|
|
|
|
if len(config.FilePath) > 0 {
|
|
|
|
f, err := openAccessLogFile(config.FilePath)
|
|
|
|
if err != nil {
|
|
|
|
return nil, fmt.Errorf("error opening access log file: %s", err)
|
|
|
|
}
|
|
|
|
file = f
|
2017-05-22 19:39:29 +00:00
|
|
|
}
|
2018-05-23 14:46:04 +00:00
|
|
|
logHandlerChan := make(chan logHandlerParams, config.BufferingSize)
|
2017-05-22 19:39:29 +00:00
|
|
|
|
2017-05-25 11:25:53 +00:00
|
|
|
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)
|
|
|
|
}
|
|
|
|
|
2017-05-22 19:39:29 +00:00
|
|
|
logger := &logrus.Logger{
|
|
|
|
Out: file,
|
2017-05-25 11:25:53 +00:00
|
|
|
Formatter: formatter,
|
2017-05-22 19:39:29 +00:00
|
|
|
Hooks: make(logrus.LevelHooks),
|
|
|
|
Level: logrus.InfoLevel,
|
|
|
|
}
|
2018-03-14 13:12:04 +00:00
|
|
|
|
|
|
|
logHandler := &LogHandler{
|
2018-05-23 14:46:04 +00:00
|
|
|
config: config,
|
|
|
|
logger: logger,
|
|
|
|
file: file,
|
|
|
|
logHandlerChan: logHandlerChan,
|
2018-03-14 13:12:04 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
if config.Filters != nil {
|
2018-03-23 08:28:03 +00:00
|
|
|
if httpCodeRanges, err := types.NewHTTPCodeRanges(config.Filters.StatusCodes); err != nil {
|
2018-03-14 13:12:04 +00:00
|
|
|
log.Errorf("Failed to create new HTTP code ranges: %s", err)
|
2018-03-23 08:28:03 +00:00
|
|
|
} else {
|
2018-03-14 13:12:04 +00:00
|
|
|
logHandler.httpCodeRanges = httpCodeRanges
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2018-05-23 14:46:04 +00:00
|
|
|
if config.BufferingSize > 0 {
|
|
|
|
logHandler.wg.Add(1)
|
|
|
|
go func() {
|
|
|
|
defer logHandler.wg.Done()
|
|
|
|
for handlerParams := range logHandler.logHandlerChan {
|
|
|
|
logHandler.logTheRoundTrip(handlerParams.logDataTable, handlerParams.crr, handlerParams.crw)
|
|
|
|
}
|
|
|
|
}()
|
|
|
|
}
|
|
|
|
|
2018-03-14 13:12:04 +00:00
|
|
|
return logHandler, nil
|
2017-05-09 12:02:44 +00:00
|
|
|
}
|
|
|
|
|
2017-05-30 10:06:49 +00:00
|
|
|
func openAccessLogFile(filePath string) (*os.File, error) {
|
|
|
|
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", filePath, err)
|
|
|
|
}
|
|
|
|
|
|
|
|
return file, nil
|
|
|
|
}
|
|
|
|
|
2018-05-14 08:38:03 +00:00
|
|
|
// GetLogDataTable gets the request context object that contains logging data.
|
|
|
|
// This creates data as the request passes through the middleware chain.
|
2017-05-09 12:02:44 +00:00
|
|
|
func GetLogDataTable(req *http.Request) *LogData {
|
2018-05-14 08:38:03 +00:00
|
|
|
if ld, ok := req.Context().Value(DataTableKey).(*LogData); ok {
|
|
|
|
return ld
|
|
|
|
}
|
|
|
|
log.Errorf("%s is nil", DataTableKey)
|
|
|
|
return &LogData{Core: make(CoreLogData)}
|
2017-05-09 12:02:44 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
func (l *LogHandler) ServeHTTP(rw http.ResponseWriter, req *http.Request, next http.HandlerFunc) {
|
|
|
|
now := time.Now().UTC()
|
2018-05-14 08:38:03 +00:00
|
|
|
|
|
|
|
core := CoreLogData{
|
|
|
|
StartUTC: now,
|
|
|
|
StartLocal: now.Local(),
|
|
|
|
}
|
2017-05-09 12:02:44 +00:00
|
|
|
|
|
|
|
logDataTable := &LogData{Core: core, Request: req.Header}
|
|
|
|
|
|
|
|
reqWithDataTable := req.WithContext(context.WithValue(req.Context(), DataTableKey, logDataTable))
|
|
|
|
|
|
|
|
var crr *captureRequestReader
|
|
|
|
if req.Body != nil {
|
|
|
|
crr = &captureRequestReader{source: req.Body, count: 0}
|
|
|
|
reqWithDataTable.Body = crr
|
|
|
|
}
|
|
|
|
|
|
|
|
core[RequestCount] = nextRequestCount()
|
|
|
|
if req.Host != "" {
|
|
|
|
core[RequestAddr] = req.Host
|
|
|
|
core[RequestHost], core[RequestPort] = silentSplitHostPort(req.Host)
|
|
|
|
}
|
|
|
|
// copy the URL without the scheme, hostname etc
|
|
|
|
urlCopy := &url.URL{
|
|
|
|
Path: req.URL.Path,
|
|
|
|
RawPath: req.URL.RawPath,
|
|
|
|
RawQuery: req.URL.RawQuery,
|
|
|
|
ForceQuery: req.URL.ForceQuery,
|
|
|
|
Fragment: req.URL.Fragment,
|
|
|
|
}
|
|
|
|
urlCopyString := urlCopy.String()
|
|
|
|
core[RequestMethod] = req.Method
|
|
|
|
core[RequestPath] = urlCopyString
|
|
|
|
core[RequestProtocol] = req.Proto
|
|
|
|
|
|
|
|
core[ClientAddr] = req.RemoteAddr
|
|
|
|
core[ClientHost], core[ClientPort] = silentSplitHostPort(req.RemoteAddr)
|
|
|
|
|
2017-08-25 11:00:03 +00:00
|
|
|
if forwardedFor := req.Header.Get("X-Forwarded-For"); forwardedFor != "" {
|
|
|
|
core[ClientHost] = forwardedFor
|
|
|
|
}
|
|
|
|
|
2017-05-09 12:02:44 +00:00
|
|
|
crw := &captureResponseWriter{rw: rw}
|
|
|
|
|
|
|
|
next.ServeHTTP(crw, reqWithDataTable)
|
|
|
|
|
2018-01-24 17:18:03 +00:00
|
|
|
core[ClientUsername] = usernameIfPresent(reqWithDataTable.URL)
|
|
|
|
|
2017-05-09 12:02:44 +00:00
|
|
|
logDataTable.DownstreamResponse = crw.Header()
|
2018-05-23 14:46:04 +00:00
|
|
|
|
|
|
|
if l.config.BufferingSize > 0 {
|
|
|
|
l.logHandlerChan <- logHandlerParams{
|
|
|
|
logDataTable: logDataTable,
|
|
|
|
crr: crr,
|
|
|
|
crw: crw,
|
|
|
|
}
|
|
|
|
} else {
|
|
|
|
l.logTheRoundTrip(logDataTable, crr, crw)
|
|
|
|
}
|
2017-05-09 12:02:44 +00:00
|
|
|
}
|
|
|
|
|
2018-05-23 14:46:04 +00:00
|
|
|
// Close closes the Logger (i.e. the file, drain logHandlerChan, etc).
|
2017-05-09 12:02:44 +00:00
|
|
|
func (l *LogHandler) Close() error {
|
2018-05-23 14:46:04 +00:00
|
|
|
close(l.logHandlerChan)
|
|
|
|
l.wg.Wait()
|
2017-05-22 19:39:29 +00:00
|
|
|
return l.file.Close()
|
2017-05-09 12:02:44 +00:00
|
|
|
}
|
|
|
|
|
2017-08-11 10:04:58 +00:00
|
|
|
// Rotate closes and reopens the log file to allow for rotation
|
|
|
|
// by an external source.
|
|
|
|
func (l *LogHandler) Rotate() error {
|
|
|
|
var err error
|
2017-09-15 13:02:03 +00:00
|
|
|
|
|
|
|
if l.file != nil {
|
|
|
|
defer func(f *os.File) {
|
|
|
|
f.Close()
|
|
|
|
}(l.file)
|
2017-08-11 10:04:58 +00:00
|
|
|
}
|
|
|
|
|
2018-03-23 08:28:03 +00:00
|
|
|
l.file, err = os.OpenFile(l.config.FilePath, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0664)
|
2017-08-11 10:04:58 +00:00
|
|
|
if err != nil {
|
|
|
|
return err
|
|
|
|
}
|
2017-09-15 13:02:03 +00:00
|
|
|
l.mu.Lock()
|
|
|
|
defer l.mu.Unlock()
|
2017-08-11 10:04:58 +00:00
|
|
|
l.logger.Out = l.file
|
|
|
|
return nil
|
|
|
|
}
|
|
|
|
|
2017-05-09 12:02:44 +00:00
|
|
|
func silentSplitHostPort(value string) (host string, port string) {
|
|
|
|
host, port, err := net.SplitHostPort(value)
|
|
|
|
if err != nil {
|
|
|
|
return value, "-"
|
|
|
|
}
|
|
|
|
return host, port
|
|
|
|
}
|
|
|
|
|
|
|
|
func usernameIfPresent(theURL *url.URL) string {
|
|
|
|
username := "-"
|
|
|
|
if theURL.User != nil {
|
|
|
|
if name := theURL.User.Username(); name != "" {
|
|
|
|
username = name
|
|
|
|
}
|
|
|
|
}
|
|
|
|
return username
|
|
|
|
}
|
|
|
|
|
|
|
|
// Logging handler to log frontend name, backend name, and elapsed time
|
|
|
|
func (l *LogHandler) logTheRoundTrip(logDataTable *LogData, crr *captureRequestReader, crw *captureResponseWriter) {
|
|
|
|
core := logDataTable.Core
|
|
|
|
|
2018-03-23 08:28:03 +00:00
|
|
|
retryAttempts, ok := core[RetryAttempts].(int)
|
|
|
|
if !ok {
|
|
|
|
retryAttempts = 0
|
2017-08-28 10:50:02 +00:00
|
|
|
}
|
2018-03-23 08:28:03 +00:00
|
|
|
core[RetryAttempts] = retryAttempts
|
|
|
|
|
2017-05-09 12:02:44 +00:00
|
|
|
if crr != nil {
|
|
|
|
core[RequestContentSize] = crr.count
|
|
|
|
}
|
|
|
|
|
|
|
|
core[DownstreamStatus] = crw.Status()
|
2018-03-14 13:12:04 +00:00
|
|
|
|
2018-06-11 16:40:08 +00:00
|
|
|
// 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) {
|
2018-03-14 13:12:04 +00:00
|
|
|
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())
|
|
|
|
}
|
2017-05-09 12:02:44 +00:00
|
|
|
}
|
|
|
|
|
2018-06-11 16:40:08 +00:00
|
|
|
core[Overhead] = totalDuration
|
2018-03-14 13:12:04 +00:00
|
|
|
if origin, ok := core[OriginDuration]; ok {
|
2018-06-11 16:40:08 +00:00
|
|
|
core[Overhead] = totalDuration - origin.(time.Duration)
|
2018-03-14 13:12:04 +00:00
|
|
|
}
|
2017-05-22 19:39:29 +00:00
|
|
|
|
2018-03-14 13:12:04 +00:00
|
|
|
fields := logrus.Fields{}
|
2017-05-22 19:39:29 +00:00
|
|
|
|
2018-03-14 13:12:04 +00:00
|
|
|
for k, v := range logDataTable.Core {
|
2018-03-23 08:28:03 +00:00
|
|
|
if l.config.Fields.Keep(k) {
|
2018-03-14 13:12:04 +00:00
|
|
|
fields[k] = v
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
l.redactHeaders(logDataTable.Request, fields, "request_")
|
|
|
|
l.redactHeaders(logDataTable.OriginResponse, fields, "origin_")
|
|
|
|
l.redactHeaders(logDataTable.DownstreamResponse, fields, "downstream_")
|
2017-05-22 19:39:29 +00:00
|
|
|
|
2018-03-14 13:12:04 +00:00
|
|
|
l.mu.Lock()
|
|
|
|
defer l.mu.Unlock()
|
|
|
|
l.logger.WithFields(fields).Println()
|
2017-05-22 19:39:29 +00:00
|
|
|
}
|
2018-03-14 13:12:04 +00:00
|
|
|
}
|
2017-05-22 19:39:29 +00:00
|
|
|
|
2018-03-14 13:12:04 +00:00
|
|
|
func (l *LogHandler) redactHeaders(headers http.Header, fields logrus.Fields, prefix string) {
|
|
|
|
for k := range headers {
|
2018-03-23 08:28:03 +00:00
|
|
|
v := l.config.Fields.KeepHeader(k)
|
2018-03-14 13:12:04 +00:00
|
|
|
if v == types.AccessLogKeep {
|
|
|
|
fields[prefix+k] = headers.Get(k)
|
|
|
|
} else if v == types.AccessLogRedact {
|
|
|
|
fields[prefix+k] = "REDACTED"
|
|
|
|
}
|
2017-05-22 19:39:29 +00:00
|
|
|
}
|
2018-03-14 13:12:04 +00:00
|
|
|
}
|
2017-05-22 19:39:29 +00:00
|
|
|
|
2018-06-11 16:40:08 +00:00
|
|
|
func (l *LogHandler) keepAccessLog(statusCode, retryAttempts int, duration time.Duration) bool {
|
2018-04-23 08:54:03 +00:00
|
|
|
if l.config.Filters == nil {
|
2018-03-23 08:28:03 +00:00
|
|
|
// no filters were specified
|
2018-03-14 13:12:04 +00:00
|
|
|
return true
|
2018-04-23 08:54:03 +00:00
|
|
|
}
|
|
|
|
|
2018-06-11 16:40:08 +00:00
|
|
|
if len(l.httpCodeRanges) == 0 && !l.config.Filters.RetryAttempts && l.config.Filters.MinDuration == 0 {
|
2018-03-23 08:28:03 +00:00
|
|
|
// empty filters were specified, e.g. by passing --accessLog.filters only (without other filter options)
|
|
|
|
return true
|
2018-04-23 08:54:03 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
if l.httpCodeRanges.Contains(statusCode) {
|
2018-03-23 08:28:03 +00:00
|
|
|
return true
|
2018-04-23 08:54:03 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
if l.config.Filters.RetryAttempts && retryAttempts > 0 {
|
2018-03-23 08:28:03 +00:00
|
|
|
return true
|
2017-05-22 19:39:29 +00:00
|
|
|
}
|
2017-05-09 12:02:44 +00:00
|
|
|
|
2018-06-11 16:40:08 +00:00
|
|
|
if l.config.Filters.MinDuration > 0 && (parse.Duration(duration) > l.config.Filters.MinDuration) {
|
|
|
|
return true
|
|
|
|
}
|
|
|
|
|
2018-04-23 08:54:03 +00:00
|
|
|
return false
|
|
|
|
}
|
2017-05-09 12:02:44 +00:00
|
|
|
|
|
|
|
var requestCounter uint64 // Request ID
|
|
|
|
|
|
|
|
func nextRequestCount() uint64 {
|
|
|
|
return atomic.AddUint64(&requestCounter, 1)
|
|
|
|
}
|