Revert "Revert "First stage of access logging middleware. Initially w…

…ithout any output appenders.""

This reverts commit 8265198.

middlewares/accesslog/capture_request_reader.go

@@ -0,0 +1,18 @@
+package accesslog
+
+import "io"
+
+type captureRequestReader struct {
+	source io.ReadCloser
+	count  int64
+}
+
+func (r *captureRequestReader) Read(p []byte) (int, error) {
+	n, err := r.source.Read(p)
+	r.count += int64(n)
+	return n, err
+}
+
+func (r *captureRequestReader) Close() error {
+	return r.source.Close()
+}

middlewares/accesslog/capture_response_writer.go

@@ -0,0 +1,69 @@
+package accesslog
+
+import (
+	"bufio"
+	"fmt"
+	"net"
+	"net/http"
+)
+
+var (
+	_ http.ResponseWriter = &captureResponseWriter{}
+	_ http.Hijacker       = &captureResponseWriter{}
+	_ http.Flusher        = &captureResponseWriter{}
+	_ http.CloseNotifier  = &captureResponseWriter{}
+)
+
+// captureResponseWriter is a wrapper of type http.ResponseWriter
+// that tracks request status and size
+type captureResponseWriter struct {
+	rw     http.ResponseWriter
+	status int
+	size   int64
+}
+
+func (crw *captureResponseWriter) Header() http.Header {
+	return crw.rw.Header()
+}
+
+func (crw *captureResponseWriter) Write(b []byte) (int, error) {
+	if crw.status == 0 {
+		crw.status = http.StatusOK
+	}
+	size, err := crw.rw.Write(b)
+	crw.size += int64(size)
+	return size, err
+}
+
+func (crw *captureResponseWriter) WriteHeader(s int) {
+	crw.rw.WriteHeader(s)
+	crw.status = s
+}
+
+func (crw *captureResponseWriter) Flush() {
+	if f, ok := crw.rw.(http.Flusher); ok {
+		f.Flush()
+	}
+}
+
+func (crw *captureResponseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) {
+	if h, ok := crw.rw.(http.Hijacker); ok {
+		return h.Hijack()
+	}
+	return nil, nil, fmt.Errorf("Not a hijacker: %T", crw.rw)
+}
+
+func (crw *captureResponseWriter) CloseNotify() <-chan bool {
+	if c, ok := crw.rw.(http.CloseNotifier); ok {
+		return c.CloseNotify()
+	}
+	return nil
+}
+
+func (crw *captureResponseWriter) Status() int {
+	return crw.status
+}
+
+func (crw *captureResponseWriter) Size() int64 {
+	return crw.size
+}

middlewares/accesslog/logdata.go

@@ -0,0 +1,124 @@
+package accesslog
+
+import (
+	"net/http"
+)
+
+const (
+	// StartUTC is the map key used for the time at which request processing started.
+	StartUTC = "StartUTC"
+	// StartLocal is the map key used for the local time at which request processing started.
+	StartLocal = "StartLocal"
+	// Duration is the map key used for the total time taken by processing the response, including the origin server's time but
+	// not the log writing time.
+	Duration = "Duration"
+	// FrontendName is the map key used for the name of the Traefik frontend.
+	FrontendName = "FrontendName"
+	// BackendName is the map key used for the name of the Traefik backend.
+	BackendName = "BackendName"
+	// BackendURL is the map key used for the URL of the Traefik backend.
+	BackendURL = "BackendURL"
+	// BackendAddr is the map key used for the IP:port of the Traefik backend (extracted from BackendURL)
+	BackendAddr = "BackendAddr"
+	// ClientAddr is the map key used for the remote address in its original form (usually IP:port).
+	ClientAddr = "ClientAddr"
+	// ClientHost is the map key used for the remote IP address from which the client request was received.
+	ClientHost = "ClientHost"
+	// ClientPort is the map key used for the remote TCP port from which the client request was received.
+	ClientPort = "ClientPort"
+	// ClientUsername is the map key used for the username provided in the URL, if present.
+	ClientUsername = "ClientUsername"
+	// RequestAddr is the map key used for the HTTP Host header (usually IP:port). This is treated as not a header by the Go API.
+	RequestAddr = "RequestAddr"
+	// RequestHost is the map key used for the HTTP Host server name (not including port).
+	RequestHost = "RequestHost"
+	// RequestPort is the map key used for the TCP port from the HTTP Host.
+	RequestPort = "RequestPort"
+	// RequestMethod is the map key used for the HTTP method.
+	RequestMethod = "RequestMethod"
+	// RequestPath is the map key used for the HTTP request URI, not including the scheme, host or port.
+	RequestPath = "RequestPath"
+	// RequestProtocol is the map key used for the version of HTTP requested.
+	RequestProtocol = "RequestProtocol"
+	// RequestLine is the original request line
+	RequestLine = "RequestLine"
+	// RequestContentSize is the map key used for the number of bytes in the request entity (a.k.a. body) sent by the client.
+	RequestContentSize = "RequestContentSize"
+	// OriginDuration is the map key used for the time taken by the origin server ('upstream') to return its response.
+	OriginDuration = "OriginDuration"
+	// OriginContentSize is the map key used for the content length specified by the origin server, or 0 if unspecified.
+	OriginContentSize = "OriginContentSize"
+	// OriginStatus is the map key used for the HTTP status code returned by the origin server.
+	// If the request was handled by this Traefik instance (e.g. with a redirect), then this value will be absent.
+	OriginStatus = "OriginStatus"
+	// OriginStatusLine is the map key used for the HTTP status code and corresponding descriptive string.
+	// If the request was handled by this Traefik instance (e.g. with a redirect), then this value will be absent.
+	// Note that the actual message string might be different to what is reported here, depending on server behaviour.
+	OriginStatusLine = "OriginStatusLine"
+	// DownstreamStatus is the map key used for the HTTP status code returned to the client.
+	DownstreamStatus = "DownstreamStatus"
+	// DownstreamStatusLine is the map key used for the HTTP status line returned to the client.
+	DownstreamStatusLine = "DownstreamStatusLine"
+	// DownstreamContentSize is the map key used for the number of bytes in the response entity returned to the client.
+	// This is in addition to the "Content-Length" header, which may be present in the origin response.
+	DownstreamContentSize = "DownstreamContentSize"
+	// RequestCount is the map key used for the number of requests received since the Traefik instance started.
+	RequestCount = "RequestCount"
+	// GzipRatio is the map key used for the response body compression ratio achieved.
+	GzipRatio = "GzipRatio"
+	// Overhead is the map key used for the processing time overhead caused by Traefik.
+	Overhead = "Overhead"
+)
+
+// These are written out in the default case when no config is provided to specify keys of interest.
+var defaultCoreKeys = [...]string{
+	StartUTC,
+	Duration,
+	FrontendName,
+	BackendName,
+	BackendURL,
+	ClientHost,
+	ClientPort,
+	ClientUsername,
+	RequestHost,
+	RequestPort,
+	RequestMethod,
+	RequestPath,
+	RequestProtocol,
+	RequestContentSize,
+	OriginDuration,
+	OriginContentSize,
+	OriginStatus,
+	DownstreamStatus,
+	DownstreamContentSize,
+	RequestCount,
+}
+
+// This contains the set of all keys, i.e. all the default keys plus all non-default keys.
+var allCoreKeys = make(map[string]struct{})
+
+func init() {
+	for _, k := range defaultCoreKeys {
+		allCoreKeys[k] = struct{}{}
+	}
+	allCoreKeys[BackendAddr] = struct{}{}
+	allCoreKeys[ClientAddr] = struct{}{}
+	allCoreKeys[RequestAddr] = struct{}{}
+	allCoreKeys[RequestLine] = struct{}{}
+	allCoreKeys[OriginStatusLine] = struct{}{}
+	allCoreKeys[DownstreamStatusLine] = struct{}{}
+	allCoreKeys[GzipRatio] = struct{}{}
+	allCoreKeys[StartLocal] = struct{}{}
+	allCoreKeys[Overhead] = struct{}{}
+}
+
+// CoreLogData holds the fields computed from the request/response.
+type CoreLogData map[string]interface{}
+
+// LogData is the data captured by the middleware so that it can be logged.
+type LogData struct {
+	Core               CoreLogData
+	Request            http.Header
+	OriginResponse     http.Header
+	DownstreamResponse http.Header
+}

