1 package reqlog
2
3 import (
4 "bytes"
5 "fmt"
6 "net/http"
7 "net/http/httptest"
8 "strings"
9 "testing"
10 "time"
11
12 "github.com/sirupsen/logrus"
13 "github.com/stretchr/testify/assert"
14 "github.com/urfave/negroni"
15
16 "github.com/ory/x/logrusx"
17 )
18
19 var (
20 nowTime = time.Now()
21 nowToday = nowTime.Format("2006-01-02")
22 )
23
24 type testClock struct{}
25
26 func (tc *testClock) Now() time.Time {
27 return nowTime
28 }
29
30 func (tc *testClock) Since(time.Time) time.Duration {
31 return 10 * time.Microsecond
32 }
33
34 func TestNewMiddleware_Logger(t *testing.T) {
35 l := logrusx.New("", "")
36 mw := NewMiddleware()
37 assert.NotEqual(t, fmt.Sprintf("%p", mw.Logger), fmt.Sprintf("%p", l))
38 }
39
40 func TestNewMiddleware_Name(t *testing.T) {
41 mw := NewMiddleware()
42 assert.Equal(t, "web", mw.Name)
43 }
44
45 func TestNewMiddleware_LoggerFormatter(t *testing.T) {
46 mw := NewMiddleware()
47 assert.Equal(t, &logrus.TextFormatter{}, mw.Logger.Logger.Formatter)
48 }
49
50 func TestNewMiddleware_logStarting(t *testing.T) {
51 mw := NewMiddleware()
52 assert.True(t, mw.logStarting)
53 }
54
55 func TestNewCustomMiddleware_Name(t *testing.T) {
56 mw := NewCustomMiddleware(logrus.DebugLevel, &logrus.JSONFormatter{}, "test")
57 assert.Equal(t, "test", mw.Name)
58 }
59
60 func TestNewCustomMiddleware_LoggerFormatter(t *testing.T) {
61 f := &logrus.JSONFormatter{}
62 mw := NewCustomMiddleware(logrus.DebugLevel, f, "test")
63 assert.Equal(t, f, mw.Logger.Logger.Formatter)
64 }
65
66 func TestNewCustomMiddleware_LoggerLevel(t *testing.T) {
67 l := logrus.DebugLevel
68 mw := NewCustomMiddleware(l, &logrus.JSONFormatter{}, "test")
69 assert.Equal(t, l, mw.Logger.Logger.Level)
70 }
71
72 func TestNewCustomMiddleware_logStarting(t *testing.T) {
73 mw := NewCustomMiddleware(logrus.DebugLevel, &logrus.JSONFormatter{}, "test")
74 assert.True(t, mw.logStarting)
75 }
76
77 func TestNewMiddlewareFromLogger_Logger(t *testing.T) {
78 l := logrusx.New("", "")
79 mw := NewMiddlewareFromLogger(l, "test")
80 assert.Exactly(t, l, mw.Logger)
81 }
82
83 func TestNewMiddlewareFromLogger_Name(t *testing.T) {
84 mw := NewMiddlewareFromLogger(logrusx.New("", ""), "test")
85 assert.Equal(t, "test", mw.Name)
86 }
87
88 func TestNewMiddlewareFromLogger_logStarting(t *testing.T) {
89 mw := NewMiddlewareFromLogger(logrusx.New("", ""), "test")
90 assert.True(t, mw.logStarting)
91 }
92
93 func setupServeHTTP(t *testing.T) (*Middleware, negroni.ResponseWriter, *http.Request) {
94 req, err := http.NewRequest("GET", "http://example.com/stuff?rly=ya", nil)
95 assert.Nil(t, err)
96
97 req.RequestURI = "http://example.com/stuff?rly=ya"
98 req.Method = "GET"
99 req.Header.Set("X-Request-Id", "22035D08-98EF-413C-BBA0-C4E66A11B28D")
100 req.Header.Set("X-Real-IP", "10.10.10.10")
101
102 mw := NewMiddleware()
103 mw.Logger.Logger.Formatter = &logrus.JSONFormatter{
104 TimestampFormat: "2006-01-02",
105 }
106 mw.Logger.Logger.Out = &bytes.Buffer{}
107 mw.clock = &testClock{}
108 mw.ExcludePaths("/ping")
109
110 return mw, negroni.NewResponseWriter(httptest.NewRecorder()), req
111 }
112
113 func TestMiddleware_ServeHTTP(t *testing.T) {
114 mw, rec, req := setupServeHTTP(t)
115 mw.ServeHTTP(rec, req, func(w http.ResponseWriter, r *http.Request) {
116 w.WriteHeader(418)
117 })
118 lines := strings.Split(strings.TrimSpace(mw.Logger.Logger.Out.(*bytes.Buffer).String()), "\n")
119 assert.Len(t, lines, 2)
120 assert.JSONEq(t,
121 fmt.Sprintf(`{"http_request":{"headers":{"x-request-id":"22035D08-98EF-413C-BBA0-C4E66A11B28D"},"host":"example.com","method":"GET","path":"/stuff","query":"Value is sensitive and has been redacted. To see the value set config key \"log.leak_sensitive_values = true\" or environment variable \"LOG_LEAK_SENSITIVE_VALUES=true\".","remote":"","scheme":"http"},"level":"info","msg":"started handling request","time":"%s"}`, nowToday),
122 lines[0], lines[0])
123 assert.JSONEq(t,
124 fmt.Sprintf(`{"http_request":{"headers":{"x-request-id":"22035D08-98EF-413C-BBA0-C4E66A11B28D"},"host":"example.com","method":"GET","path":"/stuff","query":"Value is sensitive and has been redacted. To see the value set config key \"log.leak_sensitive_values = true\" or environment variable \"LOG_LEAK_SENSITIVE_VALUES=true\".","remote":"","scheme":"http"},"http_response":{"status":418,"text_status":"I'm a teapot","took":10000},"level":"info","msg":"completed handling request","time":"%s"}`, nowToday),
125 lines[1], lines[1])
126 }
127
128 func TestMiddleware_ServeHTTP_nilHooks(t *testing.T) {
129 mw, rec, req := setupServeHTTP(t)
130 mw.Before = nil
131 mw.After = nil
132 mw.ServeHTTP(rec, req, func(w http.ResponseWriter, r *http.Request) {
133 w.WriteHeader(418)
134 })
135 lines := strings.Split(strings.TrimSpace(mw.Logger.Logger.Out.(*bytes.Buffer).String()), "\n")
136 assert.Len(t, lines, 2)
137 assert.JSONEq(t,
138 fmt.Sprintf(`{"http_request":{"headers":{"x-request-id":"22035D08-98EF-413C-BBA0-C4E66A11B28D"},"host":"example.com","method":"GET","path":"/stuff","query":"Value is sensitive and has been redacted. To see the value set config key \"log.leak_sensitive_values = true\" or environment variable \"LOG_LEAK_SENSITIVE_VALUES=true\".","remote":"","scheme":"http"},"level":"info","msg":"started handling request","time":"%s"}`, nowToday),
139 lines[0], lines[0])
140 assert.JSONEq(t,
141 fmt.Sprintf(`{"http_request":{"headers":{"x-request-id":"22035D08-98EF-413C-BBA0-C4E66A11B28D"},"host":"example.com","method":"GET","path":"/stuff","query":"Value is sensitive and has been redacted. To see the value set config key \"log.leak_sensitive_values = true\" or environment variable \"LOG_LEAK_SENSITIVE_VALUES=true\".","remote":"","scheme":"http"},"http_response":{"status":418,"text_status":"I'm a teapot","took":10000},"level":"info","msg":"completed handling request","time":"%s"}`, nowToday),
142 lines[1], lines[1])
143 }
144
145 func TestMiddleware_ServeHTTP_BeforeOverride(t *testing.T) {
146 mw, rec, req := setupServeHTTP(t)
147 mw.Before = func(entry *logrusx.Logger, _ *http.Request, _ string) *logrusx.Logger {
148 return entry.WithFields(logrus.Fields{"wat": 200})
149 }
150 mw.ServeHTTP(rec, req, func(w http.ResponseWriter, r *http.Request) {
151 w.WriteHeader(418)
152 })
153 lines := strings.Split(strings.TrimSpace(mw.Logger.Logger.Out.(*bytes.Buffer).String()), "\n")
154 assert.Len(t, lines, 2)
155 assert.JSONEq(t,
156 fmt.Sprintf(`{"http_request":{"headers":{"x-request-id":"22035D08-98EF-413C-BBA0-C4E66A11B28D"},"host":"example.com","method":"GET","path":"/stuff","query":"Value is sensitive and has been redacted. To see the value set config key \"log.leak_sensitive_values = true\" or environment variable \"LOG_LEAK_SENSITIVE_VALUES=true\".","remote":"","scheme":"http"},"http_response":{"status":418,"text_status":"I'm a teapot","took":10000},"level":"info","msg":"completed handling request","time":"%s","wat":200}`, nowToday),
157 lines[1], lines[1])
158 }
159
160 func TestMiddleware_ServeHTTP_AfterOverride(t *testing.T) {
161 mw, rec, req := setupServeHTTP(t)
162 mw.After = func(entry *logrusx.Logger, _ *http.Request, _ negroni.ResponseWriter, _ time.Duration, _ string) *logrusx.Logger {
163 return entry.WithFields(logrus.Fields{"hambone": 57})
164 }
165 mw.ServeHTTP(rec, req, func(w http.ResponseWriter, r *http.Request) {
166 w.WriteHeader(418)
167 })
168 lines := strings.Split(strings.TrimSpace(mw.Logger.Logger.Out.(*bytes.Buffer).String()), "\n")
169 assert.Len(t, lines, 2)
170 assert.JSONEq(t,
171 fmt.Sprintf(`{"hambone":57,"http_request":{"headers":{"x-request-id":"22035D08-98EF-413C-BBA0-C4E66A11B28D"},"host":"example.com","method":"GET","path":"/stuff","query":"Value is sensitive and has been redacted. To see the value set config key \"log.leak_sensitive_values = true\" or environment variable \"LOG_LEAK_SENSITIVE_VALUES=true\".","remote":"","scheme":"http"},"level":"info","msg":"completed handling request","time":"%s"}`, nowToday),
172 lines[1], lines[1])
173 }
174
175 func TestMiddleware_ServeHTTP_logStartingFalse(t *testing.T) {
176 mw, rec, req := setupServeHTTP(t)
177 mw.SetLogStarting(false)
178 mw.ServeHTTP(rec, req, func(w http.ResponseWriter, r *http.Request) {
179 w.WriteHeader(418)
180 })
181 lines := strings.Split(strings.TrimSpace(mw.Logger.Logger.Out.(*bytes.Buffer).String()), "\n")
182 assert.Len(t, lines, 1)
183 assert.JSONEq(t,
184 fmt.Sprintf(`{"http_request":{"headers":{"x-request-id":"22035D08-98EF-413C-BBA0-C4E66A11B28D"},"host":"example.com","method":"GET","path":"/stuff","query":"Value is sensitive and has been redacted. To see the value set config key \"log.leak_sensitive_values = true\" or environment variable \"LOG_LEAK_SENSITIVE_VALUES=true\".","remote":"","scheme":"http"},"http_response":{"status":418,"text_status":"I'm a teapot","took":10000},"level":"info","msg":"completed handling request","time":"%s"}`, nowToday),
185 lines[0], lines[0])
186 }
187
188 func TestServeHTTPWithURLExcluded(t *testing.T) {
189 mw, rec, req := setupServeHTTP(t)
190 mw.ExcludePaths(req.URL.Path)
191
192 nextHandlerCalled := false
193 mw.ServeHTTP(rec, req, func(w http.ResponseWriter, r *http.Request) {
194 nextHandlerCalled = true
195 w.WriteHeader(418)
196 })
197 lines := strings.Split(strings.TrimSpace(mw.Logger.Logger.Out.(*bytes.Buffer).String()), "\n")
198 assert.Equal(t, []string{""}, lines)
199 assert.True(t, nextHandlerCalled, "The next http.HandlerFunc was not called!")
200 }
201
202 func TestRealClock_Now(t *testing.T) {
203 rc := &realClock{}
204 tf := "2006-01-02T15:04:05"
205 assert.Equal(t, rc.Now().Format(tf), time.Now().Format(tf))
206 }
207
208 func TestRealClock_Since(t *testing.T) {
209 rc := &realClock{}
210 now := rc.Now()
211
212 napDuration := 10 * time.Millisecond
213 time.Sleep(napDuration)
214 since := rc.Since(now)
215
216 assert.True(t, since >= napDuration)
217 assert.True(t, since < napDuration+6*time.Millisecond)
218 }
219
View as plain text