12167: Log keep-web requests and responses as JSON.

Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tclegg@veritasgenetics.com>

diff --git a/sdk/go/httpserver/logger.go b/sdk/go/httpserver/logger.go
index 569931a3edd732b4fb3d48a09db318622bd08075..1a4b7c55925b20eb398cc9d9c402004a0d2f779c 100644 (file)
--- a/sdk/go/httpserver/logger.go
+++ b/sdk/go/httpserver/logger.go
@@ -32,7 +32,9 @@ func LogRequests(h http.Handler) http.Handler {
                        "remoteAddr":      req.RemoteAddr,
                        "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
                        "reqMethod":       req.Method,
+                       "reqHost":         req.Host,
                        "reqPath":         req.URL.Path[1:],
+                       "reqQuery":        req.URL.RawQuery,
                        "reqBytes":        req.ContentLength,
                })
                logRequest(w, req, lgr)

diff --git a/services/keep-web/handler.go b/services/keep-web/handler.go
index 4ffac26797514de7317099307f36e3be57b3da89..63e2f37a80b4e04a244ad1f32de9af03ba834287 100644 (file)
--- a/services/keep-web/handler.go
+++ b/services/keep-web/handler.go
@@ -10,7 +10,6 @@ import (
        "html"
        "html/template"
        "io"
-       "log"
        "net/http"
        "net/url"
        "os"
@@ -26,6 +25,7 @@ import (
        "git.curoverse.com/arvados.git/sdk/go/health"
        "git.curoverse.com/arvados.git/sdk/go/httpserver"
        "git.curoverse.com/arvados.git/sdk/go/keepclient"
+       log "github.com/Sirupsen/logrus"
        "golang.org/x/net/webdav"
 )
 
@@ -191,13 +191,12 @@ func (h *handler) ServeHTTP(wOrig http.ResponseWriter, r *http.Request) {
                } else if w.WroteStatus() == 0 {
                        w.WriteHeader(statusCode)
                } else if w.WroteStatus() != statusCode {
-                       httpserver.Log(r.RemoteAddr, "WARNING",
+                       log.WithField("RequestID", r.Header.Get("X-Request-Id")).Warn(
                                fmt.Sprintf("Our status changed from %d to %d after we sent headers", w.WroteStatus(), statusCode))
                }
                if statusText == "" {
                        statusText = http.StatusText(statusCode)
                }
-               httpserver.Log(remoteAddr, statusCode, statusText, w.WroteBodyBytes(), r.Method, r.Host, r.URL.Path, r.URL.RawQuery)
        }()
 
        if strings.HasPrefix(r.URL.Path, "/_health/") && r.Method == "GET" {

diff --git a/services/keep-web/handler_test.go b/services/keep-web/handler_test.go
index 4894ceb70b2087d21bf08cd3bae1e20fd78a43e0..03bd8f171e9748aead6c3537542c4d99f48fbc6b 100644 (file)
--- a/services/keep-web/handler_test.go
+++ b/services/keep-web/handler_test.go
@@ -632,7 +632,7 @@ func (s *IntegrationSuite) TestDirectoryListing(c *check.C) {
                        Host:       u.Host,
                        URL:        u,
                        RequestURI: u.RequestURI(),
-                       Header:     trial.header,
+                       Header:     copyHeader(trial.header),
                }
                s.testServer.Handler.ServeHTTP(resp, req)
                var cookies []*http.Cookie
@@ -643,7 +643,7 @@ func (s *IntegrationSuite) TestDirectoryListing(c *check.C) {
                                Host:       u.Host,
                                URL:        u,
                                RequestURI: u.RequestURI(),
-                               Header:     trial.header,
+                               Header:     copyHeader(trial.header),
                        }
                        cookies = append(cookies, (&http.Response{Header: resp.Header()}).Cookies()...)
                        for _, c := range cookies {
@@ -671,7 +671,7 @@ func (s *IntegrationSuite) TestDirectoryListing(c *check.C) {
                        Host:       u.Host,
                        URL:        u,
                        RequestURI: u.RequestURI(),
-                       Header:     trial.header,
+                       Header:     copyHeader(trial.header),
                        Body:       ioutil.NopCloser(&bytes.Buffer{}),
                }
                resp = httptest.NewRecorder()
@@ -687,7 +687,7 @@ func (s *IntegrationSuite) TestDirectoryListing(c *check.C) {
                        Host:       u.Host,
                        URL:        u,
                        RequestURI: u.RequestURI(),
-                       Header:     trial.header,
+                       Header:     copyHeader(trial.header),
                        Body:       ioutil.NopCloser(&bytes.Buffer{}),
                }
                resp = httptest.NewRecorder()
@@ -723,3 +723,11 @@ func (s *IntegrationSuite) TestHealthCheckPing(c *check.C) {
        c.Check(resp.Code, check.Equals, http.StatusOK)
        c.Check(resp.Body.String(), check.Matches, `{"health":"OK"}\n`)
 }
+
+func copyHeader(h http.Header) http.Header {
+       hc := http.Header{}
+       for k, v := range h {
+               hc[k] = append([]string(nil), v...)
+       }
+       return hc
+}

diff --git a/services/keep-web/main.go b/services/keep-web/main.go
index 724af27c7e0e746b44218f5269d23b71228e6655..d09fce706c4a50033649b32df152afa30ab85dc6 100644 (file)
--- a/services/keep-web/main.go
+++ b/services/keep-web/main.go
@@ -7,12 +7,12 @@ package main
 import (
        "flag"
        "fmt"
-       "log"
        "os"
        "time"
 
        "git.curoverse.com/arvados.git/sdk/go/arvados"
        "git.curoverse.com/arvados.git/sdk/go/config"
+       log "github.com/Sirupsen/logrus"
        "github.com/coreos/go-systemd/daemon"
 )
 
@@ -65,6 +65,10 @@ func init() {
        if os.Getenv("ARVADOS_API_TOKEN") == "" {
                os.Setenv("ARVADOS_API_TOKEN", "xxx")
        }
+
+       log.SetFormatter(&log.JSONFormatter{
+               TimestampFormat: "2006-01-02T15:04:05.000000000Z07:00",
+       })
 }
 
 func main() {

diff --git a/services/keep-web/server.go b/services/keep-web/server.go
index aed2989219cab297adcc0629c0162ae1f1610f36..2995bd30abe0008fb9623aa1758907aae111ae8c 100644 (file)
--- a/services/keep-web/server.go
+++ b/services/keep-web/server.go
@@ -14,7 +14,7 @@ type server struct {
 }
 
 func (srv *server) Start() error {
-       srv.Handler = httpserver.AddRequestIDs(&handler{Config: srv.Config})
+       srv.Handler = httpserver.AddRequestIDs(httpserver.LogRequests(&handler{Config: srv.Config}))
        srv.Addr = srv.Config.Listen
        return srv.Server.Start()
 }