[ARVADOS] created: 1.3.0-1786-g7db3ceda1

[Git user]

        at  7db3ceda16742b65d73ebbc05d02351a5e0496bd (commit)


commit 7db3ceda16742b65d73ebbc05d02351a5e0496bd
Author: Tom Clegg <tclegg at veritasgenetics.com>
Date:   Wed Oct 23 15:57:12 2019 -0400

    15713: Include 1K of response body when logging error responses.
    
    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 f64708454..50191eb3f 100644
--- 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 3b2bc7758..eb71fcd81 100644
--- 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 8dea759cc..26aee65c5 100644
--- 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
+}

-----------------------------------------------------------------------


hooks/post-receive
--