From: Tom Clegg <tclegg@veritasgenetics.com>
Date: Wed, 25 Apr 2018 04:14:16 +0000 (-0400)
Subject: 12167: Log keep-web requests and responses as JSON.
X-Git-Tag: 1.2.0~171^2~8
X-Git-Url: https://git.arvados.org/arvados.git/commitdiff_plain/08b96e3ff47ef0f3b147442c14d6f5e404c93540

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 569931a3ed..1a4b7c5592 100644
--- 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 4ffac26797..63e2f37a80 100644
--- 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 4894ceb70b..03bd8f171e 100644
--- 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 724af27c7e..d09fce706c 100644
--- 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 aed2989219..2995bd30ab 100644
--- 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()
 }