15713: Include 1K of response body when logging error responses.

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 f64708454c2b1e12cb5a75906d7d43676629cfb5..50191eb3f0b04f36faedabf8f023a344a42b264e 100644 (file)
--- a/sdk/go/httpserver/logger.go
+++ b/sdk/go/httpserver/logger.go
@@ -78,11 +78,15 @@ func logResponse(w *responseTimer, req *http.Request, lgr *logrus.Entry) {
        if respCode == 0 {
                respCode = http.StatusOK
        }
-       lgr.WithFields(logrus.Fields{
+       fields := logrus.Fields{
                "respStatusCode": respCode,
                "respStatus":     http.StatusText(respCode),
                "respBytes":      w.WroteBodyBytes(),
-       }).Info("response")
+       }
+       if respCode >= 400 {
+               fields["respBody"] = string(w.Sniffed())
+       }
+       lgr.WithFields(fields).Info("response")
 }
 
 type responseTimer struct {

diff --git a/sdk/go/httpserver/logger_test.go b/sdk/go/httpserver/logger_test.go
index 3b2bc7758069b44345b3da522b8f80cc303c52fe..eb71fcd814fdaf87262553f47731a8c2a555ba0e 100644 (file)
--- a/sdk/go/httpserver/logger_test.go
+++ b/sdk/go/httpserver/logger_test.go
@@ -8,6 +8,7 @@ import (
        "bytes"
        "context"
        "encoding/json"
+       "fmt"
        "net/http"
        "net/http/httptest"
        "testing"
@@ -24,17 +25,23 @@ func Test(t *testing.T) {
 
 var _ = check.Suite(&Suite{})
 
-type Suite struct{}
+type Suite struct {
+       ctx     context.Context
+       log     *logrus.Logger
+       logdata *bytes.Buffer
+}
 
-func (s *Suite) TestLogRequests(c *check.C) {
-       captured := &bytes.Buffer{}
-       log := logrus.New()
-       log.Out = captured
-       log.Formatter = &logrus.JSONFormatter{
+func (s *Suite) SetUpTest(c *check.C) {
+       s.logdata = bytes.NewBuffer(nil)
+       s.log = logrus.New()
+       s.log.Out = s.logdata
+       s.log.Formatter = &logrus.JSONFormatter{
                TimestampFormat: time.RFC3339Nano,
        }
-       ctx := ctxlog.Context(context.Background(), log)
+       s.ctx = ctxlog.Context(context.Background(), s.log)
+}
 
+func (s *Suite) TestLogRequests(c *check.C) {
        h := AddRequestIDs(LogRequests(
                http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
                        w.Write([]byte("hello world"))
@@ -45,9 +52,9 @@ func (s *Suite) TestLogRequests(c *check.C) {
        c.Assert(err, check.IsNil)
        resp := httptest.NewRecorder()
 
-       HandlerWithContext(ctx, h).ServeHTTP(resp, req)
+       HandlerWithContext(s.ctx, h).ServeHTTP(resp, req)
 
-       dec := json.NewDecoder(captured)
+       dec := json.NewDecoder(s.logdata)
 
        gotReq := make(map[string]interface{})
        err = dec.Decode(&gotReq)
@@ -72,3 +79,46 @@ func (s *Suite) TestLogRequests(c *check.C) {
                c.Check(gotResp[key].(float64), check.Not(check.Equals), float64(0))
        }
 }
+
+func (s *Suite) TestLogErrorBody(c *check.C) {
+       dec := json.NewDecoder(s.logdata)
+
+       for _, trial := range []struct {
+               label      string
+               statusCode int
+               sentBody   string
+               expectLog  bool
+               expectBody string
+       }{
+               {"ok", 200, "hello world", false, ""},
+               {"redir", 302, "<a href='http://foo.example/baz'>redir</a>", false, ""},
+               {"4xx short body", 400, "oops", true, "oops"},
+               {"4xx long body", 400, fmt.Sprintf("%0*d", sniffBytes*2, 1), true, fmt.Sprintf("%0*d", sniffBytes, 0)},
+               {"5xx empty body", 500, "", true, ""},
+       } {
+               comment := check.Commentf("in trial: %q", trial.label)
+
+               req, err := http.NewRequest("GET", "https://foo.example/bar", nil)
+               c.Assert(err, check.IsNil)
+               resp := httptest.NewRecorder()
+
+               HandlerWithContext(s.ctx, LogRequests(
+                       http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+                               w.WriteHeader(trial.statusCode)
+                               w.Write([]byte(trial.sentBody))
+                       }),
+               )).ServeHTTP(resp, req)
+
+               gotReq := make(map[string]interface{})
+               err = dec.Decode(&gotReq)
+               c.Logf("%#v", gotReq)
+               gotResp := make(map[string]interface{})
+               err = dec.Decode(&gotResp)
+               c.Logf("%#v", gotResp)
+               if trial.expectLog {
+                       c.Check(gotResp["respBody"], check.Equals, trial.expectBody, comment)
+               } else {
+                       c.Check(gotResp["respBody"], check.IsNil, comment)
+               }
+       }
+}

diff --git a/sdk/go/httpserver/responsewriter.go b/sdk/go/httpserver/responsewriter.go
index 8dea759ccb9b1772b816ad565a279975ab751c8a..26aee65c5ca0da1f5e23e301aa88024c3fac51b9 100644 (file)
--- a/sdk/go/httpserver/responsewriter.go
+++ b/sdk/go/httpserver/responsewriter.go
@@ -8,10 +8,13 @@ import (
        "net/http"
 )
 
+const sniffBytes = 1024
+
 type ResponseWriter interface {
        http.ResponseWriter
        WroteStatus() int
        WroteBodyBytes() int
+       Sniffed() []byte
 }
 
 // responseWriter wraps http.ResponseWriter and exposes the status
@@ -22,6 +25,7 @@ type responseWriter struct {
        wroteStatus    int   // Last status given to WriteHeader()
        wroteBodyBytes int   // Bytes successfully written
        err            error // Last error returned from Write()
+       sniffed        []byte
 }
 
 func WrapResponseWriter(orig http.ResponseWriter) ResponseWriter {
@@ -44,6 +48,7 @@ func (w *responseWriter) Write(data []byte) (n int, err error) {
        if w.wroteStatus == 0 {
                w.WriteHeader(http.StatusOK)
        }
+       w.sniff(data)
        n, err = w.ResponseWriter.Write(data)
        w.wroteBodyBytes += n
        w.err = err
@@ -61,3 +66,17 @@ func (w *responseWriter) WroteBodyBytes() int {
 func (w *responseWriter) Err() error {
        return w.err
 }
+
+func (w *responseWriter) sniff(data []byte) {
+       max := sniffBytes - len(w.sniffed)
+       if max <= 0 {
+               return
+       } else if max < len(data) {
+               data = data[:max]
+       }
+       w.sniffed = append(w.sniffed, data...)
+}
+
+func (w *responseWriter) Sniffed() []byte {
+       return w.sniffed
+}