traefik/pkg/middlewares/accesslog/logger.go
2020-07-07 14:42:03 +02:00

371 lines
9 KiB
Go

package accesslog
import (
"context"
"fmt"
"io"
"net"
"net/http"
"net/url"
"os"
"path/filepath"
"sync"
"sync/atomic"
"time"
"github.com/containous/alice"
"github.com/containous/traefik/v2/pkg/log"
"github.com/containous/traefik/v2/pkg/types"
"github.com/sirupsen/logrus"
)
type key string
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 string = "common"
// JSONFormat is the JSON logging format.
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
}
type handlerParams struct {
logDataTable *LogData
}
// Handler will write each request and its response to the access log.
type Handler struct {
config *types.AccessLog
logger *logrus.Logger
file io.WriteCloser
mu sync.Mutex
httpCodeRanges types.HTTPCodeRanges
logHandlerChan chan handlerParams
wg sync.WaitGroup
}
// 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) {
handler.ServeHTTP(rw, req, next)
}), 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: %w", err)
}
file = f
}
logHandlerChan := make(chan handlerParams, config.BufferingSize)
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)
}
logger := &logrus.Logger{
Out: file,
Formatter: formatter,
Hooks: make(logrus.LevelHooks),
Level: logrus.InfoLevel,
}
logHandler := &Handler{
config: config,
logger: logger,
file: file,
logHandlerChan: logHandlerChan,
}
if config.Filters != nil {
if httpCodeRanges, err := types.NewHTTPCodeRanges(config.Filters.StatusCodes); err != nil {
log.WithoutContext().Errorf("Failed to create new HTTP code ranges: %s", err)
} else {
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)
}
}()
}
return logHandler, nil
}
func openAccessLogFile(filePath string) (*os.File, error) {
dir := filepath.Dir(filePath)
if err := os.MkdirAll(dir, 0o755); err != nil {
return nil, fmt.Errorf("failed to create log path %s: %w", dir, err)
}
file, err := os.OpenFile(filePath, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0o664)
if err != nil {
return nil, fmt.Errorf("error opening file %s: %w", filePath, err)
}
return file, nil
}
// GetLogData gets the request context object that contains logging data.
// This creates data as the request passes through the middleware chain.
func GetLogData(req *http.Request) *LogData {
if ld, ok := req.Context().Value(DataTableKey).(*LogData); ok {
return ld
}
return nil
}
func (h *Handler) ServeHTTP(rw http.ResponseWriter, req *http.Request, next http.Handler) {
now := time.Now().UTC()
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
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)
}
logDataTable.DownstreamResponse = downstreamResponse{
headers: crw.Header().Clone(),
status: crw.Status(),
size: crw.Size(),
}
if crr != nil {
logDataTable.Request.size = crr.count
}
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).
func (h *Handler) Close() error {
close(h.logHandlerChan)
h.wg.Wait()
return h.file.Close()
}
// 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
}
if h.file != nil {
defer func(f io.Closer) { _ = f.Close() }(h.file)
}
var err error
h.file, err = os.OpenFile(h.config.FilePath, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0o664)
if err != nil {
return err
}
h.mu.Lock()
defer h.mu.Unlock()
h.logger.Out = h.file
return nil
}
func silentSplitHostPort(value string) (host, port string) {
host, port, err := net.SplitHostPort(value)
if err != nil {
return value, "-"
}
return host, port
}
func usernameIfPresent(theURL *url.URL) string {
if theURL.User != nil {
if name := theURL.User.Username(); name != "" {
return name
}
}
return "-"
}
// 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
// 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 h.keepAccessLog(status, retryAttempts, totalDuration) {
size := logDataTable.DownstreamResponse.size
core[DownstreamContentSize] = size
if original, ok := core[OriginContentSize]; ok {
o64 := original.(int64)
if size != o64 && size != 0 {
core[GzipRatio] = float64(o64) / float64(size)
}
}
core[Overhead] = totalDuration
if origin, ok := core[OriginDuration]; ok {
core[Overhead] = totalDuration - origin.(time.Duration)
}
fields := logrus.Fields{}
for k, v := range logDataTable.Core {
if h.config.Fields.Keep(k) {
fields[k] = v
}
}
h.redactHeaders(logDataTable.Request.headers, fields, "request_")
h.redactHeaders(logDataTable.OriginResponse, fields, "origin_")
h.redactHeaders(logDataTable.DownstreamResponse.headers, fields, "downstream_")
h.mu.Lock()
defer h.mu.Unlock()
h.logger.WithFields(fields).Println()
}
}
func (h *Handler) redactHeaders(headers http.Header, fields logrus.Fields, prefix string) {
for k := range headers {
v := h.config.Fields.KeepHeader(k)
if v == types.AccessLogKeep {
fields[prefix+k] = headers.Get(k)
} else if v == types.AccessLogRedact {
fields[prefix+k] = "REDACTED"
}
}
}
func (h *Handler) keepAccessLog(statusCode, retryAttempts int, duration time.Duration) bool {
if h.config.Filters == nil {
// no filters were specified
return true
}
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
}
if h.httpCodeRanges.Contains(statusCode) {
return true
}
if h.config.Filters.RetryAttempts && retryAttempts > 0 {
return true
}
if h.config.Filters.MinDuration > 0 && (types.Duration(duration) > h.config.Filters.MinDuration) {
return true
}
return false
}
var requestCounter uint64 // Request ID
func nextRequestCount() uint64 {
return atomic.AddUint64(&requestCounter, 1)
}