sdk/go/httpserver/logger_test.go

   1 // Copyright (C) The Arvados Authors. All rights reserved.
   2 //
   3 // SPDX-License-Identifier: AGPL-3.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.curoverse.com/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) TestLogRequests(c *check.C) {
  45         h := AddRequestIDs(LogRequests(
  46                 http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
  47                         w.Write([]byte("hello world"))
  48                 })))
  49
  50         req, err := http.NewRequest("GET", "https://foo.example/bar", nil)
  51         req.Header.Set("X-Forwarded-For", "1.2.3.4:12345")
  52         c.Assert(err, check.IsNil)
  53         resp := httptest.NewRecorder()
  54
  55         HandlerWithContext(s.ctx, h).ServeHTTP(resp, req)
  56
  57         dec := json.NewDecoder(s.logdata)
  58
  59         gotReq := make(map[string]interface{})
  60         err = dec.Decode(&gotReq)
  61         c.Logf("%#v", gotReq)
  62         c.Check(gotReq["RequestID"], check.Matches, "req-[a-z0-9]{20}")
  63         c.Check(gotReq["reqForwardedFor"], check.Equals, "1.2.3.4:12345")
  64         c.Check(gotReq["msg"], check.Equals, "request")
  65
  66         gotResp := make(map[string]interface{})
  67         err = dec.Decode(&gotResp)
  68         c.Logf("%#v", gotResp)
  69         c.Check(gotResp["RequestID"], check.Equals, gotReq["RequestID"])
  70         c.Check(gotResp["reqForwardedFor"], check.Equals, "1.2.3.4:12345")
  71         c.Check(gotResp["msg"], check.Equals, "response")
  72
  73         c.Assert(gotResp["time"], check.FitsTypeOf, "")
  74         _, err = time.Parse(time.RFC3339Nano, gotResp["time"].(string))
  75         c.Check(err, check.IsNil)
  76
  77         for _, key := range []string{"timeToStatus", "timeWriteBody", "timeTotal"} {
  78                 c.Assert(gotResp[key], check.FitsTypeOf, float64(0))
  79                 c.Check(gotResp[key].(float64), check.Not(check.Equals), float64(0))
  80         }
  81 }
  82
  83 func (s *Suite) TestLogErrorBody(c *check.C) {
  84         dec := json.NewDecoder(s.logdata)
  85
  86         for _, trial := range []struct {
  87                 label      string
  88                 statusCode int
  89                 sentBody   string
  90                 expectLog  bool
  91                 expectBody string
  92         }{
  93                 {"ok", 200, "hello world", false, ""},
  94                 {"redir", 302, "<a href='http://foo.example/baz'>redir</a>", false, ""},
  95                 {"4xx short body", 400, "oops", true, "oops"},
  96                 {"4xx long body", 400, fmt.Sprintf("%0*d", sniffBytes*2, 1), true, fmt.Sprintf("%0*d", sniffBytes, 0)},
  97                 {"5xx empty body", 500, "", true, ""},
  98         } {
  99                 comment := check.Commentf("in trial: %q", trial.label)
 100
 101                 req, err := http.NewRequest("GET", "https://foo.example/bar", nil)
 102                 c.Assert(err, check.IsNil)
 103                 resp := httptest.NewRecorder()
 104
 105                 HandlerWithContext(s.ctx, LogRequests(
 106                         http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
 107                                 w.WriteHeader(trial.statusCode)
 108                                 w.Write([]byte(trial.sentBody))
 109                         }),
 110                 )).ServeHTTP(resp, req)
 111
 112                 gotReq := make(map[string]interface{})
 113                 err = dec.Decode(&gotReq)
 114                 c.Logf("%#v", gotReq)
 115                 gotResp := make(map[string]interface{})
 116                 err = dec.Decode(&gotResp)
 117                 c.Logf("%#v", gotResp)
 118                 if trial.expectLog {
 119                         c.Check(gotResp["respBody"], check.Equals, trial.expectBody, comment)
 120                 } else {
 121                         c.Check(gotResp["respBody"], check.IsNil, comment)
 122                 }
 123         }
 124 }