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