10473: Log requests/responses in JSON format by default; add config option for text...

diff --git a/sdk/go/httpserver/id_generator.go b/sdk/go/httpserver/id_generator.go
new file mode 100644 (file)
index 0000000..c2830f7
--- /dev/null
+++ b/sdk/go/httpserver/id_generator.go
@@ -0,0 +1,31 @@
+package httpserver
+
+import (
+       "strconv"
+       "sync"
+       "time"
+)
+
+// IDGenerator generates alphanumeric strings suitable for use as
+// unique IDs (a given IDGenerator will never return the same ID
+// twice).
+type IDGenerator struct {
+       // Prefix is prepended to each returned ID.
+       Prefix string
+
+       lastID int64
+       mtx    sync.Mutex
+}
+
+// Next returns a new ID string. It is safe to call Next from multiple
+// goroutines.
+func (g *IDGenerator) Next() string {
+       id := time.Now().UnixNano()
+       g.mtx.Lock()
+       if id <= g.lastID {
+               id = g.lastID + 1
+       }
+       g.lastID = id
+       g.mtx.Unlock()
+       return g.Prefix + strconv.FormatInt(id, 36)
+}

diff --git a/services/keepstore/azure_blob_volume.go b/services/keepstore/azure_blob_volume.go
index 6ca31c38329ec7347631a03c802b4216bd05f167..43cf83a07ead3db94b2620be74375c738d4e5d08 100644 (file)
--- a/services/keepstore/azure_blob_volume.go
+++ b/services/keepstore/azure_blob_volume.go
@@ -8,7 +8,6 @@ import (
        "fmt"
        "io"
        "io/ioutil"
-       "log"
        "net/http"
        "os"
        "regexp"
@@ -18,6 +17,7 @@ import (
        "time"
 
        "git.curoverse.com/arvados.git/sdk/go/arvados"
+       log "github.com/Sirupsen/logrus"
        "github.com/curoverse/azure-sdk-for-go/storage"
 )
 

diff --git a/services/keepstore/azure_blob_volume_test.go b/services/keepstore/azure_blob_volume_test.go
index d636a5ee86887806372a14e2f291e5c4f2c11b33..c5dbc8f5831402aa3e223391c3ad0ece918de0a3 100644 (file)
--- a/services/keepstore/azure_blob_volume_test.go
+++ b/services/keepstore/azure_blob_volume_test.go
@@ -9,7 +9,6 @@ import (
        "flag"
        "fmt"
        "io/ioutil"
-       "log"
        "math/rand"
        "net"
        "net/http"
@@ -22,6 +21,7 @@ import (
        "testing"
        "time"
 
+       log "github.com/Sirupsen/logrus"
        "github.com/curoverse/azure-sdk-for-go/storage"
 )
 

diff --git a/services/keepstore/bufferpool.go b/services/keepstore/bufferpool.go
index 9a3509424a3b10a1b8361c06be8475ddaa31f832..38f97aff1183d0da0fdaa05b3022765277c9a954 100644 (file)
--- a/services/keepstore/bufferpool.go
+++ b/services/keepstore/bufferpool.go
@@ -1,10 +1,11 @@
 package main
 
 import (
-       "log"
        "sync"
        "sync/atomic"
        "time"
+
+       log "github.com/Sirupsen/logrus"
 )
 
 type bufferPool struct {

diff --git a/services/keepstore/config.go b/services/keepstore/config.go
index dc06ef549877ba0316294e4a0e7767393ef4436d..b2041c30325cbfaef35bc7dbcbf25a4b2c646a4b 100644 (file)
--- a/services/keepstore/config.go
+++ b/services/keepstore/config.go
@@ -5,17 +5,19 @@ import (
        "encoding/json"
        "fmt"
        "io/ioutil"
-       "log"
        "strings"
        "time"
 
        "git.curoverse.com/arvados.git/sdk/go/arvados"
+       log "github.com/Sirupsen/logrus"
 )
 
 type Config struct {
        Debug  bool
        Listen string
 
+       LogFormat string
+
        PIDFile string
 
        MaxBuffers  int
@@ -42,6 +44,7 @@ var theConfig = DefaultConfig()
 func DefaultConfig() *Config {
        return &Config{
                Listen:             ":25107",
+               LogFormat:          "json",
                MaxBuffers:         128,
                RequireSignatures:  true,
                BlobSignatureTTL:   arvados.Duration(14 * 24 * time.Hour),
@@ -55,12 +58,26 @@ func DefaultConfig() *Config {
 // fields, and before using the config.
 func (cfg *Config) Start() error {
        if cfg.Debug {
+               log.SetLevel(log.DebugLevel)
                cfg.debugLogf = log.Printf
                cfg.debugLogf("debugging enabled")
        } else {
                cfg.debugLogf = func(string, ...interface{}) {}
        }
 
+       switch strings.ToLower(cfg.LogFormat) {
+       case "text":
+               log.SetFormatter(&log.TextFormatter{
+                       TimestampFormat: time.RFC3339Nano,
+               })
+       case "json":
+               log.SetFormatter(&log.JSONFormatter{
+                       TimestampFormat: time.RFC3339Nano,
+               })
+       default:
+               return fmt.Errorf(`unsupported log format %q (try "text" or "json")`, cfg.LogFormat)
+       }
+
        if cfg.MaxBuffers < 0 {
                return fmt.Errorf("MaxBuffers must be greater than zero")
        }

diff --git a/services/keepstore/config_test.go b/services/keepstore/config_test.go
index eaa09042484388dd8185b2d8c79679034c6951f7..a6d46e5e4a1166967f5d3be9c22581d3c1401ef9 100644 (file)
--- a/services/keepstore/config_test.go
+++ b/services/keepstore/config_test.go
@@ -1,7 +1,7 @@
 package main
 
 import (
-       "log"
+       log "github.com/Sirupsen/logrus"
 )
 
 func init() {

diff --git a/services/keepstore/handler_test.go b/services/keepstore/handler_test.go
index 9708b4e6be32f96645d500dfcd4319972f213d47..40b4839e06cc96fc05cd8eb5a2be4e73707ac03d 100644 (file)
--- a/services/keepstore/handler_test.go
+++ b/services/keepstore/handler_test.go
@@ -958,7 +958,7 @@ func TestGetHandlerClientDisconnect(t *testing.T) {
        ok := make(chan struct{})
        go func() {
                req, _ := http.NewRequest("GET", fmt.Sprintf("/%s+%d", TestHash, len(TestBlock)), nil)
-               (&LoggingRESTRouter{MakeRESTRouter()}).ServeHTTP(resp, req)
+               (&LoggingRESTRouter{router: MakeRESTRouter()}).ServeHTTP(resp, req)
                ok <- struct{}{}
        }()
 

diff --git a/services/keepstore/handlers.go b/services/keepstore/handlers.go
index b51009ea4d78348fe53bab01c13070d950e6aa42..ed0d8d7a5bff1721a144db27bcd29273f70c77d3 100644 (file)
--- a/services/keepstore/handlers.go
+++ b/services/keepstore/handlers.go
@@ -15,7 +15,6 @@ import (
        "fmt"
        "github.com/gorilla/mux"
        "io"
-       "log"
        "net/http"
        "os"
        "regexp"
@@ -24,6 +23,8 @@ import (
        "strings"
        "sync"
        "time"
+
+       log "github.com/Sirupsen/logrus"
 )
 
 // MakeRESTRouter returns a new mux.Router that forwards all Keep

diff --git a/services/keepstore/keepstore.go b/services/keepstore/keepstore.go
index 4eaaea8ea3695ac0f9bd69f71bef4fa2fd5b9278..d82c7d0f7a78792b4ccd46558e5ccb159ae463e4 100644 (file)
--- a/services/keepstore/keepstore.go
+++ b/services/keepstore/keepstore.go
@@ -3,7 +3,6 @@ package main
 import (
        "flag"
        "fmt"
-       "log"
        "net"
        "net/http"
        "os"
@@ -15,6 +14,7 @@ import (
        "git.curoverse.com/arvados.git/sdk/go/config"
        "git.curoverse.com/arvados.git/sdk/go/httpserver"
        "git.curoverse.com/arvados.git/sdk/go/keepclient"
+       log "github.com/Sirupsen/logrus"
        "github.com/coreos/go-systemd/daemon"
        "github.com/ghodss/yaml"
 )
@@ -151,8 +151,7 @@ func main() {
 
        // Middleware stack: logger, MaxRequests limiter, method handlers
        http.Handle("/", &LoggingRESTRouter{
-               httpserver.NewRequestLimiter(theConfig.MaxRequests,
-                       MakeRESTRouter()),
+               router: httpserver.NewRequestLimiter(theConfig.MaxRequests, MakeRESTRouter()),
        })
 
        // Set up a TCP listener.

diff --git a/services/keepstore/logging_router.go b/services/keepstore/logging_router.go
index 0f556b538ac7ae15b1939f61bad13be3ed0404e5..30b10b3bca52265b9742c4f9d585de686c4c8670 100644 (file)
--- a/services/keepstore/logging_router.go
+++ b/services/keepstore/logging_router.go
@@ -4,10 +4,12 @@ package main
 // LoggingResponseWriter
 
 import (
-       "log"
        "net/http"
        "strings"
        "time"
+
+       "git.curoverse.com/arvados.git/sdk/go/httpserver"
+       log "github.com/Sirupsen/logrus"
 )
 
 // LoggingResponseWriter has anonymous fields ResponseWriter and ResponseBody
@@ -57,21 +59,36 @@ func (resp *LoggingResponseWriter) Write(data []byte) (int, error) {
 
 // LoggingRESTRouter is used to add logging capabilities to mux.Router
 type LoggingRESTRouter struct {
-       router http.Handler
+       router      http.Handler
+       idGenerator httpserver.IDGenerator
 }
 
 func (loggingRouter *LoggingRESTRouter) ServeHTTP(wrappedResp http.ResponseWriter, req *http.Request) {
-       t0 := time.Now()
+       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,
+       })
+       lgr.Info("request")
+
        resp := LoggingResponseWriter{http.StatusOK, 0, wrappedResp, "", zeroTime}
        loggingRouter.router.ServeHTTP(&resp, req)
        statusText := http.StatusText(resp.Status)
        if resp.Status >= 400 {
                statusText = strings.Replace(resp.ResponseBody, "\n", "", -1)
        }
-       now := time.Now()
-       tTotal := now.Sub(t0)
-       tLatency := resp.sentHdr.Sub(t0)
-       tResponse := now.Sub(resp.sentHdr)
-       log.Printf("[%s] %s %s %d %.6fs %.6fs %.6fs %d %d \"%s\"", req.RemoteAddr, req.Method, req.URL.Path[1:], req.ContentLength, tTotal.Seconds(), tLatency.Seconds(), tResponse.Seconds(), resp.Status, resp.Length, statusText)
 
+       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,
+       }).Info("response")
 }

diff --git a/services/keepstore/pull_worker.go b/services/keepstore/pull_worker.go
index 12860bb662d91a1e31191fed2bccace97bc2ac30..3c6278d478d3d897982b2b6f8c9a166c505e6433 100644 (file)
--- a/services/keepstore/pull_worker.go
+++ b/services/keepstore/pull_worker.go
@@ -7,8 +7,9 @@ import (
        "git.curoverse.com/arvados.git/sdk/go/keepclient"
        "io"
        "io/ioutil"
-       "log"
        "time"
+
+       log "github.com/Sirupsen/logrus"
 )
 
 // RunPullWorker is used by Keepstore to initiate pull worker channel goroutine.

diff --git a/services/keepstore/s3_volume.go b/services/keepstore/s3_volume.go
index 27ac0d9c74992f57fb9091c96dca8dfa59fb6ffc..ca5b1a2eb945cb2ae940c9599c955fb59d9e489a 100644 (file)
--- a/services/keepstore/s3_volume.go
+++ b/services/keepstore/s3_volume.go
@@ -9,7 +9,6 @@ import (
        "fmt"
        "io"
        "io/ioutil"
-       "log"
        "net/http"
        "os"
        "regexp"
@@ -21,6 +20,7 @@ import (
        "git.curoverse.com/arvados.git/sdk/go/arvados"
        "github.com/AdRoll/goamz/aws"
        "github.com/AdRoll/goamz/s3"
+       log "github.com/Sirupsen/logrus"
 )
 
 const (

diff --git a/services/keepstore/s3_volume_test.go b/services/keepstore/s3_volume_test.go
index 10e915852ca75e31cfbbe629198de52821e5ab3a..6389d503dfc5ccee32471d308bf81ee64b012135 100644 (file)
--- a/services/keepstore/s3_volume_test.go
+++ b/services/keepstore/s3_volume_test.go
@@ -7,13 +7,13 @@ import (
        "encoding/json"
        "fmt"
        "io/ioutil"
-       "log"
        "os"
        "time"
 
        "git.curoverse.com/arvados.git/sdk/go/arvados"
        "github.com/AdRoll/goamz/s3"
        "github.com/AdRoll/goamz/s3/s3test"
+       log "github.com/Sirupsen/logrus"
        check "gopkg.in/check.v1"
 )
 

diff --git a/services/keepstore/trash_worker.go b/services/keepstore/trash_worker.go
index 27d6216d01633feca360de94f0a8febaabfb475a..696c3e53a60abbd352efc035f5a0bb1afaec737f 100644 (file)
--- a/services/keepstore/trash_worker.go
+++ b/services/keepstore/trash_worker.go
@@ -2,10 +2,10 @@ package main
 
 import (
        "errors"
-       "log"
        "time"
 
        "git.curoverse.com/arvados.git/sdk/go/arvados"
+       log "github.com/Sirupsen/logrus"
 )
 
 // RunTrashWorker is used by Keepstore to initiate trash worker channel goroutine.

diff --git a/services/keepstore/usage.go b/services/keepstore/usage.go
index 29f89f567d7b64729d10ecde3a4699186f233711..887cfd3a9edf80f5ef9a620efa880b9bc93856d8 100644 (file)
--- a/services/keepstore/usage.go
+++ b/services/keepstore/usage.go
@@ -48,6 +48,10 @@ Listen:
     "address" is a host IP address or name and "port" is a port number
     or name.
 
+LogFormat:
+
+    Format of request/response and error logs: "json" or "text".
+
 PIDFile:
 
    Path to write PID file during startup. This file is kept open and

diff --git a/services/keepstore/volume_unix.go b/services/keepstore/volume_unix.go
index f9812b07cd8630ae75f2a8e32feddd7b2d099a43..fff02aac260f59a6fc46fc24cbebea57b27e5743 100644 (file)
--- a/services/keepstore/volume_unix.go
+++ b/services/keepstore/volume_unix.go
@@ -7,7 +7,6 @@ import (
        "fmt"
        "io"
        "io/ioutil"
-       "log"
        "os"
        "path/filepath"
        "regexp"
@@ -16,6 +15,8 @@ import (
        "sync"
        "syscall"
        "time"
+
+       log "github.com/Sirupsen/logrus"
 )
 
 type unixVolumeAdder struct {