[ARVADOS] updated: 927db6616baa78420a7ffccc59ef784fe57f6668

[Git user]

Summary of changes:
 services/keepstore/config.go         |  1 +
 services/keepstore/logging_router.go | 57 ++++++++++++++++++++++++++----------
 2 files changed, 43 insertions(+), 15 deletions(-)

       via  927db6616baa78420a7ffccc59ef784fe57f6668 (commit)
       via  3080d79eb30bdb6194b3c91efbbaa4cc406eac38 (commit)
      from  3947ec4aa92c71e2402de0b34a60183ae0c52445 (commit)

Those revisions listed above that are new to this repository have
not appeared on any other notification email; so we list those
revisions in full, below.


commit 927db6616baa78420a7ffccc59ef784fe57f6668
Author: Tom Clegg <tom at curoverse.com>
Date:   Sun Nov 20 01:44:35 2016 -0500

    10473: Tune up text-format logging.

diff --git a/services/keepstore/config.go b/services/keepstore/config.go
index 8824db9..83dd84e 100644
--- a/services/keepstore/config.go
+++ b/services/keepstore/config.go
@@ -70,6 +70,7 @@ func (cfg *Config) Start() error {
 	switch strings.ToLower(cfg.LogFormat) {
 	case "text":
 		log.SetFormatter(&log.TextFormatter{
+			FullTimestamp:   true,
 			TimestampFormat: rfc3339NanoFixed,
 		})
 	case "json":
diff --git a/services/keepstore/logging_router.go b/services/keepstore/logging_router.go
index 9dfb48a..bfd006e 100644
--- a/services/keepstore/logging_router.go
+++ b/services/keepstore/logging_router.go
@@ -111,5 +111,11 @@ type loggedDuration time.Duration
 // MarshalJSON formats a duration as a number of seconds, using
 // fixed-point notation with no more than 6 decimal places.
 func (d loggedDuration) MarshalJSON() ([]byte, error) {
-	return []byte(fmt.Sprintf("%.6f", time.Duration(d).Seconds())), nil
+	return []byte(d.String()), nil
+}
+
+// String formats a duration as a number of seconds, using
+// fixed-point notation with no more than 6 decimal places.
+func (d loggedDuration) String() string {
+	return fmt.Sprintf("%.6f", time.Duration(d).Seconds())
 }

commit 3080d79eb30bdb6194b3c91efbbaa4cc406eac38
Author: Tom Clegg <tom at curoverse.com>
Date:   Sun Nov 20 01:39:05 2016 -0500

    10473: Use fixed-point timestamps and more human-readable field ordering, hide "incoming request" if level<debug.

diff --git a/services/keepstore/logging_router.go b/services/keepstore/logging_router.go
index 30b10b3..9dfb48a 100644
--- a/services/keepstore/logging_router.go
+++ b/services/keepstore/logging_router.go
@@ -4,6 +4,8 @@ package main
 // LoggingResponseWriter
 
 import (
+	"context"
+	"fmt"
 	"net/http"
 	"strings"
 	"time"
@@ -65,30 +67,49 @@ type LoggingRESTRouter struct {
 
 func (loggingRouter *LoggingRESTRouter) ServeHTTP(wrappedResp http.ResponseWriter, req *http.Request) {
 	tStart := time.Now()
-	lgr := log.WithFields(log.Fields{
-		"RequestID":       loggingRouter.idGenerator.Next(),
-		"RemoteAddr":      req.RemoteAddr,
-		"X-Forwarded-For": req.Header.Get("X-Forwarded-For"),
-		"ReqMethod":       req.Method,
-		"ReqPath":         req.URL.Path[1:],
-		"ReqBytes":        req.ContentLength,
+
+	// Attach a requestID-aware logger to the request context.
+	lgr := log.WithField("RequestID", loggingRouter.idGenerator.Next())
+	ctx := context.WithValue(req.Context(), "logger", lgr)
+	req = req.WithContext(ctx)
+
+	lgr = lgr.WithFields(log.Fields{
+		"remoteAddr":      req.RemoteAddr,
+		"reqForwardedFor": req.Header.Get("X-Forwarded-For"),
+		"reqMethod":       req.Method,
+		"reqPath":         req.URL.Path[1:],
+		"reqBytes":        req.ContentLength,
 	})
-	lgr.Info("request")
+	lgr.Debug("request")
 
 	resp := LoggingResponseWriter{http.StatusOK, 0, wrappedResp, "", zeroTime}
 	loggingRouter.router.ServeHTTP(&resp, req)
+	tDone := time.Now()
+
 	statusText := http.StatusText(resp.Status)
 	if resp.Status >= 400 {
 		statusText = strings.Replace(resp.ResponseBody, "\n", "", -1)
 	}
+	if resp.sentHdr == zeroTime {
+		// Nobody changed status or wrote any data, i.e., we
+		// returned a 200 response with no body.
+		resp.sentHdr = tDone
+	}
 
-	tDone := time.Now()
 	lgr.WithFields(log.Fields{
-		"TimeTotal":      tDone.Sub(tStart).Seconds(),
-		"TimeToStatus":   resp.sentHdr.Sub(tStart).Seconds(),
-		"TimeWriteBody":  tDone.Sub(resp.sentHdr).Seconds(),
-		"RespStatusCode": resp.Status,
-		"RespStatus":     statusText,
-		"RespBytes":      resp.Length,
+		"timeTotal":      loggedDuration(tDone.Sub(tStart)),
+		"timeToStatus":   loggedDuration(resp.sentHdr.Sub(tStart)),
+		"timeWriteBody":  loggedDuration(tDone.Sub(resp.sentHdr)),
+		"respStatusCode": resp.Status,
+		"respStatus":     statusText,
+		"respBytes":      resp.Length,
 	}).Info("response")
 }
+
+type loggedDuration time.Duration
+
+// MarshalJSON formats a duration as a number of seconds, using
+// fixed-point notation with no more than 6 decimal places.
+func (d loggedDuration) MarshalJSON() ([]byte, error) {
+	return []byte(fmt.Sprintf("%.6f", time.Duration(d).Seconds())), nil
+}

-----------------------------------------------------------------------


hooks/post-receive
--