[ARVADOS] created: 1.1.1-56-g5c8b4fc
Git user
git at public.curoverse.com
Thu Nov 30 09:41:12 EST 2017
at 5c8b4fc39287a0075fc71c65684610fb4d623218 (commit)
commit 5c8b4fc39287a0075fc71c65684610fb4d623218
Merge: 0829e2d 20c3fbd
Author: Tom Clegg <tclegg at veritasgenetics.com>
Date: Thu Nov 30 09:38:29 2017 -0500
Merge branch '12167-keep-request-id'
refs #12167
Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tclegg at veritasgenetics.com>
commit 20c3fbd046f726590774c5d7a1897835080a34e3
Author: Tom Clegg <tclegg at veritasgenetics.com>
Date: Wed Nov 29 11:07:14 2017 -0500
12167: Test request ID size.
Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tclegg at veritasgenetics.com>
diff --git a/sdk/go/httpserver/logger_test.go b/sdk/go/httpserver/logger_test.go
index 5b54f32..bbcafa1 100644
--- a/sdk/go/httpserver/logger_test.go
+++ b/sdk/go/httpserver/logger_test.go
@@ -46,7 +46,7 @@ func (s *Suite) TestLogRequests(c *check.C) {
gotReq := make(map[string]interface{})
err = dec.Decode(&gotReq)
c.Logf("%#v", gotReq)
- c.Check(gotReq["RequestID"], check.Matches, "req-[a-z0-9]+")
+ c.Check(gotReq["RequestID"], check.Matches, "req-[a-z0-9]{20}")
c.Check(gotReq["reqForwardedFor"], check.Equals, "1.2.3.4:12345")
c.Check(gotReq["msg"], check.Equals, "request")
commit 5a32827d1f5ada007f83f5d5bb9b2d12526f2755
Author: Tom Clegg <tclegg at veritasgenetics.com>
Date: Wed Nov 29 10:56:44 2017 -0500
12167: Use pseudo-random IDs instead of timestamps.
Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tclegg at veritasgenetics.com>
diff --git a/sdk/go/httpserver/id_generator.go b/sdk/go/httpserver/id_generator.go
index c744691..d2c3a41 100644
--- a/sdk/go/httpserver/id_generator.go
+++ b/sdk/go/httpserver/id_generator.go
@@ -5,6 +5,7 @@
package httpserver
import (
+ "math/rand"
"net/http"
"strconv"
"sync"
@@ -18,21 +19,24 @@ type IDGenerator struct {
// Prefix is prepended to each returned ID.
Prefix string
- lastID int64
- mtx sync.Mutex
+ mtx sync.Mutex
+ src rand.Source
}
// 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
+ defer g.mtx.Unlock()
+ if g.src == nil {
+ g.src = rand.NewSource(time.Now().UnixNano())
}
- g.lastID = id
- g.mtx.Unlock()
- return g.Prefix + strconv.FormatInt(id, 36)
+ a, b := g.src.Int63(), g.src.Int63()
+ id := strconv.FormatInt(a, 36) + strconv.FormatInt(b, 36)
+ for len(id) > 20 {
+ id = id[:20]
+ }
+ return g.Prefix + id
}
// AddRequestIDs wraps an http.Handler, adding an X-Request-Id header
commit 062912dab12af62beab4d585584c0ccfc700af20
Author: Tom Clegg <tclegg at veritasgenetics.com>
Date: Wed Nov 29 10:37:05 2017 -0500
12167: Test LogRequests() and AddRequestIDs().
Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tclegg at veritasgenetics.com>
diff --git a/sdk/go/httpserver/logger_test.go b/sdk/go/httpserver/logger_test.go
new file mode 100644
index 0000000..5b54f32
--- /dev/null
+++ b/sdk/go/httpserver/logger_test.go
@@ -0,0 +1,68 @@
+// Copyright (C) The Arvados Authors. All rights reserved.
+//
+// SPDX-License-Identifier: AGPL-3.0
+
+package httpserver
+
+import (
+ "bytes"
+ "encoding/json"
+ "net/http"
+ "net/http/httptest"
+ "os"
+ "testing"
+ "time"
+
+ log "github.com/Sirupsen/logrus"
+ check "gopkg.in/check.v1"
+)
+
+func Test(t *testing.T) {
+ check.TestingT(t)
+}
+
+var _ = check.Suite(&Suite{})
+
+type Suite struct{}
+
+func (s *Suite) TestLogRequests(c *check.C) {
+ defer log.SetOutput(os.Stdout)
+ captured := &bytes.Buffer{}
+ log.SetOutput(captured)
+ log.SetFormatter(&log.JSONFormatter{
+ TimestampFormat: time.RFC3339Nano,
+ })
+ 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(h)).ServeHTTP(resp, req)
+
+ dec := json.NewDecoder(captured)
+
+ gotReq := make(map[string]interface{})
+ err = dec.Decode(&gotReq)
+ c.Logf("%#v", gotReq)
+ c.Check(gotReq["RequestID"], check.Matches, "req-[a-z0-9]+")
+ c.Check(gotReq["reqForwardedFor"], check.Equals, "1.2.3.4:12345")
+ c.Check(gotReq["msg"], check.Equals, "request")
+
+ gotResp := make(map[string]interface{})
+ err = dec.Decode(&gotResp)
+ c.Logf("%#v", gotResp)
+ c.Check(gotResp["RequestID"], check.Equals, gotReq["RequestID"])
+ c.Check(gotResp["reqForwardedFor"], check.Equals, "1.2.3.4:12345")
+ c.Check(gotResp["msg"], check.Equals, "response")
+
+ c.Assert(gotResp["time"], check.FitsTypeOf, "")
+ _, err = time.Parse(time.RFC3339Nano, gotResp["time"].(string))
+ c.Check(err, check.IsNil)
+
+ for _, key := range []string{"timeToStatus", "timeWriteBody", "timeTotal"} {
+ c.Assert(gotResp[key], check.FitsTypeOf, float64(0))
+ c.Check(gotResp[key].(float64), check.Not(check.Equals), float64(0))
+ }
+}
commit 76ebbe5955988735c14d48d12db6a06024882d2b
Author: Tom Clegg <tclegg at veritasgenetics.com>
Date: Wed Nov 29 02:05:23 2017 -0500
12167: Fix tests.
Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tclegg at veritasgenetics.com>
diff --git a/services/keepstore/handler_test.go b/services/keepstore/handler_test.go
index 424910d..4d042a7 100644
--- a/services/keepstore/handler_test.go
+++ b/services/keepstore/handler_test.go
@@ -975,7 +975,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{router: MakeRESTRouter()}).ServeHTTP(resp, req)
+ MakeRESTRouter().ServeHTTP(resp, req)
ok <- struct{}{}
}()
diff --git a/services/keepstore/logging_router_test.go b/services/keepstore/logging_router_test.go
deleted file mode 100644
index 6ca48dc..0000000
--- a/services/keepstore/logging_router_test.go
+++ /dev/null
@@ -1,14 +0,0 @@
-// Copyright (C) The Arvados Authors. All rights reserved.
-//
-// SPDX-License-Identifier: AGPL-3.0
-
-package main
-
-import (
- "net/http"
- "testing"
-)
-
-func TestLoggingResponseWriterImplementsCloseNotifier(t *testing.T) {
- http.ResponseWriter(&LoggingResponseWriter{}).(http.CloseNotifier).CloseNotify()
-}
commit 4412d92e672d4df12ffc04c2b747b750e313cae9
Author: Tom Clegg <tclegg at veritasgenetics.com>
Date: Mon Nov 27 10:51:45 2017 -0500
12167: Restore timeToStatus + timeWriteBody in keepstore/proxy logs.
Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tclegg at veritasgenetics.com>
diff --git a/sdk/go/httpserver/logger.go b/sdk/go/httpserver/logger.go
index a66b0c9..decb2ff 100644
--- a/sdk/go/httpserver/logger.go
+++ b/sdk/go/httpserver/logger.go
@@ -23,7 +23,7 @@ var requestTimeContextKey = contextKey{"requestTime"}
// response via logrus.
func LogRequests(h http.Handler) http.Handler {
return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
- w := WrapResponseWriter(wrapped)
+ w := &responseTimer{ResponseWriter: WrapResponseWriter(wrapped)}
req = req.WithContext(context.WithValue(req.Context(), &requestTimeContextKey, time.Now()))
lgr := log.WithFields(log.Fields{
"RequestID": req.Header.Get("X-Request-Id"),
@@ -39,18 +39,17 @@ func LogRequests(h http.Handler) http.Handler {
})
}
-func logRequest(w ResponseWriter, req *http.Request, lgr *log.Entry) {
+func logRequest(w *responseTimer, req *http.Request, lgr *log.Entry) {
lgr.Info("request")
}
-func logResponse(w ResponseWriter, req *http.Request, lgr *log.Entry) {
+func logResponse(w *responseTimer, req *http.Request, lgr *log.Entry) {
if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
tDone := time.Now()
lgr = lgr.WithFields(log.Fields{
- "timeTotal": stats.Duration(tDone.Sub(tStart)),
- // TODO: track WriteHeader timing
- // "timeToStatus": stats.Duration(w.sentHdr.Sub(tStart)),
- // "timeWriteBody": stats.Duration(tDone.Sub(w.sentHdr)),
+ "timeTotal": stats.Duration(tDone.Sub(tStart)),
+ "timeToStatus": stats.Duration(w.writeTime.Sub(tStart)),
+ "timeWriteBody": stats.Duration(tDone.Sub(w.writeTime)),
})
}
lgr.WithFields(log.Fields{
@@ -59,3 +58,25 @@ func logResponse(w ResponseWriter, req *http.Request, lgr *log.Entry) {
"respBytes": w.WroteBodyBytes(),
}).Info("response")
}
+
+type responseTimer struct {
+ ResponseWriter
+ wrote bool
+ writeTime time.Time
+}
+
+func (rt *responseTimer) WriteHeader(code int) {
+ if !rt.wrote {
+ rt.wrote = true
+ rt.writeTime = time.Now()
+ }
+ rt.ResponseWriter.WriteHeader(code)
+}
+
+func (rt *responseTimer) Write(p []byte) (int, error) {
+ if !rt.wrote {
+ rt.wrote = true
+ rt.writeTime = time.Now()
+ }
+ return rt.ResponseWriter.Write(p)
+}
commit 03a016b1edff72e698474cd31a887530ea89b530
Merge: b21dbd5 49707c4
Author: Tom Clegg <tclegg at veritasgenetics.com>
Date: Sat Nov 25 02:20:23 2017 -0500
12167: Merge branch 'master' into 12167-keep-request-id
Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tclegg at veritasgenetics.com>
diff --cc services/keepproxy/keepproxy_test.go
index eb2ed53,23bb2bd..a7b608b
--- a/services/keepproxy/keepproxy_test.go
+++ b/services/keepproxy/keepproxy_test.go
@@@ -10,6 -10,8 +10,7 @@@ import
"errors"
"fmt"
"io/ioutil"
- "log"
+ "math/rand"
"net/http"
"net/http/httptest"
"os"
commit b21dbd5c2fec1c8c61d232b2cf7f0a68240d9203
Author: Tom Clegg <tclegg at veritasgenetics.com>
Date: Fri Nov 24 16:52:36 2017 -0500
12167: Clean up test suite logging.
Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tclegg at veritasgenetics.com>
diff --git a/services/keepproxy/keepproxy_test.go b/services/keepproxy/keepproxy_test.go
index 25619bb..eb2ed53 100644
--- a/services/keepproxy/keepproxy_test.go
+++ b/services/keepproxy/keepproxy_test.go
@@ -10,7 +10,6 @@ import (
"errors"
"fmt"
"io/ioutil"
- "log"
"net/http"
"net/http/httptest"
"os"
@@ -55,7 +54,7 @@ func waitForListener() {
time.Sleep(ms * time.Millisecond)
}
if listener == nil {
- log.Fatalf("Timed out waiting for listener to start")
+ panic("Timed out waiting for listener to start")
}
}
@@ -226,14 +225,14 @@ func (s *ServerRequiredSuite) TestPutAskGet(c *C) {
{
_, _, err := kc.Ask(hash)
c.Check(err, Equals, keepclient.BlockNotFound)
- log.Print("Finished Ask (expected BlockNotFound)")
+ c.Log("Finished Ask (expected BlockNotFound)")
}
{
reader, _, _, err := kc.Get(hash)
c.Check(reader, Equals, nil)
c.Check(err, Equals, keepclient.BlockNotFound)
- log.Print("Finished Get (expected BlockNotFound)")
+ c.Log("Finished Get (expected BlockNotFound)")
}
// Note in bug #5309 among other errors keepproxy would set
@@ -252,14 +251,14 @@ func (s *ServerRequiredSuite) TestPutAskGet(c *C) {
c.Check(hash2, Matches, fmt.Sprintf(`^%s\+3(\+.+)?$`, hash))
c.Check(rep, Equals, 2)
c.Check(err, Equals, nil)
- log.Print("Finished PutB (expected success)")
+ c.Log("Finished PutB (expected success)")
}
{
blocklen, _, err := kc.Ask(hash2)
c.Assert(err, Equals, nil)
c.Check(blocklen, Equals, int64(3))
- log.Print("Finished Ask (expected success)")
+ c.Log("Finished Ask (expected success)")
}
{
@@ -268,7 +267,7 @@ func (s *ServerRequiredSuite) TestPutAskGet(c *C) {
all, err := ioutil.ReadAll(reader)
c.Check(all, DeepEquals, []byte("foo"))
c.Check(blocklen, Equals, int64(3))
- log.Print("Finished Get (expected success)")
+ c.Log("Finished Get (expected success)")
}
{
@@ -278,7 +277,7 @@ func (s *ServerRequiredSuite) TestPutAskGet(c *C) {
c.Check(hash2, Matches, `^d41d8cd98f00b204e9800998ecf8427e\+0(\+.+)?$`)
c.Check(rep, Equals, 2)
c.Check(err, Equals, nil)
- log.Print("Finished PutB zero block")
+ c.Log("Finished PutB zero block")
}
{
@@ -287,7 +286,7 @@ func (s *ServerRequiredSuite) TestPutAskGet(c *C) {
all, err := ioutil.ReadAll(reader)
c.Check(all, DeepEquals, []byte(""))
c.Check(blocklen, Equals, int64(0))
- log.Print("Finished Get zero block")
+ c.Log("Finished Get zero block")
}
}
@@ -302,7 +301,7 @@ func (s *ServerRequiredSuite) TestPutAskGetForbidden(c *C) {
errNotFound, _ := err.(keepclient.ErrNotFound)
c.Check(errNotFound, NotNil)
c.Assert(strings.Contains(err.Error(), "HTTP 403"), Equals, true)
- log.Print("Ask 1")
+ c.Log("Ask 1")
}
{
@@ -310,7 +309,7 @@ func (s *ServerRequiredSuite) TestPutAskGetForbidden(c *C) {
c.Check(hash2, Equals, "")
c.Check(rep, Equals, 0)
c.Check(err, FitsTypeOf, keepclient.InsufficientReplicasError(errors.New("")))
- log.Print("PutB")
+ c.Log("PutB")
}
{
@@ -319,7 +318,7 @@ func (s *ServerRequiredSuite) TestPutAskGetForbidden(c *C) {
c.Check(errNotFound, NotNil)
c.Assert(strings.Contains(err.Error(), "HTTP 403"), Equals, true)
c.Check(blocklen, Equals, int64(0))
- log.Print("Ask 2")
+ c.Log("Ask 2")
}
{
@@ -328,7 +327,7 @@ func (s *ServerRequiredSuite) TestPutAskGetForbidden(c *C) {
c.Check(errNotFound, NotNil)
c.Assert(strings.Contains(err.Error(), "HTTP 403"), Equals, true)
c.Check(blocklen, Equals, int64(0))
- log.Print("Get")
+ c.Log("Get")
}
}
@@ -343,7 +342,7 @@ func (s *ServerRequiredSuite) TestGetDisabled(c *C) {
errNotFound, _ := err.(keepclient.ErrNotFound)
c.Check(errNotFound, NotNil)
c.Assert(strings.Contains(err.Error(), "HTTP 400"), Equals, true)
- log.Print("Ask 1")
+ c.Log("Ask 1")
}
{
@@ -351,7 +350,7 @@ func (s *ServerRequiredSuite) TestGetDisabled(c *C) {
c.Check(hash2, Matches, fmt.Sprintf(`^%s\+3(\+.+)?$`, hash))
c.Check(rep, Equals, 2)
c.Check(err, Equals, nil)
- log.Print("PutB")
+ c.Log("PutB")
}
{
@@ -360,7 +359,7 @@ func (s *ServerRequiredSuite) TestGetDisabled(c *C) {
c.Check(errNotFound, NotNil)
c.Assert(strings.Contains(err.Error(), "HTTP 400"), Equals, true)
c.Check(blocklen, Equals, int64(0))
- log.Print("Ask 2")
+ c.Log("Ask 2")
}
{
@@ -369,7 +368,7 @@ func (s *ServerRequiredSuite) TestGetDisabled(c *C) {
c.Check(errNotFound, NotNil)
c.Assert(strings.Contains(err.Error(), "HTTP 400"), Equals, true)
c.Check(blocklen, Equals, int64(0))
- log.Print("Get")
+ c.Log("Get")
}
}
commit f328939c83c4cd4dfd8ed9c389e1e1bdc3fea05d
Author: Tom Clegg <tclegg at veritasgenetics.com>
Date: Fri Nov 24 16:46:58 2017 -0500
12167: Propagate X-Request-ID through keepproxy and keepstore.
Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tclegg at veritasgenetics.com>
diff --git a/sdk/go/httpserver/id_generator.go b/sdk/go/httpserver/id_generator.go
index 18fd91f..c744691 100644
--- a/sdk/go/httpserver/id_generator.go
+++ b/sdk/go/httpserver/id_generator.go
@@ -5,6 +5,7 @@
package httpserver
import (
+ "net/http"
"strconv"
"sync"
"time"
@@ -33,3 +34,15 @@ func (g *IDGenerator) Next() string {
g.mtx.Unlock()
return g.Prefix + strconv.FormatInt(id, 36)
}
+
+// AddRequestIDs wraps an http.Handler, adding an X-Request-Id header
+// to each request that doesn't already have one.
+func AddRequestIDs(h http.Handler) http.Handler {
+ gen := &IDGenerator{Prefix: "req-"}
+ return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+ if req.Header.Get("X-Request-Id") == "" {
+ req.Header.Set("X-Request-Id", gen.Next())
+ }
+ h.ServeHTTP(w, req)
+ })
+}
diff --git a/sdk/go/httpserver/logger.go b/sdk/go/httpserver/logger.go
new file mode 100644
index 0000000..a66b0c9
--- /dev/null
+++ b/sdk/go/httpserver/logger.go
@@ -0,0 +1,61 @@
+// Copyright (C) The Arvados Authors. All rights reserved.
+//
+// SPDX-License-Identifier: AGPL-3.0
+
+package httpserver
+
+import (
+ "context"
+ "net/http"
+ "time"
+
+ "git.curoverse.com/arvados.git/sdk/go/stats"
+ log "github.com/Sirupsen/logrus"
+)
+
+type contextKey struct {
+ name string
+}
+
+var requestTimeContextKey = contextKey{"requestTime"}
+
+// LogRequests wraps an http.Handler, logging each request and
+// response via logrus.
+func LogRequests(h http.Handler) http.Handler {
+ return http.HandlerFunc(func(wrapped http.ResponseWriter, req *http.Request) {
+ w := WrapResponseWriter(wrapped)
+ req = req.WithContext(context.WithValue(req.Context(), &requestTimeContextKey, time.Now()))
+ lgr := log.WithFields(log.Fields{
+ "RequestID": req.Header.Get("X-Request-Id"),
+ "remoteAddr": req.RemoteAddr,
+ "reqForwardedFor": req.Header.Get("X-Forwarded-For"),
+ "reqMethod": req.Method,
+ "reqPath": req.URL.Path[1:],
+ "reqBytes": req.ContentLength,
+ })
+ logRequest(w, req, lgr)
+ defer logResponse(w, req, lgr)
+ h.ServeHTTP(w, req)
+ })
+}
+
+func logRequest(w ResponseWriter, req *http.Request, lgr *log.Entry) {
+ lgr.Info("request")
+}
+
+func logResponse(w ResponseWriter, req *http.Request, lgr *log.Entry) {
+ if tStart, ok := req.Context().Value(&requestTimeContextKey).(time.Time); ok {
+ tDone := time.Now()
+ lgr = lgr.WithFields(log.Fields{
+ "timeTotal": stats.Duration(tDone.Sub(tStart)),
+ // TODO: track WriteHeader timing
+ // "timeToStatus": stats.Duration(w.sentHdr.Sub(tStart)),
+ // "timeWriteBody": stats.Duration(tDone.Sub(w.sentHdr)),
+ })
+ }
+ lgr.WithFields(log.Fields{
+ "respStatusCode": w.WroteStatus(),
+ "respStatus": http.StatusText(w.WroteStatus()),
+ "respBytes": w.WroteBodyBytes(),
+ }).Info("response")
+}
diff --git a/services/keepproxy/keepproxy.go b/services/keepproxy/keepproxy.go
index 3d1b447..e2a6221 100644
--- a/services/keepproxy/keepproxy.go
+++ b/services/keepproxy/keepproxy.go
@@ -10,7 +10,6 @@ import (
"fmt"
"io"
"io/ioutil"
- "log"
"net"
"net/http"
"os"
@@ -25,7 +24,9 @@ import (
"git.curoverse.com/arvados.git/sdk/go/arvadosclient"
"git.curoverse.com/arvados.git/sdk/go/config"
"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"
"github.com/coreos/go-systemd/daemon"
"github.com/ghodss/yaml"
"github.com/gorilla/mux"
@@ -55,7 +56,13 @@ var (
router http.Handler
)
+const rfc3339NanoFixed = "2006-01-02T15:04:05.000000000Z07:00"
+
func main() {
+ log.SetFormatter(&log.JSONFormatter{
+ TimestampFormat: rfc3339NanoFixed,
+ })
+
cfg := DefaultConfig()
flagset := flag.NewFlagSet("keepproxy", flag.ExitOnError)
@@ -164,7 +171,7 @@ func main() {
// Start serving requests.
router = MakeRESTRouter(!cfg.DisableGet, !cfg.DisablePut, kc, time.Duration(cfg.Timeout), cfg.ManagementToken)
- http.Serve(listener, router)
+ http.Serve(listener, httpserver.AddRequestIDs(httpserver.LogRequests(router)))
log.Println("shutting down")
}
@@ -596,7 +603,8 @@ func (h *proxyHandler) makeKeepClient(req *http.Request) *keepclient.KeepClient
Timeout: h.timeout,
Transport: h.transport,
},
- proto: req.Proto,
+ proto: req.Proto,
+ requestID: req.Header.Get("X-Request-Id"),
}
return &kc
}
diff --git a/services/keepproxy/proxy_client.go b/services/keepproxy/proxy_client.go
index 0faf4ae..3fa2671 100644
--- a/services/keepproxy/proxy_client.go
+++ b/services/keepproxy/proxy_client.go
@@ -13,11 +13,13 @@ import (
var viaAlias = "keepproxy"
type proxyClient struct {
- client keepclient.HTTPClient
- proto string
+ client keepclient.HTTPClient
+ proto string
+ requestID string
}
func (pc *proxyClient) Do(req *http.Request) (*http.Response, error) {
req.Header.Add("Via", pc.proto+" "+viaAlias)
+ req.Header.Add("X-Request-Id", pc.requestID)
return pc.client.Do(req)
}
diff --git a/services/keepstore/keepstore.go b/services/keepstore/keepstore.go
index 921176d..e422179 100644
--- a/services/keepstore/keepstore.go
+++ b/services/keepstore/keepstore.go
@@ -147,11 +147,11 @@ func main() {
// Start a round-robin VolumeManager with the volumes we have found.
KeepVM = MakeRRVolumeManager(theConfig.Volumes)
- // Middleware stack: logger, MaxRequests limiter, method handlers
+ // Middleware/handler stack
router := MakeRESTRouter()
limiter := httpserver.NewRequestLimiter(theConfig.MaxRequests, router)
router.limiter = limiter
- http.Handle("/", &LoggingRESTRouter{router: limiter})
+ http.Handle("/", httpserver.AddRequestIDs(httpserver.LogRequests(limiter)))
// Set up a TCP listener.
listener, err := net.Listen("tcp", theConfig.Listen)
diff --git a/services/keepstore/logging_router.go b/services/keepstore/logging_router.go
deleted file mode 100644
index 63c28a2..0000000
--- a/services/keepstore/logging_router.go
+++ /dev/null
@@ -1,111 +0,0 @@
-// Copyright (C) The Arvados Authors. All rights reserved.
-//
-// SPDX-License-Identifier: AGPL-3.0
-
-package main
-
-// LoggingRESTRouter
-// LoggingResponseWriter
-
-import (
- "context"
- "net/http"
- "strings"
- "time"
-
- "git.curoverse.com/arvados.git/sdk/go/httpserver"
- "git.curoverse.com/arvados.git/sdk/go/stats"
- log "github.com/Sirupsen/logrus"
-)
-
-// LoggingResponseWriter has anonymous fields ResponseWriter and ResponseBody
-type LoggingResponseWriter struct {
- Status int
- Length int
- http.ResponseWriter
- ResponseBody string
- sentHdr time.Time
-}
-
-// CloseNotify implements http.CloseNotifier.
-func (resp *LoggingResponseWriter) CloseNotify() <-chan bool {
- wrapped, ok := resp.ResponseWriter.(http.CloseNotifier)
- if !ok {
- // If upstream doesn't implement CloseNotifier, we can
- // satisfy the interface by returning a channel that
- // never sends anything (the interface doesn't
- // guarantee that anything will ever be sent on the
- // channel even if the client disconnects).
- return nil
- }
- return wrapped.CloseNotify()
-}
-
-// WriteHeader writes header to ResponseWriter
-func (resp *LoggingResponseWriter) WriteHeader(code int) {
- if resp.sentHdr == zeroTime {
- resp.sentHdr = time.Now()
- }
- resp.Status = code
- resp.ResponseWriter.WriteHeader(code)
-}
-
-var zeroTime time.Time
-
-func (resp *LoggingResponseWriter) Write(data []byte) (int, error) {
- if resp.Length == 0 && len(data) > 0 && resp.sentHdr == zeroTime {
- resp.sentHdr = time.Now()
- }
- resp.Length += len(data)
- if resp.Status >= 400 {
- resp.ResponseBody += string(data)
- }
- return resp.ResponseWriter.Write(data)
-}
-
-// LoggingRESTRouter is used to add logging capabilities to mux.Router
-type LoggingRESTRouter struct {
- router http.Handler
- idGenerator httpserver.IDGenerator
-}
-
-func (loggingRouter *LoggingRESTRouter) ServeHTTP(wrappedResp http.ResponseWriter, req *http.Request) {
- tStart := time.Now()
-
- // 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.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
- }
-
- lgr.WithFields(log.Fields{
- "timeTotal": stats.Duration(tDone.Sub(tStart)),
- "timeToStatus": stats.Duration(resp.sentHdr.Sub(tStart)),
- "timeWriteBody": stats.Duration(tDone.Sub(resp.sentHdr)),
- "respStatusCode": resp.Status,
- "respStatus": statusText,
- "respBytes": resp.Length,
- }).Info("response")
-}
diff --git a/services/keepstore/s3_volume.go b/services/keepstore/s3_volume.go
index e6a53d0..61e69f9 100644
--- a/services/keepstore/s3_volume.go
+++ b/services/keepstore/s3_volume.go
@@ -45,6 +45,8 @@ var (
s3RaceWindow time.Duration
s3ACL = s3.Private
+
+ zeroTime time.Time
)
const (
-----------------------------------------------------------------------
hooks/post-receive
--
More information about the arvados-commits
mailing list