diff --git a/.gitignore b/.gitignore index ec8cc2b36..ce1bc6a39 100644 --- a/.gitignore +++ b/.gitignore @@ -1,5 +1,6 @@ *-amd64 *.out +*.orig *.p12 *.pem *.pprof diff --git a/config/config.go b/config/config.go index d866096a9..49617a310 100644 --- a/config/config.go +++ b/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 diff --git a/config/default.go b/config/default.go index c404822c9..ecadcba89 100644 --- a/config/default.go +++ b/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", diff --git a/config/load.go b/config/load.go index e553a6cd8..5da6d5516 100644 --- a/config/load.go +++ b/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") diff --git a/config/load_test.go b/config/load_test.go index f9d2bf898..eef03db49 100644 --- a/config/load_test.go +++ b/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 { diff --git a/fabio.properties b/fabio.properties index 65ae4d2ed..421a65e74 100644 --- a/fabio.properties +++ b/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. - 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 +# 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 # diff --git a/logger/0-baseline.txt b/logger/0-baseline.txt new file mode 100644 index 000000000..4b446d91c --- /dev/null +++ b/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 diff --git a/logger/1-bytes-buffer.txt b/logger/1-bytes-buffer.txt new file mode 100644 index 000000000..58faa5080 --- /dev/null +++ b/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 diff --git a/logger/2-response-time.txt b/logger/2-response-time.txt new file mode 100644 index 000000000..3cd59aa9c --- /dev/null +++ b/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 diff --git a/logger/3-inline-time-format.txt b/logger/3-inline-time-format.txt new file mode 100644 index 000000000..9b97ab32a --- /dev/null +++ b/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 diff --git a/logger/3.1-inline-time-format.txt b/logger/3.1-inline-time-format.txt new file mode 100644 index 000000000..1a348444b --- /dev/null +++ b/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 diff --git a/logger/3.2-inline-time-format.txt b/logger/3.2-inline-time-format.txt new file mode 100644 index 000000000..195edd171 --- /dev/null +++ b/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 diff --git a/logger/3.3-inline-time-format.txt b/logger/3.3-inline-time-format.txt new file mode 100644 index 000000000..ed6723b8c --- /dev/null +++ b/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 diff --git a/logger/3.4-inline-time-format.txt b/logger/3.4-inline-time-format.txt new file mode 100644 index 000000000..e604210e5 --- /dev/null +++ b/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 diff --git a/logger/3.5-inline-time-format.txt b/logger/3.5-inline-time-format.txt new file mode 100644 index 000000000..d5aca1236 --- /dev/null +++ b/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 diff --git a/logger/logger.go b/logger/logger.go new file mode 100644 index 000000000..0106e5a81 --- /dev/null +++ b/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. - 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 +// 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:]) +} diff --git a/logger/logger_test.go b/logger/logger_test.go new file mode 100644 index 000000000..0f19add48 --- /dev/null +++ b/logger/logger_test.go @@ -0,0 +1,212 @@ +package logger + +import ( + "bytes" + "io/ioutil" + "net/http" + "net/url" + "sort" + "strings" + "testing" + "time" +) + +func TestParse(t *testing.T) { + fields := map[string]field{ + "$a": func(b *bytes.Buffer, _, _ time.Time, _ *http.Response, _ *http.Request) { + b.WriteString("aa") + }, + "$b": func(b *bytes.Buffer, _, _ time.Time, _ *http.Response, _ *http.Request) { + b.WriteString("bb") + }, + } + req := &http.Request{ + Header: http.Header{ + "User-Agent": {"Mozilla Firefox"}, + "X-Forwarded-For": {"3.3.3.3"}, + }, + } + tests := []struct { + format string + out string + }{ + {"", ""}, + {"$a", "aa\n"}, + {"$a $b", "aa bb\n"}, + {"$a \"$header.User-Agent\"", "aa \"Mozilla Firefox\"\n"}, + } + + for i, tt := range tests { + p, err := parse(tt.format, fields) + if err != nil { + t.Errorf("%d: got %v want nil", i, err) + continue + } + var b bytes.Buffer + p.write(&b, time.Time{}, time.Time{}, nil, req) + if got, want := string(b.Bytes()), tt.out; got != want { + t.Errorf("%d: got %q want %q", i, got, want) + } + } +} + +func TestLog(t *testing.T) { + t1 := time.Date(2016, 1, 1, 0, 0, 0, 0, time.UTC) + t2 := t1.Add(123456789 * time.Nanosecond) + + req := &http.Request{ + RequestURI: "/?q=x", + Header: http.Header{ + "User-Agent": {"Mozilla Firefox"}, + "Referer": {"http://foo.com/"}, + "X-Forwarded-For": {"3.3.3.3"}, + }, + RemoteAddr: "2.2.2.2:666", + Host: "foo.com", + URL: &url.URL{ + Path: "/", + RawQuery: "?q=x", + Host: "proxy host", + }, + Method: "GET", + Proto: "HTTP/1.1", + } + + resp := &http.Response{ + StatusCode: 200, + ContentLength: 1234, + Header: http.Header{"foo": []string{"bar"}}, + Request: &http.Request{ + RemoteAddr: "5.6.7.8:1234", + }, + } + + tests := []struct { + format string + out string + }{ + {"$header.Referer", "http://foo.com/\n"}, + {"$header.user-agent", "Mozilla Firefox\n"}, + {"$header.X-Forwarded-For", "3.3.3.3\n"}, + {"$request", "GET /?q=x HTTP/1.1\n"}, + {"$request_args", "?q=x\n"}, + {"$request_host", "foo.com\n"}, // TODO(fs): is this correct? + {"$request_method", "GET\n"}, + {"$request_uri", "/?q=x\n"}, + {"$request_proto", "HTTP/1.1\n"}, + {"$remote_addr", "2.2.2.2:666\n"}, + {"$remote_host", "2.2.2.2\n"}, + {"$remote_port", "666\n"}, + {"$response_body_size", "1234\n"}, + {"$response_status", "200\n"}, + {"$response_time_ms", "0.123\n"}, // TODO(fs): is this correct? + {"$response_time_us", "0.123456\n"}, // TODO(fs): is this correct? + {"$response_time_ns", "0.123456789\n"}, // TODO(fs): is this correct? + {"$time_rfc3339", "2016-01-01T00:00:00Z\n"}, + {"$time_rfc3339_ms", "2016-01-01T00:00:00.123Z\n"}, + {"$time_rfc3339_us", "2016-01-01T00:00:00.123456Z\n"}, + {"$time_rfc3339_ns", "2016-01-01T00:00:00.123456789Z\n"}, + {"$time_unix_ms", "1451606400123\n"}, + {"$time_unix_us", "1451606400123456\n"}, + {"$time_unix_ns", "1451606400123456789\n"}, + {"$time_common", "01/Jan/2016:00:00:00 +0000\n"}, + {"$upstream_addr", "5.6.7.8:1234\n"}, // TODO(fs): is this correct? + {"$upstream_host", "5.6.7.8\n"}, // TODO(fs): is this correct? + {"$upstream_port", "1234\n"}, // TODO(fs): is this correct? + } + + for _, tt := range tests { + t.Run(tt.format, func(t *testing.T) { + b := new(bytes.Buffer) + + l, err := New(b, tt.format) + if err != nil { + t.Fatalf("got %v want nil", err) + } + + l.Log(t1, t2, resp, req) + if got, want := string(b.Bytes()), tt.out; got != want { + t.Errorf("got %q want %q", got, want) + } + }) + } +} + +func TestAtoi(t *testing.T) { + tests := []struct { + i int64 + pad int + s string + }{ + {i: 0, pad: 0, s: "0"}, + {i: 1, pad: 0, s: "1"}, + {i: -1, pad: 0, s: "-1"}, + {i: 12345, pad: 0, s: "12345"}, + {i: -12345, pad: 0, s: "-12345"}, + {i: 9223372036854775807, pad: 0, s: "9223372036854775807"}, + {i: -9223372036854775807, pad: 0, s: "-9223372036854775807"}, + + {i: 0, pad: 5, s: "00000"}, + {i: 1, pad: 5, s: "00001"}, + {i: -1, pad: 5, s: "-00001"}, + {i: 12345, pad: 5, s: "12345"}, + {i: -12345, pad: 5, s: "-12345"}, + {i: 9223372036854775807, pad: 5, s: "9223372036854775807"}, + {i: -9223372036854775807, pad: 5, s: "-9223372036854775807"}, + } + + for i, tt := range tests { + var b bytes.Buffer + atoi(&b, tt.i, tt.pad) + if got, want := string(b.Bytes()), tt.s; got != want { + t.Errorf("%d: got %q want %q", i, got, want) + } + } +} + +func BenchmarkLog(b *testing.B) { + t1 := time.Date(2016, 1, 1, 0, 0, 0, 0, time.UTC) + t2 := t1.Add(100 * time.Millisecond) + req := &http.Request{ + RequestURI: "/?q=x", + Header: http.Header{ + "User-Agent": {"Mozilla Firefox"}, + "Referer": {"http://foo.com/"}, + "X-Forwarded-For": {"3.3.3.3"}, + }, + RemoteAddr: "2.2.2.2:666", + Host: "foo.com", + URL: &url.URL{ + Path: "/", + RawQuery: "?q=x", + Host: "proxy host", + }, + Method: "GET", + Proto: "HTTP/1.1", + } + + resp := &http.Response{ + StatusCode: 200, + ContentLength: 1234, + Header: http.Header{"foo": []string{"bar"}}, + Request: &http.Request{ + RemoteAddr: "5.6.7.8:1234", + }, + } + + var keys []string + for k := range fields { + keys = append(keys, k) + } + sort.Strings(keys) + format := strings.Join(keys, " ") + + l, err := New(ioutil.Discard, format) + if err != nil { + b.Fatal(err) + } + + for i := 0; i < b.N; i++ { + l.Log(t1, t2, resp, req) + } +} diff --git a/logger/pattern.go b/logger/pattern.go new file mode 100644 index 000000000..236e8f4f9 --- /dev/null +++ b/logger/pattern.go @@ -0,0 +1,367 @@ +package logger + +import ( + "bytes" + "fmt" + "net" + "net/http" + "time" +) + +// field renders a part of the log line. +type field func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) + +// Pattern is a log output format. +type pattern []field + +func (p pattern) write(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + for _, fn := range p { + fn(b, t1, t2, w, r) + } + if b.Len() == 0 { + return + } + b.WriteRune('\n') +} + +// parse parses a format string into a pattern based on the following rules: +// +// The format string consists of text and fields. Field names start with a '$' +// and consist of ASCII characters [a-zA-Z0-9.-_]. Field names like +// '$header.name' will render the HTTP header 'name'. All other field names +// must exist in the fields map. +func parse(format string, fields map[string]field) (p pattern, err error) { + // text is a helper to add raw text to the log output. + text := func(s string) field { + return func(b *bytes.Buffer, _, _ time.Time, _ *http.Response, _ *http.Request) { + b.WriteString(s) + } + } + + // header is a helper to add an HTTP header to the log output. + header := func(name string) field { + return func(b *bytes.Buffer, _, _ time.Time, _ *http.Response, r *http.Request) { + b.WriteString(r.Header.Get(name)) + } + } + + s := []rune(format) + for { + if len(s) == 0 { + break + } + typ, n := lex(s) + val := string(s[:n]) + s = s[n:] + switch typ { + case itemText: + p = append(p, text(val)) + case itemHeader: + p = append(p, header(val[len("$header."):])) + case itemField: + f := fields[val] + if f == nil { + return nil, fmt.Errorf("invalid field %q", val) + } + p = append(p, f) + } + } + return p, nil +} + +// fields contains the known log fields and their field functions. The field +// functions should avoid to alloc memory at all cost since they are in the hot +// path. Do not use fmt.Sprintf() but combine the value from the parts. Instead +// of strconv.Atoi/FormatInt() use the local atoi() function which does not +// alloc. +var shortMonthNames = []string{ + "---", + "Jan", + "Feb", + "Mar", + "Apr", + "May", + "Jun", + "Jul", + "Aug", + "Sep", + "Oct", + "Nov", + "Dec", +} + +var fields = map[string]field{ + "$remote_addr": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + b.WriteString(r.RemoteAddr) + }, + "$remote_host": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + host, _, _ := net.SplitHostPort(r.RemoteAddr) + b.WriteString(host) + }, + "$remote_port": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + _, port, _ := net.SplitHostPort(r.RemoteAddr) + b.WriteString(port) + }, + "$request": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + b.WriteString(r.Method) + b.WriteRune(' ') + b.WriteString(r.RequestURI) + b.WriteRune(' ') + b.WriteString(r.Proto) + }, + "$request_args": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + b.WriteString(r.URL.RawQuery) + }, + "$request_host": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + b.WriteString(r.Host) + }, + "$request_method": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + b.WriteString(r.Method) + }, + "$request_uri": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + b.WriteString(r.RequestURI) + }, + "$request_proto": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + b.WriteString(r.Proto) + }, + "$response_body_size": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + atoi(b, w.ContentLength, 0) + }, + "$response_status": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + atoi(b, int64(w.StatusCode), 0) + }, + "$response_time_ms": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + d := t2.Sub(t1).Nanoseconds() + s, µs := d/int64(time.Second), d%int64(time.Second)/int64(time.Millisecond) + atoi(b, s, 0) + b.WriteRune('.') + atoi(b, µs, 3) + }, + "$response_time_us": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + d := t2.Sub(t1).Nanoseconds() + s, µs := d/int64(time.Second), d%int64(time.Second)/int64(time.Microsecond) + atoi(b, s, 0) + b.WriteRune('.') + atoi(b, µs, 6) + }, + "$response_time_ns": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + d := t2.Sub(t1).Nanoseconds() + s, ns := d/int64(time.Second), d%int64(time.Second)/int64(time.Nanosecond) + atoi(b, s, 0) + b.WriteRune('.') + atoi(b, ns, 9) + }, + "$time_unix_ms": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + atoi(b, t2.UnixNano()/int64(time.Millisecond), 0) + }, + "$time_unix_us": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + atoi(b, t2.UnixNano()/int64(time.Microsecond), 0) + }, + "$time_unix_ns": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + atoi(b, t2.UnixNano(), 0) + }, + "$time_common": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + atoi(b, int64(t2.Day()), 2) + b.WriteRune('/') + b.WriteString(shortMonthNames[t2.Month()]) + b.WriteRune('/') + atoi(b, int64(t2.Year()), 4) + b.WriteRune(':') + atoi(b, int64(t2.Hour()), 2) + b.WriteRune(':') + atoi(b, int64(t2.Minute()), 2) + b.WriteRune(':') + atoi(b, int64(t2.Second()), 2) + b.WriteString(" +0000") // TODO(fs): local time + }, + "$time_rfc3339": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + atoi(b, int64(t2.Year()), 4) + b.WriteRune('-') + atoi(b, int64(t2.Month()), 2) + b.WriteRune('-') + atoi(b, int64(t2.Day()), 2) + b.WriteRune('T') + atoi(b, int64(t2.Hour()), 2) + b.WriteRune(':') + atoi(b, int64(t2.Minute()), 2) + b.WriteRune(':') + atoi(b, int64(t2.Second()), 2) + b.WriteRune('Z') + }, + "$time_rfc3339_ms": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + atoi(b, int64(t2.Year()), 4) + b.WriteRune('-') + atoi(b, int64(t2.Month()), 2) + b.WriteRune('-') + atoi(b, int64(t2.Day()), 2) + b.WriteRune('T') + atoi(b, int64(t2.Hour()), 2) + b.WriteRune(':') + atoi(b, int64(t2.Minute()), 2) + b.WriteRune(':') + atoi(b, int64(t2.Second()), 2) + b.WriteRune('.') + atoi(b, int64(t2.Nanosecond())/int64(time.Millisecond), 3) + b.WriteRune('Z') + }, + "$time_rfc3339_us": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + atoi(b, int64(t2.Year()), 4) + b.WriteRune('-') + atoi(b, int64(t2.Month()), 2) + b.WriteRune('-') + atoi(b, int64(t2.Day()), 2) + b.WriteRune('T') + atoi(b, int64(t2.Hour()), 2) + b.WriteRune(':') + atoi(b, int64(t2.Minute()), 2) + b.WriteRune(':') + atoi(b, int64(t2.Second()), 2) + b.WriteRune('.') + atoi(b, int64(t2.Nanosecond())/int64(time.Microsecond), 6) + b.WriteRune('Z') + }, + "$time_rfc3339_ns": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + atoi(b, int64(t2.Year()), 4) + b.WriteRune('-') + atoi(b, int64(t2.Month()), 2) + b.WriteRune('-') + atoi(b, int64(t2.Day()), 2) + b.WriteRune('T') + atoi(b, int64(t2.Hour()), 2) + b.WriteRune(':') + atoi(b, int64(t2.Minute()), 2) + b.WriteRune(':') + atoi(b, int64(t2.Second()), 2) + b.WriteRune('.') + atoi(b, int64(t2.Nanosecond()), 9) + b.WriteRune('Z') + }, + "$upstream_addr": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + b.WriteString(w.Request.RemoteAddr) + }, + "$upstream_host": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + host, _, _ := net.SplitHostPort(w.Request.RemoteAddr) + b.WriteString(host) + }, + "$upstream_port": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + _, port, _ := net.SplitHostPort(w.Request.RemoteAddr) + b.WriteString(port) + }, + + //"$http_referer": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + // b.WriteString(r.Referer()) + //}, + //"$http_user_agent": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + // b.WriteString(r.UserAgent()) + //}, + //"$http_x_forwarded_for": func(b *bytes.Buffer, t1, t2 time.Time, w *http.Response, r *http.Request) { + // b.WriteString(r.Header.Get("X-Forwarded-For")) + //}, +} + +type itemType int + +const ( + itemText itemType = iota + itemField + itemHeader +) + +func (t itemType) String() string { + switch t { + case itemText: + return "TEXT" + case itemField: + return "FIELD" + case itemHeader: + return "HEADER" + } + panic("invalid") +} + +type state int + +const ( + stateStart state = iota + stateText + stateDollar + stateField + stateDot + stateHeader +) + +func lex(s []rune) (typ itemType, n int) { + isIDChar := func(r rune) bool { + return 'a' <= r && r <= 'z' || 'A' <= r && r <= 'Z' || '0' <= r && r <= '9' || r == '_' || r == '-' + } + + state := stateStart + for i, r := range s { + switch state { + case stateStart: + switch r { + case '$': + state = stateDollar + default: + state = stateText + } + + case stateText: + switch r { + case '$': + return itemText, i + default: + // state = stateText + } + + case stateDollar: + switch { + case isIDChar(r): + state = stateField + default: + state = stateText + } + + case stateField: + switch { + case r == '.': + if string(s[:i]) == "$header" { + state = stateDot + } else { + return itemField, i + } + case isIDChar(r): + // state = stateField + default: + return itemField, i + } + + case stateDot: + switch { + case isIDChar(r): + state = stateHeader + default: + return itemField, i + } + + case stateHeader: + switch { + case isIDChar(r): + // state = stateHeader + default: + return itemHeader, i + } + } + } + + switch state { + case stateDot: + return itemField, len(s) - 1 + case stateField: + return itemField, len(s) + case stateHeader: + return itemHeader, len(s) + default: + return itemText, len(s) + } +} diff --git a/main.go b/main.go index 44e742b51..63a23dab5 100644 --- a/main.go +++ b/main.go @@ -5,6 +5,7 @@ import ( "crypto/tls" "encoding/json" "fmt" + "io" "log" "net" "net/http" @@ -20,6 +21,7 @@ import ( "github.com/eBay/fabio/cert" "github.com/eBay/fabio/config" "github.com/eBay/fabio/exit" + "github.com/eBay/fabio/logger" "github.com/eBay/fabio/metrics" "github.com/eBay/fabio/proxy" "github.com/eBay/fabio/proxy/tcp" @@ -85,6 +87,30 @@ func main() { } func newHTTPProxy(cfg *config.Config) http.Handler { + var w io.Writer + switch cfg.Proxy.Log.Target { + case "": + log.Printf("[INFO] Access logging disabled") + case "stdout": + log.Printf("[INFO] Writing access log to stdout") + w = os.Stdout + default: + log.Fatal("[FATAL] Invalid access log target ", cfg.Proxy.Log.Target) + } + + format := cfg.Proxy.Log.Format + switch format { + case "common": + format = logger.Common + case "combined": + format = logger.Combined + } + + l, err := logger.New(w, format) + if err != nil { + log.Fatal("[FATAL] Invalid log format: ", err) + } + pick := route.Picker[cfg.Proxy.Strategy] match := route.Matcher[cfg.Proxy.Matcher] notFound := metrics.DefaultRegistry.GetCounter("notfound") @@ -110,6 +136,8 @@ func newHTTPProxy(cfg *config.Config) http.Handler { return t }, Requests: metrics.DefaultRegistry.GetTimer("requests"), + Noroute: metrics.DefaultRegistry.GetCounter("notfound"), + Logger: l, } } diff --git a/proxy/http_handler.go b/proxy/http_handler.go index 4a38f9313..d11d491c0 100644 --- a/proxy/http_handler.go +++ b/proxy/http_handler.go @@ -4,35 +4,47 @@ import ( "net/http" "net/http/httputil" "net/url" - "strconv" "time" - - "github.com/eBay/fabio/metrics" ) func newHTTPProxy(t *url.URL, tr http.RoundTripper, flush time.Duration) http.Handler { rp := httputil.NewSingleHostReverseProxy(t) rp.Transport = tr rp.FlushInterval = flush - rp.Transport = &meteredRoundTripper{tr} - return rp + rp.Transport = &transport{tr, nil} + return &httpHandler{rp} } -type meteredRoundTripper struct { - tr http.RoundTripper +// responser exposes the response from an HTTP request. +type responser interface { + response() *http.Response } -func (m *meteredRoundTripper) RoundTrip(r *http.Request) (*http.Response, error) { - start := time.Now() - resp, err := m.tr.RoundTrip(r) - if resp != nil { - metrics.DefaultRegistry.GetTimer(name(resp.StatusCode)).UpdateSince(start) - } - return resp, err +// httpHandler is a simple wrapper around a reverse proxy to access the +// captured response object in the underlying transport object. There +// may be a better way of doing this. +type httpHandler struct { + rp *httputil.ReverseProxy } -func name(code int) string { - b := []byte("http.status.") - b = strconv.AppendInt(b, int64(code), 10) - return string(b) +func (h *httpHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { + h.rp.ServeHTTP(w, r) +} + +func (h *httpHandler) response() *http.Response { + return h.rp.Transport.(*transport).resp +} + +// transport executes the roundtrip and captures the response. It is not +// safe for multiple or concurrent use since it only captures a single +// response. +type transport struct { + http.RoundTripper + resp *http.Response +} + +func (t *transport) RoundTrip(r *http.Request) (*http.Response, error) { + resp, err := t.RoundTripper.RoundTrip(r) + t.resp = resp + return resp, err } diff --git a/proxy/http_integration_test.go b/proxy/http_integration_test.go index 24bfb331d..c27d38ff5 100644 --- a/proxy/http_integration_test.go +++ b/proxy/http_integration_test.go @@ -6,10 +6,12 @@ import ( "net/http" "net/http/httptest" "net/url" + "os" "regexp" "testing" "github.com/eBay/fabio/config" + "github.com/eBay/fabio/logger" "github.com/eBay/fabio/route" ) @@ -207,3 +209,43 @@ func compress(b []byte) []byte { } return buf.Bytes() } + +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() + + format := "remote_addr time request body_bytes_sent http_referer http_user_agent server_name proxy_endpoint response_time request_args " + l, err := logger.New(os.Stdout, format) + if err != nil { + b.Fatal("logger.NewHTTPLogger:", err) + } + + proxy := &HTTPProxy{ + Config: config.Proxy{ + LocalIP: "1.1.1.1", + ClientIPHeader: "X-Forwarded-For", + }, + Transport: http.DefaultTransport, + Lookup: func(r *http.Request) *route.Target { + tbl, _ := route.NewTable("route add mock / " + server.URL) + return tbl.Lookup(r, "", route.Picker["rr"], route.Matcher["prefix"]) + }, + Logger: l, + } + + 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) + } +} diff --git a/proxy/http_proxy.go b/proxy/http_proxy.go index d521080f5..ed74df9ab 100644 --- a/proxy/http_proxy.go +++ b/proxy/http_proxy.go @@ -2,10 +2,12 @@ package proxy import ( "net/http" + "strconv" "strings" "time" "github.com/eBay/fabio/config" + "github.com/eBay/fabio/logger" "github.com/eBay/fabio/metrics" "github.com/eBay/fabio/proxy/gzip" "github.com/eBay/fabio/route" @@ -26,6 +28,13 @@ type HTTPProxy struct { // Requests is a timer metric which is updated for every request. Requests metrics.Timer + + // Noroute is a counter metric which is updated for every request + // where Lookup() returns nil. + Noroute metrics.Counter + + // Logger is the access logger for the requests. + Logger logger.HTTPLogger } func (p *HTTPProxy) ServeHTTP(w http.ResponseWriter, r *http.Request) { @@ -78,4 +87,19 @@ func (p *HTTPProxy) ServeHTTP(w http.ResponseWriter, r *http.Request) { p.Requests.UpdateSince(start) } t.Timer.UpdateSince(start) + + if hr, ok := h.(responser); ok { + resp := hr.response() + name := key(resp.StatusCode) + metrics.DefaultRegistry.GetTimer(name).UpdateSince(start) + if p.Logger != nil { + p.Logger.Log(start, time.Now(), resp, r) + } + } +} + +func key(code int) string { + b := []byte("http.status.") + b = strconv.AppendInt(b, int64(code), 10) + return string(b) }