loginsrv

Unnamed repository; edit this file 'description' to name the repository.
git clone git@jamesshield.xyz:repos/loginsrv.git
Log | Files | Refs | README | LICENSE

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 }