Issue #80: Add support for access logging

This patch is based on the PR #131 from [email protected].

It adds support for configurable access logging to either
stdout or stderr for HTTP requests.

Fixes #80

.gitignore

@@ -1,5 +1,6 @@
 *-amd64
 *.out
+*.orig
 *.p12
 *.pem
 *.pprof

config/config.go

@@ -57,6 +57,7 @@ type Proxy struct {
 	TLSHeaderValue        string
 	GZIPContentTypes      *regexp.Regexp
 	LogRoutes             string
+	Log                   Log
 }
 
 type Runtime struct {
@@ -72,6 +73,11 @@ type Circonus struct {
 	BrokerID string
 }
 
+type Log struct {
+	Target string
+	Format string
+}
+
 type Metrics struct {
 	Target       string
 	Prefix       string

config/default.go

@@ -26,6 +26,9 @@ var defaultConfig = &Config{
 		FlushInterval: time.Second,
 		LocalIP:       LocalIPString(),
 		LogRoutes:     "delta",
+		Log: Log{
+			Format: "common",
+		},
 	},
 	Registry: Registry{
 		Backend: "consul",

config/load.go

@@ -132,6 +132,8 @@ func load(cmdline, environ, envprefix []string, props *properties.Properties) (c
 	f.DurationVar(&writeTimeout, "proxy.writetimeout", defaultValues.WriteTimeout, "write timeout for outgoing responses")
 	f.DurationVar(&cfg.Proxy.FlushInterval, "proxy.flushinterval", defaultConfig.Proxy.FlushInterval, "flush interval for streaming responses")
 	f.StringVar(&cfg.Proxy.LogRoutes, "proxy.log.routes", defaultConfig.Proxy.LogRoutes, "log format of routing table updates")
+	f.StringVar(&cfg.Proxy.Log.Format, "proxy.log.format", defaultConfig.Proxy.Log.Format, "access log format")
+	f.StringVar(&cfg.Proxy.Log.Target, "proxy.log.target", defaultConfig.Proxy.Log.Target, "access log target")
 	f.StringVar(&cfg.Metrics.Target, "metrics.target", defaultConfig.Metrics.Target, "metrics backend")
 	f.StringVar(&cfg.Metrics.Prefix, "metrics.prefix", defaultConfig.Metrics.Prefix, "prefix for reported metrics")
 	f.StringVar(&cfg.Metrics.Names, "metrics.names", defaultConfig.Metrics.Names, "route metric name template")

config/load_test.go

@@ -316,6 +316,20 @@ func TestLoad(t *testing.T) {
 				return cfg
 			},
 		},
+		{
+			args: []string{"-proxy.log.format", "foobar"},
+			cfg: func(cfg *Config) *Config {
+				cfg.Proxy.Log.Format = "foobar"
+				return cfg
+			},
+		},
+		{
+			args: []string{"-proxy.log.target", "foobar"},
+			cfg: func(cfg *Config) *Config {
+				cfg.Proxy.Log.Target = "foobar"
+				return cfg
+			},
+		},
 		{
 			args: []string{"-registry.backend", "value"},
 			cfg: func(cfg *Config) *Config {

fabio.properties

@@ -384,6 +384,58 @@
 # proxy.log.routes = delta
 
 
+# proxy.log.target configures where the access log is written to.
+#
+# Options are 'stdout'. If the value is empty no access log is written.
+#
+# The default is
+#
+# proxy.log.target =
+
+
+# proxy.log.format configures the format of the access log.
+#
+# Options are 'common' or 'combined' for either the common
+# or combined access log file format. The are defined as follows:
+#
+# 'common':   $remote_host - - [$time_common] "$request" $response_status $response_body_size
+# 'combined': $remote_host - - [$time_common] "$request" $response_status $response_body_size "$header.Referer" "$header.User-Agent"
+#
+# Alternatively, a custom format can be specified with
+# the following parameters:
+#
+#   header.<name>      - request http header (name: [a-zA-Z0-9-]+)
+#   remote_addr        - host:port of remote client
+#   remote_host        - host of remote client
+#   remote_port        - port of remote client
+#   request            - request <method> <uri> <proto>
+#   request_args       - request query parameters
+#   request_host       - request host header (aka server name)
+#   request_method     - request method
+#   request_uri        - request URI
+#   request_proto      - request protocol
+#   response_body_size - response body size in bytes
+#   response_status    - response status code
+#   response_time_ms   - response time in S.sss format
+#   response_time_us   - response time in S.ssssss format
+#   response_time_ns   - response time in S.sssssssss format
+#   time_rfc3339       - log timestamp in YYYY-MM-DDTHH:MM:SSZ format
+#   time_rfc3339_ms    - log timestamp in YYYY-MM-DDTHH:MM:SS.sssZ format
+#   time_rfc3339_us    - log timestamp in YYYY-MM-DDTHH:MM:SS.ssssssZ format
+#   time_rfc3339_ns    - log timestamp in YYYY-MM-DDTHH:MM:SS.sssssssssZ format
+#   time_unix_ms       - log timestamp in unix epoch ms
+#   time_unix_ms       - log timestamp in unix epoch us
+#   time_unix_ns       - log timestamp in unix epoch ns
+#   time_common        - log timestamp in DD/MMM/YYYY:HH:MM:SS -ZZZZ
+#   upstream_addr      - host:port of upstream server
+#   upstream_host      - host of upstream server
+#   upstream_port      - port of upstream server
+#
+# The default is
+#
+# proxy.log.format = common
+
+
 # registry.backend configures which backend is used.
 # Supported backends are: consul, static, file
 #

logger/0-baseline.txt

@@ -0,0 +1,3 @@
+PASS
+BenchmarkLog-8	 1000000	      1807 ns/op	      80 B/op	       6 allocs/op
+ok  	github.com/eBay/fabio/logger	1.836s

logger/1-bytes-buffer.txt

@@ -0,0 +1,3 @@
+PASS
+BenchmarkLog-8	 1000000	      1453 ns/op	      48 B/op	       4 allocs/op
+ok  	github.com/eBay/fabio/logger	1.479s

logger/2-response-time.txt

@@ -0,0 +1,3 @@
+PASS
+BenchmarkLog-8	 1000000	      1068 ns/op	      37 B/op	       4 allocs/op
+ok  	github.com/eBay/fabio/logger	1.090s

logger/3-inline-time-format.txt

@@ -0,0 +1,3 @@
+PASS
+BenchmarkLog-8	 1000000	      1205 ns/op	      21 B/op	       9 allocs/op
+ok  	github.com/eBay/fabio/logger	1.229s

logger/3.1-inline-time-format.txt

@@ -0,0 +1,3 @@
+PASS
+BenchmarkLog-8	 1000000	      1269 ns/op	      21 B/op	       9 allocs/op
+ok  	github.com/eBay/fabio/logger	1.293s

logger/3.2-inline-time-format.txt

@@ -0,0 +1,3 @@
+PASS
+BenchmarkLog-8	 1000000	      1227 ns/op	      21 B/op	       9 allocs/op
+ok  	github.com/eBay/fabio/logger	1.250s

logger/3.3-inline-time-format.txt

@@ -0,0 +1,3 @@
+PASS
+BenchmarkLog-8	 1000000	      1009 ns/op	       8 B/op	       3 allocs/op
+ok  	github.com/eBay/fabio/logger	1.030s

logger/3.4-inline-time-format.txt

@@ -0,0 +1,3 @@
+PASS
+BenchmarkLog-8	 2000000	      1052 ns/op	       2 B/op	       2 allocs/op
+ok  	github.com/eBay/fabio/logger	3.059s

logger/3.5-inline-time-format.txt

@@ -0,0 +1,3 @@
+PASS
+BenchmarkLog-8	 2000000	       919 ns/op	       0 B/op	       0 allocs/op
+ok  	github.com/eBay/fabio/logger	2.740s

logger/logger.go

@@ -0,0 +1,130 @@
+// Package logger implements a configurable access logger.
+//
+// The access log format is defined through a format string which
+// expands to a log line per request.
+//
+//   header.<name>      - request http header (name: [a-zA-Z0-9-]+)
+//   remote_addr        - host:port of remote client
+//   remote_host        - host of remote client
+//   remote_port        - port of remote client
+//   request            - request <method> <uri> <proto>
+//   request_args       - request query parameters
+//   request_host       - request host header (aka server name)
+//   request_method     - request method
+//   request_uri        - request URI
+//   request_proto      - request protocol
+//   response_body_size - response body size in bytes
+//   response_status    - response status code
+//   response_time_ms   - response time in S.sss format
+//   response_time_us   - response time in S.ssssss format
+//   response_time_ns   - response time in S.sssssssss format
+//   time_rfc3339       - log timestamp in YYYY-MM-DDTHH:MM:SSZ format
+//   time_rfc3339_ms    - log timestamp in YYYY-MM-DDTHH:MM:SS.sssZ format
+//   time_rfc3339_us    - log timestamp in YYYY-MM-DDTHH:MM:SS.ssssssZ format
+//   time_rfc3339_ns    - log timestamp in YYYY-MM-DDTHH:MM:SS.sssssssssZ format
+//   time_unix_ms       - log timestamp in unix epoch ms
+//   time_unix_ms       - log timestamp in unix epoch us
+//   time_unix_ns       - log timestamp in unix epoch ns
+//   time_common        - log timestamp in DD/MMM/YYYY:HH:MM:SS -ZZZZ
+//   upstream_addr      - host:port of upstream server
+//   upstream_host      - host of upstream server
+//   upstream_port      - port of upstream server
+//
+package logger
+
+import (
+	"bytes"
+	"errors"
+	"io"
+	"net/http"
+	"os"
+	"sync"
+	"time"
+)
+
+const (
+	Common   = `$remote_host - - [$time_common] "$request" $response_status $response_body_size`
+	Combined = `$remote_host - - [$time_common] "$request" $response_status $response_body_size "$header.Referer" "$header.User-Agent"`
+)
+
+type HTTPLogger interface {
+	Log(start, end time.Time, resp *http.Response, req *http.Request)
+}
+
+func New(w io.Writer, format string) (HTTPLogger, error) {
+	p, err := parse(format, fields)
+	if err != nil {
+		return nil, err
+	}
+	if len(p) == 0 {
+		return nil, errors.New("empty log format")
+	}
+	if w == nil {
+		w = os.Stdout
+	}
+	return &logger{p: p, w: w}, nil
+}
+
+type logger struct {
+	p pattern
+
+	mu sync.Mutex
+	w  io.Writer
+}
+
+// BufSize defines the default size of the log buffers.
+const BufSize = 1024
+
+// pool provides a reusable set of log buffers.
+var pool = sync.Pool{
+	New: func() interface{} {
+		return bytes.NewBuffer(make([]byte, 0, BufSize))
+	},
+}
+
+// Log writes a log line for the request that was executed
+// between t1 and t2.
+func (l *logger) Log(t1, t2 time.Time, w *http.Response, r *http.Request) {
+	b := pool.Get().(*bytes.Buffer)
+	b.Reset()
+	l.p.write(b, t1, t2, w, r)
+	l.mu.Lock()
+	l.w.Write(b.Bytes())
+	l.mu.Unlock()
+	pool.Put(b)
+}
+
+// atoi is a replacement for strconv.Atoi/strconv.FormatInt
+// which does not alloc.
+func atoi(b *bytes.Buffer, i int64, pad int) {
+	var flag bool
+	if i < 0 {
+		flag = true
+		i = -i
+	}
+
+	// format number
+	// 2^63-1 == 9223372036854775807
+	var d [128]byte
+	n, p := len(d), len(d)-1
+	for i >= 0 {
+		d[p] = byte('0') + byte(i%10)
+		i /= 10
+		p--
+		if i == 0 {
+			break
+		}
+	}
+
+	// padding
+	for n-p-1 < pad {
+		d[p] = byte('0')
+		p--
+	}
+
+	if flag {
+		d[p] = '-'
+		p--
+	}
+	b.Write(d[p+1:])
+}