14287: Use ctxlog for httpserver logging.

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

diff --git a/lib/controller/federation_test.go b/lib/controller/federation_test.go
index d689bb00526d0dd701ec77316ff07727ca89e461..7e9b1fa3558fc18d0fd848f9894e8f527767357e 100644 (file)
--- a/lib/controller/federation_test.go
+++ b/lib/controller/federation_test.go
@@ -6,6 +6,7 @@ package controller
 
 import (
        "bytes"
+       "context"
        "encoding/json"
        "fmt"
        "io"
@@ -67,7 +68,9 @@ func (s *FederationSuite) SetUpTest(c *check.C) {
        arvadostest.SetServiceURL(&cluster.Services.Controller, "http://localhost:/")
        s.testHandler = &Handler{Cluster: cluster}
        s.testServer = newServerFromIntegrationTestEnv(c)
-       s.testServer.Server.Handler = httpserver.AddRequestIDs(httpserver.LogRequests(s.log, s.testHandler))
+       s.testServer.Server.Handler = httpserver.HandlerWithContext(
+               ctxlog.Context(context.Background(), s.log),
+               httpserver.AddRequestIDs(httpserver.LogRequests(s.testHandler)))
 
        cluster.RemoteClusters = map[string]arvados.RemoteCluster{
                "zzzzz": {

diff --git a/lib/controller/server_test.go b/lib/controller/server_test.go
index 803315bc66644d36e433b19000ee7da90b4a361e..edc5fd117de33f4b96dd3fa53f815ab382b13bf1 100644 (file)
--- a/lib/controller/server_test.go
+++ b/lib/controller/server_test.go
@@ -5,6 +5,7 @@
 package controller
 
 import (
+       "context"
        "net/http"
        "os"
        "path/filepath"
@@ -45,7 +46,9 @@ func newServerFromIntegrationTestEnv(c *check.C) *httpserver.Server {
 
        srv := &httpserver.Server{
                Server: http.Server{
-                       Handler: httpserver.AddRequestIDs(httpserver.LogRequests(log, handler)),
+                       Handler: httpserver.HandlerWithContext(
+                               ctxlog.Context(context.Background(), log),
+                               httpserver.AddRequestIDs(httpserver.LogRequests(handler))),
                },
                Addr: ":",
        }

diff --git a/lib/service/cmd.go b/lib/service/cmd.go
index 94021163e469fd87c6eb58dc29041ba00b95b65a..603f48890eccb6686a77ff8f80e99a8d020bfd52 100644 (file)
--- a/lib/service/cmd.go
+++ b/lib/service/cmd.go
@@ -116,7 +116,8 @@ func (c *command) RunCommand(prog string, args []string, stdin io.Reader, stdout
        }
        srv := &httpserver.Server{
                Server: http.Server{
-                       Handler: httpserver.AddRequestIDs(httpserver.LogRequests(log, handler)),
+                       Handler: httpserver.HandlerWithContext(ctx,
+                               httpserver.AddRequestIDs(httpserver.LogRequests(handler))),
                },
                Addr: listen,
        }

diff --git a/sdk/go/httpserver/logger.go b/sdk/go/httpserver/logger.go
index 357daee269f3784dd650107ef081d689cd3639de..f64708454c2b1e12cb5a75906d7d43676629cfb5 100644 (file)
--- a/sdk/go/httpserver/logger.go
+++ b/sdk/go/httpserver/logger.go
@@ -9,6 +9,7 @@ import (
        "net/http"
        "time"
 
+       "git.curoverse.com/arvados.git/sdk/go/ctxlog"
        "git.curoverse.com/arvados.git/sdk/go/stats"
        "github.com/sirupsen/logrus"
 )
@@ -19,18 +20,23 @@ type contextKey struct {
 
 var (
        requestTimeContextKey = contextKey{"requestTime"}
-       loggerContextKey      = contextKey{"logger"}
 )
 
+// HandlerWithContext returns an http.Handler that changes the request
+// context to ctx (replacing http.Server's default
+// context.Background()), then calls next.
+func HandlerWithContext(ctx context.Context, next http.Handler) http.Handler {
+       return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+               next.ServeHTTP(w, r.WithContext(ctx))
+       })
+}
+
 // LogRequests wraps an http.Handler, logging each request and
-// response via logger.
-func LogRequests(logger logrus.FieldLogger, h http.Handler) http.Handler {
-       if logger == nil {
-               logger = logrus.StandardLogger()
-       }
+// response.
+func LogRequests(h http.Handler) http.Handler {
        return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
                w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
-               lgr := logger.WithFields(logrus.Fields{
+               lgr := ctxlog.FromContext(req.Context()).WithFields(logrus.Fields{
                        "RequestID":       req.Header.Get("X-Request-Id"),
                        "remoteAddr":      req.RemoteAddr,
                        "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
@@ -42,7 +48,7 @@ func LogRequests(logger logrus.FieldLogger, h http.Handler) http.Handler {
                })
                ctx := req.Context()
                ctx = context.WithValue(ctx, &requestTimeContextKey, time.Now())
-               ctx = context.WithValue(ctx, &loggerContextKey, lgr)
+               ctx = ctxlog.Context(ctx, lgr)
                req = req.WithContext(ctx)
 
                logRequest(w, req, lgr)
@@ -52,11 +58,7 @@ func LogRequests(logger logrus.FieldLogger, h http.Handler) http.Handler {
 }
 
 func Logger(req *http.Request) logrus.FieldLogger {
-       if lgr, ok := req.Context().Value(&loggerContextKey).(logrus.FieldLogger); ok {
-               return lgr
-       } else {
-               return logrus.StandardLogger()
-       }
+       return ctxlog.FromContext(req.Context())
 }
 
 func logRequest(w *responseTimer, req *http.Request, lgr *logrus.Entry) {

diff --git a/sdk/go/httpserver/logger_test.go b/sdk/go/httpserver/logger_test.go
index 8386db9276935c9dbd565ea657357b15302111cb..3b2bc7758069b44345b3da522b8f80cc303c52fe 100644 (file)
--- a/sdk/go/httpserver/logger_test.go
+++ b/sdk/go/httpserver/logger_test.go
@@ -6,12 +6,14 @@ package httpserver
 
 import (
        "bytes"
+       "context"
        "encoding/json"
        "net/http"
        "net/http/httptest"
        "testing"
        "time"
 
+       "git.curoverse.com/arvados.git/sdk/go/ctxlog"
        "github.com/sirupsen/logrus"
        check "gopkg.in/check.v1"
 )
@@ -31,15 +33,19 @@ func (s *Suite) TestLogRequests(c *check.C) {
        log.Formatter = &logrus.JSONFormatter{
                TimestampFormat: time.RFC3339Nano,
        }
+       ctx := ctxlog.Context(context.Background(), log)
+
+       h := AddRequestIDs(LogRequests(
+               http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+                       w.Write([]byte("hello world"))
+               })))
 
-       h := http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
-               w.Write([]byte("hello world"))
-       })
        req, err := http.NewRequest("GET", "https://foo.example/bar", nil)
        req.Header.Set("X-Forwarded-For", "1.2.3.4:12345")
        c.Assert(err, check.IsNil)
        resp := httptest.NewRecorder()
-       AddRequestIDs(LogRequests(log, h)).ServeHTTP(resp, req)
+
+       HandlerWithContext(ctx, h).ServeHTTP(resp, req)
 
        dec := json.NewDecoder(captured)
 

diff --git a/sdk/go/httpserver/metrics.go b/sdk/go/httpserver/metrics.go
index 032093f8d8aab842a1a3af194089c1ee9b4980e4..fab6c3f11801a4a6ec52de6f1f86f17a438e246f 100644 (file)
--- a/sdk/go/httpserver/metrics.go
+++ b/sdk/go/httpserver/metrics.go
@@ -104,7 +104,7 @@ func (m *metrics) ServeAPI(token string, next http.Handler) http.Handler {
 //
 // For the metrics to be accurate, the caller must ensure every
 // request passed to the Handler also passes through
-// LogRequests(logger, ...), and vice versa.
+// LogRequests(...), and vice versa.
 //
 // If registry is nil, a new registry is created.
 //

diff --git a/services/keep-balance/server.go b/services/keep-balance/server.go
index 894056c9f27756c9f452f904568d53f88f433c74..e2f13a425ed8dfabc729649d98aa7e4ed977899a 100644 (file)
--- a/services/keep-balance/server.go
+++ b/services/keep-balance/server.go
@@ -5,6 +5,7 @@
 package main
 
 import (
+       "context"
        "fmt"
        "net/http"
        "os"
@@ -14,6 +15,7 @@ import (
 
        "git.curoverse.com/arvados.git/sdk/go/arvados"
        "git.curoverse.com/arvados.git/sdk/go/auth"
+       "git.curoverse.com/arvados.git/sdk/go/ctxlog"
        "git.curoverse.com/arvados.git/sdk/go/httpserver"
        "github.com/sirupsen/logrus"
 )
@@ -127,11 +129,13 @@ func (srv *Server) start() error {
        if srv.config.Listen == "" {
                return nil
        }
+       ctx := ctxlog.Context(context.Background(), srv.Logger)
        server := &httpserver.Server{
                Server: http.Server{
-                       Handler: httpserver.LogRequests(srv.Logger,
-                               auth.RequireLiteralToken(srv.config.ManagementToken,
-                                       srv.metrics.Handler(srv.Logger))),
+                       Handler: httpserver.HandlerWithContext(ctx,
+                               httpserver.LogRequests(
+                                       auth.RequireLiteralToken(srv.config.ManagementToken,
+                                               srv.metrics.Handler(srv.Logger)))),
                },
                Addr: srv.config.Listen,
        }

diff --git a/services/keep-web/server.go b/services/keep-web/server.go
index f70dd1a71f6ae92ecdc3f2979e2296f33238e28f..167fbbe5b85cf93f012d072e1fd97af3f5bd7106 100644 (file)
--- a/services/keep-web/server.go
+++ b/services/keep-web/server.go
@@ -5,10 +5,13 @@
 package main
 
 import (
+       "context"
        "net/http"
 
+       "git.curoverse.com/arvados.git/sdk/go/ctxlog"
        "git.curoverse.com/arvados.git/sdk/go/httpserver"
        "github.com/prometheus/client_golang/prometheus"
+       "github.com/sirupsen/logrus"
 )
 
 type server struct {
@@ -20,7 +23,8 @@ func (srv *server) Start() error {
        h := &handler{Config: srv.Config}
        reg := prometheus.NewRegistry()
        h.Config.Cache.registry = reg
-       mh := httpserver.Instrument(reg, nil, httpserver.AddRequestIDs(httpserver.LogRequests(nil, h)))
+       ctx := ctxlog.Context(context.Background(), logrus.StandardLogger())
+       mh := httpserver.Instrument(reg, nil, httpserver.HandlerWithContext(ctx, httpserver.AddRequestIDs(httpserver.LogRequests(h))))
        h.MetricsAPI = mh.ServeAPI(h.Config.ManagementToken, http.NotFoundHandler())
        srv.Handler = mh
        srv.Addr = srv.Config.Listen

diff --git a/services/keepproxy/keepproxy.go b/services/keepproxy/keepproxy.go
index c6fd99b9d8ed2f70b264b342ed041d5062eeb0a8..f8aa6c4aa7db3df87e7e598aaa901e8e3e91763c 100644 (file)
--- a/services/keepproxy/keepproxy.go
+++ b/services/keepproxy/keepproxy.go
@@ -182,7 +182,7 @@ func main() {
 
        // Start serving requests.
        router = MakeRESTRouter(!cfg.DisableGet, !cfg.DisablePut, kc, time.Duration(cfg.Timeout), cfg.ManagementToken)
-       http.Serve(listener, httpserver.AddRequestIDs(httpserver.LogRequests(nil, router)))
+       http.Serve(listener, httpserver.AddRequestIDs(httpserver.LogRequests(router)))
 
        log.Println("shutting down")
 }

diff --git a/services/keepstore/handlers.go b/services/keepstore/handlers.go
index 9a4d02df850fab836cdafaa4e21abb070b492782..72088e2b5ead5726e02bc06c6d8f84e6b5817fa5 100644 (file)
--- a/services/keepstore/handlers.go
+++ b/services/keepstore/handlers.go
@@ -21,6 +21,7 @@ import (
        "time"
 
        "git.curoverse.com/arvados.git/sdk/go/arvados"
+       "git.curoverse.com/arvados.git/sdk/go/ctxlog"
        "git.curoverse.com/arvados.git/sdk/go/health"
        "git.curoverse.com/arvados.git/sdk/go/httpserver"
        "github.com/gorilla/mux"
@@ -93,8 +94,10 @@ func MakeRESTRouter(cluster *arvados.Cluster, reg *prometheus.Registry) http.Han
        rtr.metrics.setupWorkQueueMetrics(trashq, "trash")
        rtr.metrics.setupRequestMetrics(rtr.limiter)
 
-       instrumented := httpserver.Instrument(rtr.metrics.reg, nil,
-               httpserver.AddRequestIDs(httpserver.LogRequests(nil, rtr.limiter)))
+       instrumented := httpserver.Instrument(rtr.metrics.reg, log,
+               httpserver.HandlerWithContext(
+                       ctxlog.Context(context.Background(), log),
+                       httpserver.AddRequestIDs(httpserver.LogRequests(rtr.limiter))))
        return instrumented.ServeAPI(theConfig.ManagementToken, instrumented)
 }