210 lines
6.3 KiB
Go
210 lines
6.3 KiB
Go
package log
|
|
|
|
import (
|
|
"bytes"
|
|
"encoding/json"
|
|
"github.com/stretchr/testify/require"
|
|
"os"
|
|
"testing"
|
|
"time"
|
|
)
|
|
|
|
func TestMain(m *testing.M) {
|
|
exitCode := m.Run()
|
|
resetState()
|
|
SetLevel(ErrorLevel) // For other modules!
|
|
os.Exit(exitCode)
|
|
}
|
|
|
|
func TestLog_TagContextFieldFields(t *testing.T) {
|
|
t.Cleanup(resetState)
|
|
v := &fakeVisitor{
|
|
UserID: "u_abc",
|
|
IP: "1.2.3.4",
|
|
}
|
|
err := &fakeError{
|
|
Code: 123,
|
|
Message: "some error",
|
|
}
|
|
var out bytes.Buffer
|
|
SetOutput(&out)
|
|
SetFormat(JSONFormat)
|
|
SetLevelOverride("tag", "stripe", DebugLevel)
|
|
SetLevelOverride("number", "5", DebugLevel)
|
|
|
|
Tag("mytag").
|
|
Field("field2", 123).
|
|
Field("field1", "value1").
|
|
Time(time.Unix(123, 999000000).UTC()).
|
|
Info("hi there %s", "phil")
|
|
|
|
Tag("not-stripe").
|
|
Debug("this message will not appear")
|
|
|
|
With(v).
|
|
Fields(Context{
|
|
"stripe_customer_id": "acct_123",
|
|
"stripe_subscription_id": "sub_123",
|
|
}).
|
|
Tag("stripe").
|
|
Err(err).
|
|
Time(time.Unix(456, 123000000).UTC()).
|
|
Debug("Subscription status %s", "active")
|
|
|
|
Field("number", 5).
|
|
Time(time.Unix(777, 001000000).UTC()).
|
|
Debug("The number 5 is an int, but the level override is a string")
|
|
|
|
expected := `{"time":"1970-01-01T00:02:03.999Z","level":"INFO","message":"hi there phil","field1":"value1","field2":123,"tag":"mytag"}
|
|
{"time":"1970-01-01T00:07:36.123Z","level":"DEBUG","message":"Subscription status active","error":"some error","error_code":123,"stripe_customer_id":"acct_123","stripe_subscription_id":"sub_123","tag":"stripe","user_id":"u_abc","visitor_ip":"1.2.3.4"}
|
|
{"time":"1970-01-01T00:12:57Z","level":"DEBUG","message":"The number 5 is an int, but the level override is a string","number":5}
|
|
`
|
|
require.Equal(t, expected, out.String())
|
|
}
|
|
|
|
func TestLog_NoAllocIfNotPrinted(t *testing.T) {
|
|
t.Cleanup(resetState)
|
|
v := &fakeVisitor{
|
|
UserID: "u_abc",
|
|
IP: "1.2.3.4",
|
|
}
|
|
|
|
var out bytes.Buffer
|
|
SetOutput(&out)
|
|
SetFormat(JSONFormat)
|
|
|
|
// Do not log, do not call contexters (because global level is INFO)
|
|
v.contextCalled = false
|
|
ev := With(v)
|
|
ev.Debug("some message")
|
|
require.False(t, v.contextCalled)
|
|
require.Equal(t, "", ev.Timestamp)
|
|
require.Equal(t, Level(0), ev.Level)
|
|
require.Equal(t, "", ev.Message)
|
|
require.Nil(t, ev.fields)
|
|
|
|
// Logged because info level, contexters called
|
|
v.contextCalled = false
|
|
ev = With(v).Time(time.Unix(1111, 0).UTC())
|
|
ev.Info("some message")
|
|
require.True(t, v.contextCalled)
|
|
require.NotNil(t, ev.fields)
|
|
require.Equal(t, "1.2.3.4", ev.fields["visitor_ip"])
|
|
|
|
// Not logged, but contexters called, because overrides exist
|
|
SetLevel(DebugLevel)
|
|
SetLevelOverride("tag", "overridetag", TraceLevel)
|
|
v.contextCalled = false
|
|
ev = Tag("sometag").Field("field", "value").With(v).Time(time.Unix(123, 0).UTC())
|
|
ev.Trace("some debug message")
|
|
require.True(t, v.contextCalled) // If there are overrides, we must call the context to determine the filter fields
|
|
require.Equal(t, "", ev.Timestamp)
|
|
require.Equal(t, Level(0), ev.Level)
|
|
require.Equal(t, "", ev.Message)
|
|
require.Equal(t, 4, len(ev.fields))
|
|
require.Equal(t, "value", ev.fields["field"])
|
|
require.Equal(t, "sometag", ev.fields["tag"])
|
|
|
|
// Logged because of override tag, and contexters called
|
|
v.contextCalled = false
|
|
ev = Tag("overridetag").Field("field", "value").With(v).Time(time.Unix(123, 0).UTC())
|
|
ev.Trace("some trace message")
|
|
require.True(t, v.contextCalled)
|
|
require.Equal(t, "1970-01-01T00:02:03Z", ev.Timestamp)
|
|
require.Equal(t, TraceLevel, ev.Level)
|
|
require.Equal(t, "some trace message", ev.Message)
|
|
|
|
// Logged because of field override, and contexters called
|
|
ResetLevelOverrides()
|
|
SetLevelOverride("visitor_ip", "1.2.3.4", TraceLevel)
|
|
v.contextCalled = false
|
|
ev = With(v).Time(time.Unix(124, 0).UTC())
|
|
ev.Trace("some trace message with override")
|
|
require.True(t, v.contextCalled)
|
|
require.Equal(t, "1970-01-01T00:02:04Z", ev.Timestamp)
|
|
require.Equal(t, TraceLevel, ev.Level)
|
|
require.Equal(t, "some trace message with override", ev.Message)
|
|
|
|
expected := `{"time":"1970-01-01T00:18:31Z","level":"INFO","message":"some message","user_id":"u_abc","visitor_ip":"1.2.3.4"}
|
|
{"time":"1970-01-01T00:02:03Z","level":"TRACE","message":"some trace message","field":"value","tag":"overridetag","user_id":"u_abc","visitor_ip":"1.2.3.4"}
|
|
{"time":"1970-01-01T00:02:04Z","level":"TRACE","message":"some trace message with override","user_id":"u_abc","visitor_ip":"1.2.3.4"}
|
|
`
|
|
require.Equal(t, expected, out.String())
|
|
}
|
|
|
|
func TestLog_Timing(t *testing.T) {
|
|
t.Cleanup(resetState)
|
|
|
|
var out bytes.Buffer
|
|
SetOutput(&out)
|
|
SetFormat(JSONFormat)
|
|
|
|
Timing(func() { time.Sleep(300 * time.Millisecond) }).
|
|
Time(time.Unix(12, 0).UTC()).
|
|
Info("A thing that takes a while")
|
|
|
|
var ev struct {
|
|
TimeTakenMs int64 `json:"time_taken_ms"`
|
|
}
|
|
require.Nil(t, json.Unmarshal(out.Bytes(), &ev))
|
|
require.True(t, ev.TimeTakenMs >= 300)
|
|
require.Contains(t, out.String(), `{"time":"1970-01-01T00:00:12Z","level":"INFO","message":"A thing that takes a while","time_taken_ms":`)
|
|
}
|
|
|
|
func TestLog_LevelOverrideAny(t *testing.T) {
|
|
t.Cleanup(resetState)
|
|
|
|
var out bytes.Buffer
|
|
SetOutput(&out)
|
|
SetFormat(JSONFormat)
|
|
SetLevelOverride("this_one", "", DebugLevel)
|
|
SetLevelOverride("time_taken_ms", "", TraceLevel)
|
|
|
|
Time(time.Unix(11, 0).UTC()).Field("this_one", "11").Debug("this is logged")
|
|
Time(time.Unix(12, 0).UTC()).Field("not_this", "11").Debug("this is not logged")
|
|
Time(time.Unix(13, 0).UTC()).Field("this_too", "11").Info("this is also logged")
|
|
Time(time.Unix(14, 0).UTC()).Field("time_taken_ms", 0).Info("this is also logged")
|
|
|
|
expected := `{"time":"1970-01-01T00:00:11Z","level":"DEBUG","message":"this is logged","this_one":"11"}
|
|
{"time":"1970-01-01T00:00:13Z","level":"INFO","message":"this is also logged","this_too":"11"}
|
|
{"time":"1970-01-01T00:00:14Z","level":"INFO","message":"this is also logged","time_taken_ms":0}
|
|
`
|
|
require.Equal(t, expected, out.String())
|
|
}
|
|
|
|
type fakeError struct {
|
|
Code int
|
|
Message string
|
|
}
|
|
|
|
func (e fakeError) Error() string {
|
|
return e.Message
|
|
}
|
|
|
|
func (e fakeError) Context() Context {
|
|
return Context{
|
|
"error": e.Message,
|
|
"error_code": e.Code,
|
|
}
|
|
}
|
|
|
|
type fakeVisitor struct {
|
|
UserID string
|
|
IP string
|
|
contextCalled bool
|
|
}
|
|
|
|
func (v *fakeVisitor) Context() Context {
|
|
v.contextCalled = true
|
|
return Context{
|
|
"user_id": v.UserID,
|
|
"visitor_ip": v.IP,
|
|
}
|
|
}
|
|
|
|
func resetState() {
|
|
SetLevel(DefaultLevel)
|
|
SetFormat(DefaultFormat)
|
|
SetOutput(DefaultOutput)
|
|
ResetLevelOverrides()
|
|
}
|