middlewares/accesslog/logger.go

@@ -0,0 +1,144 @@
+package accesslog
+
+import (
+	"context"
+	"fmt"
+	"net"
+	"net/http"
+	"net/url"
+	"sync/atomic"
+	"time"
+)
+
+type key string
+
+const (
+	// DataTableKey is the key within the request context used to
+	// store the Log Data Table
+	DataTableKey key = "LogDataTable"
+)
+
+// 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 {
+}
+
+// NewLogHandler creates a new LogHandler
+func NewLogHandler() *LogHandler {
+	return &LogHandler{}
+}
+
+// GetLogDataTable gets the request context object that contains logging data. This accretes
+// data as the request passes through the middleware chain.
+func GetLogDataTable(req *http.Request) *LogData {
+	return req.Context().Value(DataTableKey).(*LogData)
+}
+
+func (l *LogHandler) ServeHTTP(rw http.ResponseWriter, req *http.Request, next http.HandlerFunc) {
+	now := time.Now().UTC()
+	core := make(CoreLogData)
+
+	logDataTable := &LogData{Core: core, Request: req.Header}
+	core[StartUTC] = now
+	core[StartLocal] = now.Local()
+
+	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[RequestLine] = fmt.Sprintf("%s %s %s", req.Method, urlCopyString, req.Proto)
+
+	core[ClientAddr] = req.RemoteAddr
+	core[ClientHost], core[ClientPort] = silentSplitHostPort(req.RemoteAddr)
+	core[ClientUsername] = usernameIfPresent(req.URL)
+
+	crw := &captureResponseWriter{rw: rw}
+
+	next.ServeHTTP(crw, reqWithDataTable)
+
+	logDataTable.DownstreamResponse = crw.Header()
+	l.logTheRoundTrip(logDataTable, crr, crw)
+}
+
+// Close closes the Logger (i.e. the file etc).
+func (l *LogHandler) Close() error {
+	return nil
+}
+
+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
+
+	if crr != nil {
+		core[RequestContentSize] = crr.count
+	}
+
+	core[DownstreamStatus] = crw.Status()
+	core[DownstreamStatusLine] = fmt.Sprintf("%03d %s", crw.Status(), http.StatusText(crw.Status()))
+	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())
+		}
+	}
+
+	// n.b. take care to perform time arithmetic using UTC to avoid errors at DST boundaries
+	total := time.Now().UTC().Sub(core[StartUTC].(time.Time))
+	core[Duration] = total
+	if origin, ok := core[OriginDuration]; ok {
+		core[Overhead] = total - origin.(time.Duration)
+	} else {
+		core[Overhead] = total
+	}
+}
+
+//-------------------------------------------------------------------------------------------------
+
+var requestCounter uint64 // Request ID
+
+func nextRequestCount() uint64 {
+	return atomic.AddUint64(&requestCounter, 1)
+}