traefik/pkg/middlewares/accesslog/logger.go

372 lines
9 KiB
Go
Raw Normal View History

package accesslog
import (
"context"
"fmt"
"io"
"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"
"sync/atomic"
"time"
2017-05-22 19:39:29 +00:00
2018-11-14 09:18:03 +00:00
"github.com/containous/alice"
2019-08-03 01:58:23 +00:00
"github.com/containous/traefik/v2/pkg/log"
"github.com/containous/traefik/v2/pkg/types"
2018-01-22 11:16:03 +00:00
"github.com/sirupsen/logrus"
)
type key string
const (
2018-11-14 09:18:03 +00:00
// 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
2018-11-14 09:18:03 +00:00
// CommonFormat is the common logging format (CLF).
2018-08-06 18:00:03 +00:00
CommonFormat string = "common"
2017-05-25 11:25:53 +00:00
2018-11-14 09:18:03 +00:00
// JSONFormat is the JSON logging format.
2018-08-06 18:00:03 +00:00
JSONFormat string = "json"
)
type noopCloser struct {
*os.File
}
func (n noopCloser) Write(p []byte) (int, error) {
return n.File.Write(p)
}
func (n noopCloser) Close() error {
// noop
return nil
}
2018-11-14 09:18:03 +00:00
type handlerParams struct {
logDataTable *LogData
}
2018-11-14 09:18:03 +00:00
// Handler will write each request and its response to the access log.
type Handler struct {
config *types.AccessLog
2018-03-14 13:12:04 +00:00
logger *logrus.Logger
file io.WriteCloser
2018-03-14 13:12:04 +00:00
mu sync.Mutex
httpCodeRanges types.HTTPCodeRanges
2018-11-14 09:18:03 +00:00
logHandlerChan chan handlerParams
wg sync.WaitGroup
}
2018-11-14 09:18:03 +00:00
// WrapHandler Wraps access log handler into an Alice Constructor.
func WrapHandler(handler *Handler) alice.Constructor {
return func(next http.Handler) (http.Handler, error) {
return http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) {
2019-03-18 10:30:07 +00:00
handler.ServeHTTP(rw, req, next)
2018-11-14 09:18:03 +00:00
}), nil
}
}
// NewHandler creates a new Handler.
func NewHandler(config *types.AccessLog) (*Handler, error) {
var file io.WriteCloser = noopCloser{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-11-14 09:18:03 +00:00
logHandlerChan := make(chan handlerParams, 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:
log.WithoutContext().Errorf("unsupported access log format: %q, defaulting to common format instead.", config.Format)
formatter = new(CommonLogFormatter)
2017-05-25 11:25:53 +00:00
}
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
2018-11-14 09:18:03 +00:00
logHandler := &Handler{
config: config,
logger: logger,
file: file,
logHandlerChan: logHandlerChan,
2018-03-14 13:12:04 +00:00
}
if config.Filters != nil {
if httpCodeRanges, err := types.NewHTTPCodeRanges(config.Filters.StatusCodes); err != nil {
2018-11-14 09:18:03 +00:00
log.WithoutContext().Errorf("Failed to create new HTTP code ranges: %s", err)
} else {
2018-03-14 13:12:04 +00:00
logHandler.httpCodeRanges = httpCodeRanges
}
}
if config.BufferingSize > 0 {
logHandler.wg.Add(1)
go func() {
defer logHandler.wg.Done()
for handlerParams := range logHandler.logHandlerChan {
logHandler.logTheRoundTrip(handlerParams.logDataTable)
}
}()
}
2018-03-14 13:12:04 +00:00
return logHandler, nil
}
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-11-14 09:18:03 +00:00
// GetLogData gets the request context object that contains logging data.
2018-05-14 08:38:03 +00:00
// This creates data as the request passes through the middleware chain.
2018-11-14 09:18:03 +00:00
func GetLogData(req *http.Request) *LogData {
2018-05-14 08:38:03 +00:00
if ld, ok := req.Context().Value(DataTableKey).(*LogData); ok {
return ld
}
2018-11-14 09:18:03 +00:00
return nil
}
2019-03-18 10:30:07 +00:00
func (h *Handler) ServeHTTP(rw http.ResponseWriter, req *http.Request, next http.Handler) {
now := time.Now().UTC()
2018-05-14 08:38:03 +00:00
core := CoreLogData{
StartUTC: now,
StartLocal: now.Local(),
}
logDataTable := &LogData{
Core: core,
Request: request{
headers: 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
2020-02-17 09:46:04 +00:00
core[RequestScheme] = "http"
if req.TLS != nil {
core[RequestScheme] = "https"
}
core[ClientAddr] = req.RemoteAddr
core[ClientHost], core[ClientPort] = silentSplitHostPort(req.RemoteAddr)
if forwardedFor := req.Header.Get("X-Forwarded-For"); forwardedFor != "" {
core[ClientHost] = forwardedFor
}
crw := newCaptureResponseWriter(rw)
next.ServeHTTP(crw, reqWithDataTable)
if _, ok := core[ClientUsername]; !ok {
core[ClientUsername] = usernameIfPresent(reqWithDataTable.URL)
}
2018-01-24 17:18:03 +00:00
logDataTable.DownstreamResponse = downstreamResponse{
headers: crw.Header().Clone(),
status: crw.Status(),
size: crw.Size(),
}
if crr != nil {
logDataTable.Request.size = crr.count
}
2018-11-14 09:18:03 +00:00
if h.config.BufferingSize > 0 {
h.logHandlerChan <- handlerParams{
logDataTable: logDataTable,
}
} else {
h.logTheRoundTrip(logDataTable)
}
}
// Close closes the Logger (i.e. the file, drain logHandlerChan, etc).
2018-11-14 09:18:03 +00:00
func (h *Handler) Close() error {
close(h.logHandlerChan)
h.wg.Wait()
return h.file.Close()
}
2018-11-14 09:18:03 +00:00
// Rotate closes and reopens the log file to allow for rotation by an external source.
func (h *Handler) Rotate() error {
if h.config.FilePath == "" {
return nil
}
2017-09-15 13:02:03 +00:00
2018-11-14 09:18:03 +00:00
if h.file != nil {
defer func(f io.Closer) { _ = f.Close() }(h.file)
}
var err error
2018-11-14 09:18:03 +00:00
h.file, err = os.OpenFile(h.config.FilePath, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0664)
if err != nil {
return err
}
2018-11-14 09:18:03 +00:00
h.mu.Lock()
defer h.mu.Unlock()
h.logger.Out = h.file
return nil
}
func silentSplitHostPort(value string) (host string, port string) {
host, port, err := net.SplitHostPort(value)
if err != nil {
return value, "-"
}
return host, port
}
2018-11-14 09:18:03 +00:00
func usernameIfPresent(theURL *url.URL) string {
if theURL.User != nil {
if name := theURL.User.Username(); name != "" {
return name
}
}
2018-10-25 16:00:05 +00:00
return "-"
}
2018-11-14 09:18:03 +00:00
// Logging handler to log frontend name, backend name, and elapsed time.
func (h *Handler) logTheRoundTrip(logDataTable *LogData) {
core := logDataTable.Core
retryAttempts, ok := core[RetryAttempts].(int)
if !ok {
retryAttempts = 0
}
core[RetryAttempts] = retryAttempts
core[RequestContentSize] = logDataTable.Request.size
status := logDataTable.DownstreamResponse.status
core[DownstreamStatus] = status
2018-03-14 13:12:04 +00:00
2018-11-14 09:18:03 +00:00
// n.b. take care to perform time arithmetic using UTC to avoid errors at DST boundaries.
2018-06-11 16:40:08 +00:00
totalDuration := time.Now().UTC().Sub(core[StartUTC].(time.Time))
core[Duration] = totalDuration
if h.keepAccessLog(status, retryAttempts, totalDuration) {
size := logDataTable.DownstreamResponse.size
core[DownstreamContentSize] = size
2018-03-14 13:12:04 +00:00
if original, ok := core[OriginContentSize]; ok {
o64 := original.(int64)
if size != o64 && size != 0 {
core[GzipRatio] = float64(o64) / float64(size)
2018-03-14 13:12:04 +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-11-14 09:18:03 +00:00
if h.config.Fields.Keep(k) {
2018-03-14 13:12:04 +00:00
fields[k] = v
}
}
h.redactHeaders(logDataTable.Request.headers, fields, "request_")
2018-11-14 09:18:03 +00:00
h.redactHeaders(logDataTable.OriginResponse, fields, "origin_")
h.redactHeaders(logDataTable.DownstreamResponse.headers, fields, "downstream_")
2017-05-22 19:39:29 +00:00
2018-11-14 09:18:03 +00:00
h.mu.Lock()
defer h.mu.Unlock()
h.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-11-14 09:18:03 +00:00
func (h *Handler) redactHeaders(headers http.Header, fields logrus.Fields, prefix string) {
2018-03-14 13:12:04 +00:00
for k := range headers {
2018-11-14 09:18:03 +00:00
v := h.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-11-14 09:18:03 +00:00
func (h *Handler) keepAccessLog(statusCode, retryAttempts int, duration time.Duration) bool {
if h.config.Filters == nil {
// no filters were specified
2018-03-14 13:12:04 +00:00
return true
2018-04-23 08:54:03 +00:00
}
2018-11-14 09:18:03 +00:00
if len(h.httpCodeRanges) == 0 && !h.config.Filters.RetryAttempts && h.config.Filters.MinDuration == 0 {
// 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
}
2018-11-14 09:18:03 +00:00
if h.httpCodeRanges.Contains(statusCode) {
return true
2018-04-23 08:54:03 +00:00
}
2018-11-14 09:18:03 +00:00
if h.config.Filters.RetryAttempts && retryAttempts > 0 {
return true
2017-05-22 19:39:29 +00:00
}
if h.config.Filters.MinDuration > 0 && (types.Duration(duration) > h.config.Filters.MinDuration) {
2018-06-11 16:40:08 +00:00
return true
}
2018-04-23 08:54:03 +00:00
return false
}
var requestCounter uint64 // Request ID
func nextRequestCount() uint64 {
return atomic.AddUint64(&requestCounter, 1)
}