Issue #80: Access logging

More polishing

Make sure all metrics log the same duration

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 {

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.<name>           - request http header (name: [a-zA-Z0-9-]+)
 #   $remote_addr             - host:port of remote client

logger/logger.go

@@ -65,19 +65,23 @@ 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
 	// upstream server which handled the proxied request.
 	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
 }
 

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.

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 }
 

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)

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,
+		})
 	}
 }