Log per request

service/r2/metrics.go

@@ -69,9 +69,9 @@ func (sm *serviceMetrics) recordMetric(path, method, namespace string, d time.Du
 	sm.Lock()
 	defer sm.Unlock()
 	scope := sm.scope.Tagged(map[string]string{
-		"namespace":   namespace,
-		"http-method": method,
-		"route-path":  path,
+		namespaceTag: namespace,
+		methodTag:    method,
+		pathTag:      path,
 	})
 	m = newServiceMetric(scope, status)
 	sm.metrics[id] = m

service/r2/routes_test.go

@@ -162,6 +162,7 @@ func newTestService() *service {
 		nowFn:       clock.NewOptions().NowFn(),
 		store:       newMockStore(),
 		authService: auth.NewNoopAuth(),
+		iOpts:       iOpts,
 	}
 }
 

service/r2/service.go

@@ -36,6 +36,7 @@ import (
 	"github.com/m3db/m3metrics/rules"
 	"github.com/m3db/m3x/clock"
 	"github.com/m3db/m3x/instrument"
+	"github.com/m3db/m3x/log"
 
 	"github.com/gorilla/mux"
 	"gopkg.in/go-playground/validator.v9"
@@ -49,6 +50,10 @@ const (
 	namespaceIDVar = "namespaceID"
 	ruleIDVar      = "ruleID"
 
+	namespaceTag = "namespace"
+	methodTag    = "http-method"
+	pathTag      = "route-path"
+
 	nanosPerMilli = int64(time.Millisecond / time.Nanosecond)
 )
 
@@ -230,13 +235,27 @@ func (s *service) handleRoute(rf routeFunc, r *http.Request, namespace string) (
 	}
 	start := s.nowFn()
 	data, err := rf(s, r)
-	s.metrics.recordMetric(r.RequestURI, r.Method, namespace, time.Since(start), err)
+	t := time.Since(start)
+	s.metrics.recordMetric(r.RequestURI, r.Method, namespace, t, err)
+	s.logRequest(r.RequestURI, r.Method, namespace, t, err)
 	if err != nil {
 		return nil, err
 	}
 	return data, nil
 }
 
+func (s *service) logRequest(path, method, namespace string, d time.Duration, err error) {
+	logger := s.iOpts.Logger().WithFields(
+		log.NewField(namespaceTag, namespace),
+		log.NewField(methodTag, method),
+		log.NewField(pathTag, path),
+	)
+	if err != nil {
+		logger = logger.WithFields(log.NewErrField(err))
+	}
+	logger.Infof("spent %v for the request", d)
+}
+
 func (s *service) sendResponse(w http.ResponseWriter, statusCode int, data interface{}) error {
 	if j, err := json.Marshal(data); err == nil {
 		return sendResponse(w, j, statusCode)