sdk/go/httpserver/logger_test.go

   1 // Copyright (C) The Arvados Authors. All rights reserved.
   2 //
   3 // SPDX-License-Identifier: Apache-2.0
   4
   5 package httpserver
   6
   7 import (
   8         "bytes"
   9         "context"
  10         "encoding/json"
  11         "fmt"
  12         "net/http"
  13         "net/http/httptest"
  14         "testing"
  15         "time"
  16
  17         "git.arvados.org/arvados.git/sdk/go/ctxlog"
  18         "github.com/sirupsen/logrus"
  19         check "gopkg.in/check.v1"
  20 )
  21
  22 func Test(t *testing.T) {
  23         check.TestingT(t)
  24 }
  25
  26 var _ = check.Suite(&Suite{})
  27
  28 type Suite struct {
  29         ctx     context.Context
  30         log     *logrus.Logger
  31         logdata *bytes.Buffer
  32 }
  33
  34 func (s *Suite) SetUpTest(c *check.C) {
  35         s.logdata = bytes.NewBuffer(nil)
  36         s.log = logrus.New()
  37         s.log.Out = s.logdata
  38         s.log.Formatter = &logrus.JSONFormatter{
  39                 TimestampFormat: time.RFC3339Nano,
  40         }
  41         s.ctx = ctxlog.Context(context.Background(), s.log)
  42 }
  43
  44 func (s *Suite) TestWithDeadline(c *check.C) {
  45         req, err := http.NewRequest("GET", "https://foo.example/bar", nil)
  46         c.Assert(err, check.IsNil)
  47
  48         // Short timeout cancels context in <1s
  49         resp := httptest.NewRecorder()
  50         HandlerWithDeadline(time.Millisecond, http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
  51                 select {
  52                 case <-req.Context().Done():
  53                         w.Write([]byte("ok"))
  54                 case <-time.After(time.Second):
  55                         c.Error("timed out")
  56                 }
  57         })).ServeHTTP(resp, req.WithContext(s.ctx))
  58         c.Check(resp.Body.String(), check.Equals, "ok")
  59
  60         // Long timeout does not cancel context in <1ms
  61         resp = httptest.NewRecorder()
  62         HandlerWithDeadline(time.Second, http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
  63                 select {
  64                 case <-req.Context().Done():
  65                         c.Error("request context done too soon")
  66                 case <-time.After(time.Millisecond):
  67                         w.Write([]byte("ok"))
  68                 }
  69         })).ServeHTTP(resp, req.WithContext(s.ctx))
  70         c.Check(resp.Body.String(), check.Equals, "ok")
  71 }
  72
  73 func (s *Suite) TestLogRequests(c *check.C) {
  74         h := AddRequestIDs(LogRequests(
  75                 http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
  76                         w.Write([]byte("hello world"))
  77                 })))
  78
  79         req, err := http.NewRequest("GET", "https://foo.example/bar", nil)
  80         req.Header.Set("X-Forwarded-For", "1.2.3.4:12345")
  81         c.Assert(err, check.IsNil)
  82         resp := httptest.NewRecorder()
  83
  84         h.ServeHTTP(resp, req.WithContext(s.ctx))
  85
  86         dec := json.NewDecoder(s.logdata)
  87
  88         gotReq := make(map[string]interface{})
  89         err = dec.Decode(&gotReq)
  90         c.Check(err, check.IsNil)
  91         c.Logf("%#v", gotReq)
  92         c.Check(gotReq["RequestID"], check.Matches, "req-[a-z0-9]{20}")
  93         c.Check(gotReq["reqForwardedFor"], check.Equals, "1.2.3.4:12345")
  94         c.Check(gotReq["msg"], check.Equals, "request")
  95
  96         gotResp := make(map[string]interface{})
  97         err = dec.Decode(&gotResp)
  98         c.Check(err, check.IsNil)
  99         c.Logf("%#v", gotResp)
 100         c.Check(gotResp["RequestID"], check.Equals, gotReq["RequestID"])
 101         c.Check(gotResp["reqForwardedFor"], check.Equals, "1.2.3.4:12345")
 102         c.Check(gotResp["msg"], check.Equals, "response")
 103
 104         c.Assert(gotResp["time"], check.FitsTypeOf, "")
 105         _, err = time.Parse(time.RFC3339Nano, gotResp["time"].(string))
 106         c.Check(err, check.IsNil)
 107
 108         for _, key := range []string{"timeToStatus", "timeWriteBody", "timeTotal"} {
 109                 c.Assert(gotResp[key], check.FitsTypeOf, float64(0))
 110                 c.Check(gotResp[key].(float64), check.Not(check.Equals), float64(0))
 111         }
 112 }
 113
 114 func (s *Suite) TestLogErrorBody(c *check.C) {
 115         dec := json.NewDecoder(s.logdata)
 116
 117         for _, trial := range []struct {
 118                 label      string
 119                 statusCode int
 120                 sentBody   string
 121                 expectLog  bool
 122                 expectBody string
 123         }{
 124                 {"ok", 200, "hello world", false, ""},
 125                 {"redir", 302, "<a href='http://foo.example/baz'>redir</a>", false, ""},
 126                 {"4xx short body", 400, "oops", true, "oops"},
 127                 {"4xx long body", 400, fmt.Sprintf("%0*d", sniffBytes*2, 1), true, fmt.Sprintf("%0*d", sniffBytes, 0)},
 128                 {"5xx empty body", 500, "", true, ""},
 129         } {
 130                 comment := check.Commentf("in trial: %q", trial.label)
 131
 132                 req, err := http.NewRequest("GET", "https://foo.example/bar", nil)
 133                 c.Assert(err, check.IsNil)
 134                 resp := httptest.NewRecorder()
 135
 136                 LogRequests(
 137                         http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
 138                                 w.WriteHeader(trial.statusCode)
 139                                 w.Write([]byte(trial.sentBody))
 140                         }),
 141                 ).ServeHTTP(resp, req.WithContext(s.ctx))
 142
 143                 gotReq := make(map[string]interface{})
 144                 err = dec.Decode(&gotReq)
 145                 c.Check(err, check.IsNil)
 146                 c.Logf("%#v", gotReq)
 147                 gotResp := make(map[string]interface{})
 148                 err = dec.Decode(&gotResp)
 149                 c.Check(err, check.IsNil)
 150                 c.Logf("%#v", gotResp)
 151                 if trial.expectLog {
 152                         c.Check(gotResp["respBody"], check.Equals, trial.expectBody, comment)
 153                 } else {
 154                         c.Check(gotResp["respBody"], check.IsNil, comment)
 155                 }
 156         }
 157 }