caddyhttp: Better duration logging

Also un-nest all the error handling, that was unnecessary indentation

modules/caddyhttp/server.go

@@ -153,9 +153,9 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	// to capture the original request in case it gets
 	// modified during handling
 	loggableReq := zap.Object("request", LoggableHTTPRequest{r})
-	errLog := s.errorLogger.With(
+	errLog := s.errorLogger.With(loggableReq)
-		loggableReq,
+
-	)
+	var duration time.Duration
 
 	if s.shouldLogRequest(r) {
 		wrec := NewResponseRecorder(w, nil, nil)
@@ -164,13 +164,10 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		// capture the original version of the request
 		accLog := s.accessLogger.With(loggableReq)
 
-		start := time.Now()
 		defer func() {
-			latency := time.Since(start)
-
 			repl.Set("http.response.status", wrec.Status())
 			repl.Set("http.response.size", wrec.Size())
-			repl.Set("http.response.latency", latency)
+			repl.Set("http.response.duration", duration)
 
 			logger := accLog
 			if s.Logs != nil {
@@ -184,7 +181,7 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 
 			log("handled request",
 				zap.String("common_log", repl.ReplaceAll(commonLogFormat, commonLogEmptyValue)),
-				zap.Duration("latency", latency),
+				zap.Duration("duration", duration),
 				zap.Int("size", wrec.Size()),
 				zap.Int("status", wrec.Status()),
 				zap.Object("resp_headers", LoggableHTTPHeader(wrec.Header())),
@@ -192,20 +189,30 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		}()
 	}
 
+	start := time.Now()
+
 	// guarantee ACME HTTP challenges; handle them
 	// separately from any user-defined handlers
 	if s.tlsApp.HandleHTTPChallenge(w, r) {
+		duration = time.Since(start)
 		return
 	}
 
 	// execute the primary handler chain
 	err := s.primaryHandlerChain.ServeHTTP(w, r)
-	if err != nil {
+	duration = time.Since(start)
+
+	// if no errors, we're done!
+	if err == nil {
+		return
+	}
+
 	// prepare the error log
 	logger := errLog
 	if s.Logs != nil {
 		logger = s.Logs.wrapLogger(logger, r.Host)
 	}
+	logger = logger.With(zap.Duration("duration", duration))
 
 	// get the values that will be used to log the error
 	errStatus, errMsg, errFields := errLogValues(err)
@@ -238,7 +245,6 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		w.WriteHeader(errStatus)
 	}
 }
-}
 
 // wrapPrimaryRoute wraps stack (a compiled middleware handler chain)
 // in s.enforcementHandler which performs crucial security checks, etc.