Issue #80: Add access logging support

Original PR #131 by [email protected]

This patch adds support for configurable access logging
which is compatible with nginx config parameters.

config/config.go

@@ -59,13 +59,19 @@ type Proxy struct {
 	ClientIPHeader        string
 	TLSHeader             string
 	TLSHeaderValue        string
+	Log                   Log
 }
 
 type Runtime struct {
 	GOGC       int
 	GOMAXPROCS int
 }
 
+type Log struct {
+	Target string
+	Format string
+}
+
 type Metrics struct {
 	Target       string
 	Prefix       string

config/load.go

@@ -105,6 +105,8 @@ func load(p *properties.Properties) (cfg *Config, err error) {
 	f.DurationVar(&cfg.Proxy.ReadTimeout, "proxy.readtimeout", Default.Proxy.ReadTimeout, "read timeout for incoming requests")
 	f.DurationVar(&cfg.Proxy.WriteTimeout, "proxy.writetimeout", Default.Proxy.WriteTimeout, "write timeout for outgoing responses")
 	f.DurationVar(&cfg.Proxy.FlushInterval, "proxy.flushinterval", Default.Proxy.FlushInterval, "flush interval for streaming responses")
+	f.StringVar(&cfg.Proxy.Log.Format, "proxy.log.format", Default.Proxy.Log.Format, "directive to change the format of logged")
+	f.StringVar(&cfg.Proxy.Log.Target, "proxy.log.target", Default.Proxy.Log.Target, "logged backend")
 	f.StringVar(&cfg.Metrics.Target, "metrics.target", Default.Metrics.Target, "metrics backend")
 	f.StringVar(&cfg.Metrics.Prefix, "metrics.prefix", Default.Metrics.Prefix, "prefix for reported metrics")
 	f.DurationVar(&cfg.Metrics.Interval, "metrics.interval", Default.Metrics.Interval, "metrics reporting interval")

fabio.properties

@@ -312,6 +312,18 @@
 # proxy.header.tls.value =
 
 
+# proxy log configures which access logger is used.
+#
+# Example:
+#     proxy.log.target = stdout 
+#     proxy.log.format = remote_addr time request body_bytes_sent http_referer http_user_agent server_name proxy_endpoint response_time request_args http_x_forwarded_for
+#
+# The default is
+#
+# proxy.log.target =
+# proxy.log.format =
+
+
 # registry.backend configures which backend is used.
 # Supported backends are: consul, static, file
 #

logger/logger.go

@@ -0,0 +1,115 @@
+package logger
+
+import (
+	"bytes"
+	"fmt"
+	"io"
+	"net/http"
+	"strings"
+	"sync"
+	"time"
+)
+
+const BufferSize = 1024
+
+type Pattern func(w io.Writer, t time.Time, r *http.Request)
+
+var (
+	pool = sync.Pool{
+		New: func() interface{} {
+			return bytes.NewBuffer(make([]byte, 0, BufferSize))
+		},
+	}
+	patterns = map[string]Pattern{
+		"remote_addr": func(w io.Writer, t time.Time, r *http.Request) {
+			io.WriteString(w, r.RemoteAddr[:strings.Index(r.RemoteAddr, ":")])
+		},
+		"time": func(w io.Writer, t time.Time, r *http.Request) {
+			io.WriteString(w, t.Format(time.RFC3339))
+		},
+		"request": func(w io.Writer, t time.Time, r *http.Request) {
+			io.WriteString(w, "\""+r.Method+" "+r.URL.Path+" "+r.Proto+"\"")
+		},
+		"body_bytes_sent": func(w io.Writer, t time.Time, r *http.Request) {
+			io.WriteString(w, fmt.Sprintf("%d", uint64(r.ContentLength)))
+		},
+		"http_referer": func(w io.Writer, t time.Time, r *http.Request) {
+			io.WriteString(w, r.Referer())
+		},
+		"http_user_agent": func(w io.Writer, t time.Time, r *http.Request) {
+			io.WriteString(w, r.UserAgent())
+		},
+		"http_x_forwarded_for": func(w io.Writer, t time.Time, r *http.Request) {
+			io.WriteString(w, r.Header.Get("X-Forwarded-For"))
+		},
+		"server_name": func(w io.Writer, t time.Time, r *http.Request) {
+			io.WriteString(w, r.Host)
+		},
+		"proxy_endpoint": func(w io.Writer, t time.Time, r *http.Request) {
+			io.WriteString(w, r.URL.Host)
+		},
+		"response_time": func(w io.Writer, t time.Time, r *http.Request) {
+			io.WriteString(w, fmt.Sprintf("%.4f", time.Since(t).Seconds()))
+		},
+		"request_args": func(w io.Writer, t time.Time, r *http.Request) {
+			io.WriteString(w, r.URL.RawQuery)
+		},
+	}
+)
+
+type Logger struct {
+	p []Pattern
+
+	// w is the log destination
+	w io.Writer
+
+	// mu guards w
+	mu sync.Mutex
+}
+
+func New(w io.Writer, format string) (*Logger, error) {
+	p, err := parse(format)
+
+	if err != nil {
+		return nil, err
+	}
+
+	//format can't empty
+	if p == nil || len(p) == 0 {
+		return nil, fmt.Errorf("Invalid Logger format %s", format)
+	}
+
+	return &Logger{w: w, p: p}, nil
+}
+
+func parse(format string) ([]Pattern, error) {
+	var pp []Pattern
+
+	for _, f := range strings.Fields(format) {
+		p := patterns[f]
+		if p == nil {
+			return nil, fmt.Errorf("Invalid log field \"%s\"", f)
+		}
+		pp = append(pp, p)
+
+	}
+
+	return pp, nil
+}
+
+func (l *Logger) Log(t time.Time, r *http.Request) {
+	b := pool.Get().(*bytes.Buffer)
+	b.Reset()
+
+	for _, p := range l.p {
+		p(b, t, r)
+		b.WriteRune(' ')
+	}
+	b.Truncate(b.Len() - 1) //drop last space
+	b.WriteRune('\n')
+
+	l.mu.Lock()
+	l.w.Write(b.Bytes())
+	l.mu.Unlock()
+	pool.Put(b)
+}

logger/logger_test.go

@@ -0,0 +1,48 @@
+package logger
+
+import (
+	"bytes"
+	"net/http"
+	"net/url"
+	"testing"
+	"time"
+)
+
+func TestLog(t *testing.T) {
+	ts := time.Date(2016, 1, 1, 0, 0, 0, 0, time.UTC)
+
+	tests := []struct {
+		req    *http.Request
+		format string
+		out    string
+	}{
+		{
+			&http.Request{
+				RequestURI: "/",
+				Header:     http.Header{"X-Forwarded-For": {"3.3.3.3"}},
+				RemoteAddr: "2.2.2.2:666",
+				URL:        &url.URL{},
+				Method:     "GET",
+				Proto:      "HTTP/1.1",
+			},
+			"remote_addr time request body_bytes_sent http_x_forwarded_for",
+			"2.2.2.2 2016-01-01T00:00:00Z \"GET  HTTP/1.1\" 0 3.3.3.3\n",
+		},
+	}
+
+	for i, tt := range tests {
+		b := new(bytes.Buffer)
+		l, err := New(b, tt.format)
+
+		if err != nil {
+			t.Fatalf("%d: got %v want nil", i, err)
+		}
+
+		l.Log(ts, tt.req)
+
+		if got, want := string(b.Bytes()), tt.out; got != want {
+			t.Errorf("%d: got %q want %q", i, got, want)
+		}
+	}
+
+}

proxy/logger.go

@@ -0,0 +1,26 @@
+package proxy
+
+import (
+	"fmt"
+	"github.com/eBay/fabio/logger"
+	"io"
+	"log"
+	"os"
+)
+
+func newLogger(target string, format string) (*logger.Logger, error) {
+	var w io.Writer
+
+	switch target {
+	case "stdout":
+		log.Printf("[INFO] Output logger to stdout")
+		w = os.Stdout
+	case "":
+		log.Printf("[INFO] Logger disabled")
+		return nil, nil
+	default:
+		return nil, fmt.Errorf("Invalid Logger target %s", target)
+	}
+
+	return logger.New(w, format)
+}

proxy/proxy.go

@@ -1,10 +1,12 @@
 package proxy
 
 import (
+	"log"
 	"net/http"
 	"time"
 
 	"github.com/eBay/fabio/config"
+	"github.com/eBay/fabio/logger"
 
 	gometrics "github.com/rcrowley/go-metrics"
 )
@@ -14,13 +16,22 @@ type Proxy struct {
 	tr       http.RoundTripper
 	cfg      config.Proxy
 	requests gometrics.Timer
+	logger   *logger.Logger
 }
 
 func New(tr http.RoundTripper, cfg config.Proxy) *Proxy {
+
+	logger, err := newLogger(cfg.Log.Target, cfg.Log.Format)
+
+	if err != nil {
+		log.Fatal("[FATAL] ", err)
+	}
+
 	return &Proxy{
 		tr:       tr,
 		cfg:      cfg,
 		requests: gometrics.GetOrRegisterTimer("requests", gometrics.DefaultRegistry),
+		logger:   logger,
 	}
 }
 
@@ -62,4 +73,7 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	h.ServeHTTP(w, r)
 	p.requests.UpdateSince(start)
 	t.Timer.UpdateSince(start)
+	if p.logger != nil {
+		p.logger.Log(start, r)
+	}
 }

proxy/proxy_integration_test.go

@@ -55,3 +55,35 @@ func TestProxyNoRouteStaus(t *testing.T) {
 		t.Fatalf("got %d want %d", got, want)
 	}
 }
+
+func BenchmarkProxyLogger(b *testing.B) {
+	got := "not called"
+	server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		got = r.Header.Get("X-Forwarded-For")
+	}))
+	defer server.Close()
+
+	table := make(route.Table)
+	table.AddRoute("mock", "/", server.URL, 1, nil)
+	route.SetTable(table)
+
+	tr := &http.Transport{Dial: (&net.Dialer{}).Dial}
+	proxy := New(tr, config.Proxy{LocalIP: "1.1.1.1", ClientIPHeader: "X-Forwarded-For", Log: config.Log{
+		Format: "remote_addr time request body_bytes_sent http_referer http_user_agent server_name proxy_endpoint response_time request_args ",
+		Target: "stdout",
+	}})
+
+	req := &http.Request{
+		RequestURI: "/",
+		Header:     http.Header{"X-Forwarded-For": {"1.2.3.4"}},
+		RemoteAddr: "2.2.2.2:666",
+		URL:        &url.URL{},
+		Method:     "GET",
+		Proto:      "HTTP/1.1",
+	}
+
+	for i := 0; i < b.N; i++ {
+		proxy.ServeHTTP(httptest.NewRecorder(), req)
+	}
+
+}