ntfy/log/log_test.go
2023-05-17 10:39:15 -04:00

303 lines
9.2 KiB
Go

package log
import (
"bytes"
"encoding/json"
"github.com/stretchr/testify/require"
"io"
"log"
"os"
"path/filepath"
"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())
require.False(t, IsFile())
require.Equal(t, "", File())
}
func TestLog_LevelOverride_ManyOnSameField(t *testing.T) {
t.Cleanup(resetState)
var out bytes.Buffer
SetOutput(&out)
SetFormat(JSONFormat)
SetLevelOverride("tag", "manager", DebugLevel)
SetLevelOverride("tag", "publish", DebugLevel)
Time(time.Unix(11, 0).UTC()).Field("tag", "manager").Debug("this is logged")
Time(time.Unix(12, 0).UTC()).Field("tag", "no-match").Debug("this is not logged")
Time(time.Unix(13, 0).UTC()).Field("tag", "publish").Info("this is also logged")
expected := `{"time":"1970-01-01T00:00:11Z","level":"DEBUG","message":"this is logged","tag":"manager"}
{"time":"1970-01-01T00:00:13Z","level":"INFO","message":"this is also logged","tag":"publish"}
`
require.Equal(t, expected, out.String())
require.False(t, IsFile())
require.Equal(t, "", File())
}
func TestLog_FieldIf(t *testing.T) {
t.Cleanup(resetState)
var out bytes.Buffer
SetOutput(&out)
SetLevel(DebugLevel)
SetFormat(JSONFormat)
Time(time.Unix(11, 0).UTC()).
FieldIf("trace_field", "manager", TraceLevel). // This is not logged
Field("tag", "manager").
Debug("trace_field is not logged")
SetLevel(TraceLevel)
Time(time.Unix(12, 0).UTC()).
FieldIf("trace_field", "manager", TraceLevel). // Now it is logged
Field("tag", "manager").
Debug("trace_field is logged")
expected := `{"time":"1970-01-01T00:00:11Z","level":"DEBUG","message":"trace_field is not logged","tag":"manager"}
{"time":"1970-01-01T00:00:12Z","level":"DEBUG","message":"trace_field is logged","tag":"manager","trace_field":"manager"}
`
require.Equal(t, expected, out.String())
}
func TestLog_UsingStdLogger_JSON(t *testing.T) {
t.Cleanup(resetState)
var out bytes.Buffer
SetOutput(&out)
SetFormat(JSONFormat)
log.Println("Some other library is using the standard Go logger")
require.Contains(t, out.String(), `,"level":"INFO","message":"Some other library is using the standard Go logger","tag":"stdlog"}`+"\n")
}
func TestLog_UsingStdLogger_Text(t *testing.T) {
t.Cleanup(resetState)
var out bytes.Buffer
SetOutput(&out)
log.Println("Some other library is using the standard Go logger")
require.Contains(t, out.String(), `Some other library is using the standard Go logger`+"\n")
require.NotContains(t, out.String(), `{`)
}
func TestLog_File(t *testing.T) {
t.Cleanup(resetState)
logfile := filepath.Join(t.TempDir(), "ntfy.log")
f, err := os.OpenFile(logfile, os.O_CREATE|os.O_WRONLY, 0600)
require.Nil(t, err)
SetOutput(f)
SetFormat(JSONFormat)
require.True(t, IsFile())
require.Equal(t, logfile, File())
Time(time.Unix(11, 0).UTC()).Field("this_one", "11").Info("this is logged")
require.Nil(t, f.Close())
f, err = os.Open(logfile)
require.Nil(t, err)
contents, err := io.ReadAll(f)
require.Nil(t, err)
require.Equal(t, `{"time":"1970-01-01T00:00:11Z","level":"INFO","message":"this is logged","this_one":"11"}`+"\n", string(contents))
}
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()
}