diff --git a/config/config.go b/config/config.go index 5929a1ddf..8603cf0ec 100644 --- a/config/config.go +++ b/config/config.go @@ -59,6 +59,7 @@ type Proxy struct { ClientIPHeader string TLSHeader string TLSHeaderValue string + Log Log } type Runtime struct { @@ -66,6 +67,11 @@ type Runtime struct { GOMAXPROCS int } +type Log struct { + Target string + Format string +} + type Metrics struct { Target string Prefix string diff --git a/config/load.go b/config/load.go index 857ab5731..fbe919cac 100644 --- a/config/load.go +++ b/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") diff --git a/fabio.properties b/fabio.properties index f6c2ddf12..9098698d2 100644 --- a/fabio.properties +++ b/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 # diff --git a/logger/logger.go b/logger/logger.go new file mode 100644 index 000000000..ddbded5ad --- /dev/null +++ b/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) +} diff --git a/logger/logger_test.go b/logger/logger_test.go new file mode 100644 index 000000000..338dc41ed --- /dev/null +++ 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) + } + } + +} diff --git a/proxy/logger.go b/proxy/logger.go new file mode 100644 index 000000000..4d9e2ac97 --- /dev/null +++ b/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) +} diff --git a/proxy/proxy.go b/proxy/proxy.go index 201a173dd..abfd56e25 100644 --- a/proxy/proxy.go +++ b/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) + } } diff --git a/proxy/proxy_integration_test.go b/proxy/proxy_integration_test.go index 34c2185a0..6630bfa3d 100644 --- a/proxy/proxy_integration_test.go +++ b/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) + } + +}