logger_test.go (10400B)
1 package logging 2 3 import ( 4 "bytes" 5 "encoding/json" 6 "errors" 7 "github.com/sirupsen/logrus" 8 "github.com/stretchr/testify/assert" 9 "net/http" 10 "os" 11 "testing" 12 "time" 13 ) 14 15 type logReccord struct { 16 Type string `json:"type"` 17 Timestamp string `json:"@timestamp"` 18 CorrelationId string `json:"correlation_id"` 19 RemoteIp string `json:"remote_ip"` 20 Host string `json:"host"` 21 URL string `json:"url"` 22 Method string `json:"method"` 23 Proto string `json:"proto"` 24 Duration int `json:"duration"` 25 ResponseStatus int `json:"response_status"` 26 UserCorrelationId string `json:"user_correlation_id"` 27 Cookies map[string]string `json:"cookies"` 28 Error string `json:"error"` 29 Message string `json:"message"` 30 Level string `json:"level"` 31 UserAgent string `json:"User_Agent"` 32 } 33 34 func Test_Logger_Set(t *testing.T) { 35 a := assert.New(t) 36 37 // given: an error logger in text format 38 Set("error", true) 39 defer Set("info", false) 40 Logger.Formatter.(*logrus.TextFormatter).DisableColors = true 41 b := bytes.NewBuffer(nil) 42 Logger.Out = b 43 44 // when: I log something 45 Logger.Info("should be ignored ..") 46 Logger.WithField("foo", "bar").Error("oops") 47 48 // then: only the error text is contained 49 // and it is text formated 50 a.Regexp(`^time.* level\=error msg\=oops foo\=bar.*`, b.String()) 51 } 52 53 func Test_Logger_Set_Invalid(t *testing.T) { 54 err := Set("foo", true) 55 a := assert.New(t) 56 a.Equal(err.Error(), "not a valid logrus Level: \"foo\"") 57 } 58 59 func Test_Logger_Call(t *testing.T) { 60 a := assert.New(t) 61 62 // given a logger 63 b := bytes.NewBuffer(nil) 64 Logger.Out = b 65 AccessLogCookiesBlacklist = []string{"ignore", "user_id"} 66 UserCorrelationCookie = "user_id" 67 68 // and a request 69 r, _ := http.NewRequest("GET", "http://www.example.org/foo?q=bar", nil) 70 r.Header = http.Header{ 71 CorrelationIdHeader: {"correlation-123"}, 72 "Cookie": {"user_id=user-id-xyz; ignore=me; foo=bar;"}, 73 } 74 75 resp := &http.Response{ 76 StatusCode: 404, 77 Header: http.Header{"Content-Type": {"text/html"}}, 78 } 79 80 // when: We log a request with access 81 start := time.Now().Add(-1 * time.Second) 82 Call(r, resp, start, nil) 83 84 // then: all fields match 85 data := &logReccord{} 86 err := json.Unmarshal(b.Bytes(), data) 87 a.NoError(err) 88 89 a.Equal("warning", data.Level) 90 a.Equal("correlation-123", data.CorrelationId) 91 a.Equal("user-id-xyz", data.UserCorrelationId) 92 a.InDelta(1000, data.Duration, 0.5) 93 a.Equal("", data.Error) 94 a.Equal("www.example.org", data.Host) 95 a.Equal("GET", data.Method) 96 a.Equal("404 GET-> http://www.example.org/foo?q=bar", data.Message) 97 a.Equal(404, data.ResponseStatus) 98 a.Equal("call", data.Type) 99 a.Equal("/foo?q=bar", data.URL) 100 101 // when we call with an error 102 b.Reset() 103 start = time.Now().Add(-1 * time.Second) 104 Call(r, nil, start, errors.New("oops")) 105 106 // then: all fields match 107 data = &logReccord{} 108 err = json.Unmarshal(b.Bytes(), data) 109 a.NoError(err) 110 111 a.Equal("error", data.Level) 112 a.Equal("oops", data.Error) 113 a.Equal("oops", data.Message) 114 a.Equal("correlation-123", data.CorrelationId) 115 a.Equal("user-id-xyz", data.UserCorrelationId) 116 a.InDelta(1000, data.Duration, 0.5) 117 a.Equal("www.example.org", data.Host) 118 a.Equal("GET", data.Method) 119 a.Equal("call", data.Type) 120 a.Equal("/foo?q=bar", data.URL) 121 } 122 123 func Test_Logger_Access(t *testing.T) { 124 a := assert.New(t) 125 126 // given a logger 127 b := bytes.NewBuffer(nil) 128 Logger.Out = b 129 AccessLogCookiesBlacklist = []string{"ignore", "user_id"} 130 UserCorrelationCookie = "user_id" 131 132 // Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.84 Safari/537.36 133 134 // and a request 135 r, _ := http.NewRequest("GET", "http://www.example.org/foo?q=bar", nil) 136 r.Header = http.Header{ 137 CorrelationIdHeader: {"correlation-123"}, 138 "Cookie": {"user_id=user-id-xyz; ignore=me; foo=bar;"}, 139 "User-Agent": {"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.84 Safari/537.36"}, 140 } 141 r.RemoteAddr = "127.0.0.1" 142 143 // when: We log a request with access 144 start := time.Now().Add(-1 * time.Second) 145 Access(r, start, 201) 146 147 // then: all fields match 148 data := &logReccord{} 149 err := json.Unmarshal(b.Bytes(), data) 150 a.NoError(err) 151 152 a.Equal("info", data.Level) 153 a.Equal(map[string]string{"foo": "bar"}, data.Cookies) 154 a.Equal("correlation-123", data.CorrelationId) 155 a.InDelta(1000, data.Duration, 0.5) 156 a.Equal("", data.Error) 157 a.Equal("www.example.org", data.Host) 158 a.Equal("GET", data.Method) 159 a.Equal("HTTP/1.1", data.Proto) 160 a.Equal("201 ->GET /foo?...", data.Message) 161 a.Equal("127.0.0.1", data.RemoteIp) 162 a.Equal(201, data.ResponseStatus) 163 a.Equal("access", data.Type) 164 a.Equal("/foo?q=bar", data.URL) 165 a.Equal("user-id-xyz", data.UserCorrelationId) 166 a.Equal("Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.84 Safari/537.36", data.UserAgent) 167 } 168 169 func Test_Logger_Access_ErrorCases(t *testing.T) { 170 a := assert.New(t) 171 172 // given a logger 173 b := bytes.NewBuffer(nil) 174 Logger.Out = b 175 176 // and a request 177 r, _ := http.NewRequest("GET", "http://www.example.org/foo", nil) 178 179 // when a status 404 is logged 180 Access(r, time.Now(), 404) 181 // then: all fields match 182 data := logRecordFromBuffer(b) 183 a.Equal("warning", data.Level) 184 a.Equal("404 ->GET /foo", data.Message) 185 186 // when a status 500 is logged 187 b.Reset() 188 Access(r, time.Now(), 500) 189 // then: all fields match 190 data = logRecordFromBuffer(b) 191 a.Equal("error", data.Level) 192 193 // when an error is logged 194 b.Reset() 195 AccessError(r, time.Now(), errors.New("oops")) 196 // then: all fields match 197 data = logRecordFromBuffer(b) 198 a.Equal("error", data.Level) 199 a.Equal("oops", data.Error) 200 a.Equal("ERROR ->GET /foo", data.Message) 201 } 202 203 func Test_Logger_Application(t *testing.T) { 204 a := assert.New(t) 205 206 // given: 207 UserCorrelationCookie = "user_id" 208 header := http.Header{ 209 CorrelationIdHeader: {"correlation-123"}, 210 "Cookie": {"user_id=user-id-xyz;"}, 211 } 212 213 // when: 214 entry := Application(header) 215 216 // then: 217 a.Equal("correlation-123", entry.Data["correlation_id"]) 218 a.Equal("user-id-xyz", entry.Data["user_correlation_id"]) 219 } 220 221 func Test_Logger_LifecycleStart(t *testing.T) { 222 a := assert.New(t) 223 224 // given a logger 225 b := bytes.NewBuffer(nil) 226 Logger.Out = b 227 228 // and 229 someArguments := struct { 230 Foo string 231 Number int 232 }{ 233 Foo: "bar", 234 Number: 42, 235 } 236 237 // and an Environment Variable with the Build Number is set 238 os.Setenv("BUILD_NUMBER", "b666") 239 240 // when a LifecycleStart is logged 241 LifecycleStart("my-app", someArguments) 242 243 // then: it is logged 244 data := mapFromBuffer(b) 245 a.Equal("info", data["level"]) 246 a.Equal("lifecycle", data["type"]) 247 a.Equal("start", data["event"]) 248 a.Equal("bar", data["Foo"]) 249 a.Equal(42.0, data["Number"]) 250 a.Equal("b666", data["build_number"]) 251 } 252 253 func Test_Logger_LifecycleStop_ByInterrupt(t *testing.T) { 254 a := assert.New(t) 255 256 // given a logger 257 b := bytes.NewBuffer(nil) 258 Logger.Out = b 259 260 // and an Environment Variable with the Build Number is set 261 os.Setenv("BUILD_NUMBER", "b666") 262 263 // when a LifecycleStart is logged 264 LifecycleStop("my-app", os.Interrupt, nil) 265 266 // then: it is logged 267 data := mapFromBuffer(b) 268 a.Equal("info", data["level"]) 269 a.Equal("stopping application: my-app (interrupt)", data["message"]) 270 a.Equal("lifecycle", data["type"]) 271 a.Equal("stop", data["event"]) 272 a.Equal("interrupt", data["signal"]) 273 a.Equal("b666", data["build_number"]) 274 } 275 276 func Test_Logger_LifecycleStop_ByError(t *testing.T) { 277 a := assert.New(t) 278 279 // given a logger 280 b := bytes.NewBuffer(nil) 281 Logger.Out = b 282 283 // and an Environment Variable with the Build Number is set 284 os.Setenv("BUILD_NUMBER", "b666") 285 286 // when a LifecycleStart is logged 287 LifecycleStop("my-app", nil, errors.New("error")) 288 289 // then: it is logged 290 data := mapFromBuffer(b) 291 a.Equal("error", data["level"]) 292 a.Equal("stopping application: my-app (error)", data["message"]) 293 a.Equal("lifecycle", data["type"]) 294 a.Equal("stop", data["event"]) 295 a.Equal(nil, data["signal"]) 296 a.Equal("b666", data["build_number"]) 297 } 298 299 func Test_Logger_ServerClosed(t *testing.T) { 300 a := assert.New(t) 301 302 // given a logger 303 b := bytes.NewBuffer(nil) 304 Logger.Out = b 305 306 // and an Environment Variable with the Build Number is set 307 os.Setenv("BUILD_NUMBER", "b666") 308 309 // when a LifecycleStart is logged 310 ServerClosed("my-app") 311 312 // then: it is logged 313 data := mapFromBuffer(b) 314 a.Equal("info", data["level"]) 315 a.Equal("http server was closed: my-app", data["message"]) 316 a.Equal("application", data["type"]) 317 a.Equal("stop", data["event"]) 318 a.Equal("b666", data["build_number"]) 319 } 320 321 func Test_Logger_Cacheinfo(t *testing.T) { 322 a := assert.New(t) 323 324 // given a logger 325 Set("debug", false) 326 defer Set("info", false) 327 b := bytes.NewBuffer(nil) 328 Logger.Out = b 329 330 // when a positive cachinfo is logged 331 Cacheinfo("/foo", true) 332 333 // then: it is logged 334 data := mapFromBuffer(b) 335 a.Equal("/foo", data["url"]) 336 a.Equal("cacheinfo", data["type"]) 337 a.Equal(true, data["hit"]) 338 a.Equal("cache hit: /foo", data["message"]) 339 340 b.Reset() 341 // logging a non hit 342 Cacheinfo("/foo", false) 343 data = mapFromBuffer(b) 344 a.Equal(false, data["hit"]) 345 a.Equal("cache miss: /foo", data["message"]) 346 } 347 348 func Test_Logger_GetRemoteIp1(t *testing.T) { 349 a := assert.New(t) 350 req, _ := http.NewRequest("GET", "test.com", nil) 351 req.Header["X-Cluster-Client-Ip"] = []string{"1234"} 352 ret := getRemoteIp(req) 353 a.Equal("1234", ret) 354 } 355 356 func Test_Logger_GetRemoteIp2(t *testing.T) { 357 a := assert.New(t) 358 req, _ := http.NewRequest("GET", "test.com", nil) 359 req.Header["X-Real-Ip"] = []string{"1234"} 360 ret := getRemoteIp(req) 361 a.Equal("1234", ret) 362 } 363 364 func Test_Logger_GetRemoteIp3(t *testing.T) { 365 a := assert.New(t) 366 req, _ := http.NewRequest("GET", "test.com", nil) 367 req.RemoteAddr = "1234:80" 368 ret := getRemoteIp(req) 369 a.Equal("1234", ret) 370 } 371 372 func logRecordFromBuffer(b *bytes.Buffer) *logReccord { 373 data := &logReccord{} 374 err := json.Unmarshal(b.Bytes(), data) 375 if err != nil { 376 panic(err.Error() + " " + b.String()) 377 } 378 return data 379 } 380 381 func mapFromBuffer(b *bytes.Buffer) map[string]interface{} { 382 data := map[string]interface{}{} 383 err := json.Unmarshal(b.Bytes(), &data) 384 if err != nil { 385 panic(err.Error() + " " + b.String()) 386 } 387 return data 388 }