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