From 3c9a24755fed693d2da0f752288bcd9a395fd2fc Mon Sep 17 00:00:00 2001 From: Frank Schroeder Date: Tue, 4 Apr 2017 15:40:41 +0200 Subject: [PATCH] Issue #80: Access logging More polishing Make sure all metrics log the same duration --- config/load_test.go | 14 +++++++------- fabio.properties | 5 +++-- logger/logger.go | 4 ++++ metrics/circonus.go | 4 ++++ metrics/noop.go | 4 +++- metrics/registry.go | 3 +++ proxy/http_proxy.go | 47 +++++++++++++++++++++++++++------------------ 7 files changed, 52 insertions(+), 29 deletions(-) diff --git a/config/load_test.go b/config/load_test.go index 1e08d5432..ae5b720dc 100644 --- a/config/load_test.go +++ b/config/load_test.go @@ -309,6 +309,13 @@ func TestLoad(t *testing.T) { return cfg }, }, + { + args: []string{"-proxy.log.routes", "foobar"}, + cfg: func(cfg *Config) *Config { + cfg.Log.RoutesFormat = "foobar" + return cfg + }, + }, { args: []string{"-registry.backend", "value"}, cfg: func(cfg *Config) *Config { @@ -467,13 +474,6 @@ func TestLoad(t *testing.T) { return cfg }, }, - { - args: []string{"-proxy.log.routes", "foobar"}, - cfg: func(cfg *Config) *Config { - cfg.Log.RoutesFormat = "foobar" - return cfg - }, - }, { args: []string{"-metrics.target", "some-target"}, cfg: func(cfg *Config) *Config { diff --git a/fabio.properties b/fabio.properties index 376bf1c17..e75a6a2be 100644 --- a/fabio.properties +++ b/fabio.properties @@ -380,8 +380,9 @@ # 'combined': $remote_host - - [$time_common] "$request" $response_status $response_body_size "$header.Referer" "$header.User-Agent" # # Otherwise, the value is interpreted as a custom log format which is defined -# with these parameters. Providing an empty format when logging is enabled is -# an error. To disable logging leave the log.access.target value empty. +# with the following parameters. Providing an empty format when logging is +# enabled is an error. To disable access logging leave the log.access.target +# value empty. # # $header. - request http header (name: [a-zA-Z0-9-]+) # $remote_addr - host:port of remote client diff --git a/logger/logger.go b/logger/logger.go index d25538824..a42205654 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -65,12 +65,15 @@ type Event struct { End time.Time // Request is the HTTP request that is connected to this event. + // It should only be set for HTTP log events. Request *http.Request // Response is the HTTP response which is connected to this event. + // It should only be set for HTTP log events. Response *http.Response // RequestURL is the URL of the incoming HTTP request. + // It should only be set for HTTP log events. RequestURL *url.URL // UpstreamAddr is the TCP address in the form of "host:port" of the @@ -78,6 +81,7 @@ type Event struct { UpstreamAddr string // UpstreamURL is the URL which was sent to the upstream server. + // It should only be set for HTTP log events. UpstreamURL *url.URL } diff --git a/metrics/circonus.go b/metrics/circonus.go index 5c2ffeaff..d15dd2441 100644 --- a/metrics/circonus.go +++ b/metrics/circonus.go @@ -116,6 +116,10 @@ func (t *cgmTimer) Percentile(nth float64) float64 { return 0 } // Rate1 is not supported by Circonus. func (t *cgmTimer) Rate1() float64 { return 0 } +func (t *cgmTimer) Update(d time.Duration) { + t.metrics.Timing(t.name, float64(d)) +} + // UpdateSince adds delta between start and current time as // a sample to a histogram. The histogram is created if it // does not already exist. diff --git a/metrics/noop.go b/metrics/noop.go index 414bd9318..738517f9f 100644 --- a/metrics/noop.go +++ b/metrics/noop.go @@ -27,7 +27,9 @@ var noopTimer = NoopTimer{} // NoopTimer is a stub implementation of the Timer interface. type NoopTimer struct{} -func (t NoopTimer) UpdateSince(start time.Time) {} +func (t NoopTimer) Update(time.Duration) {} + +func (t NoopTimer) UpdateSince(time.Time) {} func (t NoopTimer) Rate1() float64 { return 0 } diff --git a/metrics/registry.go b/metrics/registry.go index 4f2cb917d..e60924a30 100644 --- a/metrics/registry.go +++ b/metrics/registry.go @@ -45,6 +45,9 @@ type Timer interface { // Rate1 returns the 1min rate. Rate1() float64 + // Update counts an event and records the duration. + Update(time.Duration) + // UpdateSince counts an event and records the duration // as the delta between 'start' and the function is called. UpdateSince(start time.Time) diff --git a/proxy/http_proxy.go b/proxy/http_proxy.go index a6796905d..410e0442d 100644 --- a/proxy/http_proxy.go +++ b/proxy/http_proxy.go @@ -20,7 +20,7 @@ type HTTPProxy struct { Config config.Proxy // Time returns the current time as the number of seconds since the epoch. - // If Time is nil, HTTPProxy uses time.Now. + // If Time is nil, time.Now is used. Time func() time.Time // Transport is the http connection pool configured with timeouts. @@ -114,29 +114,38 @@ func (p *HTTPProxy) ServeHTTP(w http.ResponseWriter, r *http.Request) { start := timeNow() h.ServeHTTP(w, r) + end := timeNow() + dur := end.Sub(start) + if p.Requests != nil { - p.Requests.UpdateSince(start) + p.Requests.Update(dur) } if t.Timer != nil { - t.Timer.UpdateSince(start) + t.Timer.Update(dur) } - if hr, ok := h.(responseKeeper); ok { - if resp := hr.response(); resp != nil { - name := key(resp.StatusCode) - metrics.DefaultRegistry.GetTimer(name).UpdateSince(start) - if p.Logger != nil { - p.Logger.Log(&logger.Event{ - Start: start, - End: timeNow(), - Request: r, - Response: resp, - RequestURL: requestURL, - UpstreamAddr: targetURL.Host, - UpstreamURL: targetURL, - }) - } - } + // get response and update metrics + hr, ok := h.(responseKeeper) + if !ok { + return + } + resp := hr.response() + if resp == nil { + return + } + metrics.DefaultRegistry.GetTimer(key(resp.StatusCode)).Update(dur) + + // write access log + if p.Logger != nil { + p.Logger.Log(&logger.Event{ + Start: start, + End: end, + Request: r, + Response: resp, + RequestURL: requestURL, + UpstreamAddr: targetURL.Host, + UpstreamURL: targetURL, + }) } }