567 lines
12 KiB
Go
567 lines
12 KiB
Go
package log15
|
|
|
|
import (
|
|
"bufio"
|
|
"bytes"
|
|
"encoding/json"
|
|
"errors"
|
|
"fmt"
|
|
"net"
|
|
"regexp"
|
|
"runtime"
|
|
"sync"
|
|
"testing"
|
|
"time"
|
|
)
|
|
|
|
func testHandler() (Handler, *Record) {
|
|
rec := new(Record)
|
|
return FuncHandler(func(r *Record) error {
|
|
*rec = *r
|
|
return nil
|
|
}), rec
|
|
}
|
|
|
|
func testLogger() (Logger, Handler, *Record) {
|
|
l := New()
|
|
h, r := testHandler()
|
|
l.SetHandler(LazyHandler(h))
|
|
return l, h, r
|
|
}
|
|
|
|
func TestLazy(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
x := 1
|
|
lazy := func() int {
|
|
return x
|
|
}
|
|
|
|
l, _, r := testLogger()
|
|
l.Info("", "x", Lazy{lazy})
|
|
if r.Ctx[1] != 1 {
|
|
t.Fatalf("Lazy function not evaluated, got %v, expected %d", r.Ctx[1], 1)
|
|
}
|
|
|
|
x = 2
|
|
l.Info("", "x", Lazy{lazy})
|
|
if r.Ctx[1] != 2 {
|
|
t.Fatalf("Lazy function not evaluated, got %v, expected %d", r.Ctx[1], 1)
|
|
}
|
|
}
|
|
|
|
func TestInvalidLazy(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l, _, r := testLogger()
|
|
validate := func() {
|
|
if len(r.Ctx) < 4 {
|
|
t.Fatalf("Invalid lazy, got %d args, expecting at least 4", len(r.Ctx))
|
|
}
|
|
|
|
if r.Ctx[2] != errorKey {
|
|
t.Fatalf("Invalid lazy, got key %s expecting %s", r.Ctx[2], errorKey)
|
|
}
|
|
}
|
|
|
|
l.Info("", "x", Lazy{1})
|
|
validate()
|
|
|
|
l.Info("", "x", Lazy{func(x int) int { return x }})
|
|
validate()
|
|
|
|
l.Info("", "x", Lazy{func() {}})
|
|
validate()
|
|
}
|
|
|
|
func TestCtx(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l, _, r := testLogger()
|
|
l.Info("", Ctx{"x": 1, "y": "foo", "tester": t})
|
|
if len(r.Ctx) != 6 {
|
|
t.Fatalf("Expecting Ctx tansformed into %d ctx args, got %d: %v", 6, len(r.Ctx), r.Ctx)
|
|
}
|
|
}
|
|
|
|
func testFormatter(f Format) (Logger, *bytes.Buffer) {
|
|
l := New()
|
|
var buf bytes.Buffer
|
|
l.SetHandler(StreamHandler(&buf, f))
|
|
return l, &buf
|
|
}
|
|
|
|
func TestJson(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l, buf := testFormatter(JsonFormat())
|
|
l.Error("some message", "x", 1, "y", 3.2)
|
|
|
|
var v map[string]interface{}
|
|
decoder := json.NewDecoder(buf)
|
|
if err := decoder.Decode(&v); err != nil {
|
|
t.Fatalf("Error decoding JSON: %v", v)
|
|
}
|
|
|
|
validate := func(key string, expected interface{}) {
|
|
if v[key] != expected {
|
|
t.Fatalf("Got %v expected %v for %v", v[key], expected, key)
|
|
}
|
|
}
|
|
|
|
validate("msg", "some message")
|
|
validate("x", float64(1)) // all numbers are floats in JSON land
|
|
validate("y", 3.2)
|
|
}
|
|
|
|
type testtype struct {
|
|
name string
|
|
}
|
|
|
|
func (tt testtype) String() string {
|
|
return tt.name
|
|
}
|
|
|
|
func TestLogfmt(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
var nilVal *testtype
|
|
|
|
l, buf := testFormatter(LogfmtFormat())
|
|
l.Error("some message", "x", 1, "y", 3.2, "equals", "=", "quote", "\"", "nil", nilVal)
|
|
|
|
// skip timestamp in comparison
|
|
got := buf.Bytes()[27:buf.Len()]
|
|
expected := []byte(`lvl=eror msg="some message" x=1 y=3.200 equals="=" quote="\"" nil=nil` + "\n")
|
|
if !bytes.Equal(got, expected) {
|
|
t.Fatalf("Got %s, expected %s", got, expected)
|
|
}
|
|
}
|
|
|
|
func TestMultiHandler(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
h1, r1 := testHandler()
|
|
h2, r2 := testHandler()
|
|
l := New()
|
|
l.SetHandler(MultiHandler(h1, h2))
|
|
l.Debug("clone")
|
|
|
|
if r1.Msg != "clone" {
|
|
t.Fatalf("wrong value for h1.Msg. Got %s expected %s", r1.Msg, "clone")
|
|
}
|
|
|
|
if r2.Msg != "clone" {
|
|
t.Fatalf("wrong value for h2.Msg. Got %s expected %s", r2.Msg, "clone")
|
|
}
|
|
|
|
}
|
|
|
|
type waitHandler struct {
|
|
ch chan Record
|
|
}
|
|
|
|
func (h *waitHandler) Log(r *Record) error {
|
|
h.ch <- *r
|
|
return nil
|
|
}
|
|
|
|
func TestBufferedHandler(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
ch := make(chan Record)
|
|
l := New()
|
|
l.SetHandler(BufferedHandler(0, &waitHandler{ch}))
|
|
|
|
l.Debug("buffer")
|
|
if r := <-ch; r.Msg != "buffer" {
|
|
t.Fatalf("wrong value for r.Msg. Got %s expected %s", r.Msg, "")
|
|
}
|
|
}
|
|
|
|
func TestLogContext(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l, _, r := testLogger()
|
|
l = l.New("foo", "bar")
|
|
l.Crit("baz")
|
|
|
|
if len(r.Ctx) != 2 {
|
|
t.Fatalf("Expected logger context in record context. Got length %d, expected %d", len(r.Ctx), 2)
|
|
}
|
|
|
|
if r.Ctx[0] != "foo" {
|
|
t.Fatalf("Wrong context key, got %s expected %s", r.Ctx[0], "foo")
|
|
}
|
|
|
|
if r.Ctx[1] != "bar" {
|
|
t.Fatalf("Wrong context value, got %s expected %s", r.Ctx[1], "bar")
|
|
}
|
|
}
|
|
|
|
func TestMapCtx(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l, _, r := testLogger()
|
|
l.Crit("test", Ctx{"foo": "bar"})
|
|
|
|
if len(r.Ctx) != 2 {
|
|
t.Fatalf("Wrong context length, got %d, expected %d", len(r.Ctx), 2)
|
|
}
|
|
|
|
if r.Ctx[0] != "foo" {
|
|
t.Fatalf("Wrong context key, got %s expected %s", r.Ctx[0], "foo")
|
|
}
|
|
|
|
if r.Ctx[1] != "bar" {
|
|
t.Fatalf("Wrong context value, got %s expected %s", r.Ctx[1], "bar")
|
|
}
|
|
}
|
|
|
|
func TestLvlFilterHandler(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l := New()
|
|
h, r := testHandler()
|
|
l.SetHandler(LvlFilterHandler(LvlWarn, h))
|
|
l.Info("info'd")
|
|
|
|
if r.Msg != "" {
|
|
t.Fatalf("Expected zero record, but got record with msg: %v", r.Msg)
|
|
}
|
|
|
|
l.Warn("warned")
|
|
if r.Msg != "warned" {
|
|
t.Fatalf("Got record msg %s expected %s", r.Msg, "warned")
|
|
}
|
|
|
|
l.Warn("error'd")
|
|
if r.Msg != "error'd" {
|
|
t.Fatalf("Got record msg %s expected %s", r.Msg, "error'd")
|
|
}
|
|
}
|
|
|
|
func TestNetHandler(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l, err := net.Listen("tcp", "localhost:0")
|
|
if err != nil {
|
|
t.Fatalf("Failed to listen: %v", l)
|
|
}
|
|
|
|
errs := make(chan error)
|
|
go func() {
|
|
c, err := l.Accept()
|
|
if err != nil {
|
|
t.Errorf("Failed to accept conneciton: %v", err)
|
|
return
|
|
}
|
|
|
|
rd := bufio.NewReader(c)
|
|
s, err := rd.ReadString('\n')
|
|
if err != nil {
|
|
t.Errorf("Failed to read string: %v", err)
|
|
}
|
|
|
|
got := s[27:]
|
|
expected := "lvl=info msg=test x=1\n"
|
|
if got != expected {
|
|
t.Errorf("Got log line %s, expected %s", got, expected)
|
|
}
|
|
|
|
errs <- nil
|
|
}()
|
|
|
|
lg := New()
|
|
h, err := NetHandler("tcp", l.Addr().String(), LogfmtFormat())
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
lg.SetHandler(h)
|
|
lg.Info("test", "x", 1)
|
|
|
|
select {
|
|
case <-time.After(time.Second):
|
|
t.Fatalf("Test timed out!")
|
|
case <-errs:
|
|
// ok
|
|
}
|
|
}
|
|
|
|
func TestMatchFilterHandler(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l, h, r := testLogger()
|
|
l.SetHandler(MatchFilterHandler("err", nil, h))
|
|
|
|
l.Crit("test", "foo", "bar")
|
|
if r.Msg != "" {
|
|
t.Fatalf("expected filter handler to discard msg")
|
|
}
|
|
|
|
l.Crit("test2", "err", "bad fd")
|
|
if r.Msg != "" {
|
|
t.Fatalf("expected filter handler to discard msg")
|
|
}
|
|
|
|
l.Crit("test3", "err", nil)
|
|
if r.Msg != "test3" {
|
|
t.Fatalf("expected filter handler to allow msg")
|
|
}
|
|
}
|
|
|
|
func TestMatchFilterBuiltin(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l, h, r := testLogger()
|
|
l.SetHandler(MatchFilterHandler("lvl", LvlError, h))
|
|
l.Info("does not pass")
|
|
|
|
if r.Msg != "" {
|
|
t.Fatalf("got info level record that should not have matched")
|
|
}
|
|
|
|
l.Error("error!")
|
|
if r.Msg != "error!" {
|
|
t.Fatalf("did not get error level record that should have matched")
|
|
}
|
|
|
|
r.Msg = ""
|
|
l.SetHandler(MatchFilterHandler("msg", "matching message", h))
|
|
l.Info("doesn't match")
|
|
if r.Msg != "" {
|
|
t.Fatalf("got record with wrong message matched")
|
|
}
|
|
|
|
l.Debug("matching message")
|
|
if r.Msg != "matching message" {
|
|
t.Fatalf("did not get record which matches")
|
|
}
|
|
}
|
|
|
|
type failingWriter struct {
|
|
fail bool
|
|
}
|
|
|
|
func (w *failingWriter) Write(buf []byte) (int, error) {
|
|
if w.fail {
|
|
return 0, errors.New("fail")
|
|
} else {
|
|
return len(buf), nil
|
|
}
|
|
}
|
|
|
|
func TestFailoverHandler(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l := New()
|
|
h, r := testHandler()
|
|
w := &failingWriter{false}
|
|
|
|
l.SetHandler(FailoverHandler(
|
|
StreamHandler(w, JsonFormat()),
|
|
h))
|
|
|
|
l.Debug("test ok")
|
|
if r.Msg != "" {
|
|
t.Fatalf("expected no failover")
|
|
}
|
|
|
|
w.fail = true
|
|
l.Debug("test failover", "x", 1)
|
|
if r.Msg != "test failover" {
|
|
t.Fatalf("expected failover")
|
|
}
|
|
|
|
if len(r.Ctx) != 4 {
|
|
t.Fatalf("expected additional failover ctx")
|
|
}
|
|
|
|
got := r.Ctx[2]
|
|
expected := "failover_err_0"
|
|
if got != expected {
|
|
t.Fatalf("expected failover ctx. got: %s, expected %s", got, expected)
|
|
}
|
|
}
|
|
|
|
// https://github.com/inconshreveable/log15/issues/16
|
|
func TestIndependentSetHandler(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
parent, _, r := testLogger()
|
|
child := parent.New()
|
|
child.SetHandler(DiscardHandler())
|
|
parent.Info("test")
|
|
if r.Msg != "test" {
|
|
t.Fatalf("parent handler affected by child")
|
|
}
|
|
}
|
|
|
|
// https://github.com/inconshreveable/log15/issues/16
|
|
func TestInheritHandler(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
parent, _, r := testLogger()
|
|
child := parent.New()
|
|
parent.SetHandler(DiscardHandler())
|
|
child.Info("test")
|
|
if r.Msg == "test" {
|
|
t.Fatalf("child handler affected not affected by parent")
|
|
}
|
|
}
|
|
|
|
func TestCallerFileHandler(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l := New()
|
|
h, r := testHandler()
|
|
l.SetHandler(CallerFileHandler(h))
|
|
|
|
l.Info("baz")
|
|
_, _, line, _ := runtime.Caller(0)
|
|
|
|
if len(r.Ctx) != 2 {
|
|
t.Fatalf("Expected caller in record context. Got length %d, expected %d", len(r.Ctx), 2)
|
|
}
|
|
|
|
const key = "caller"
|
|
|
|
if r.Ctx[0] != key {
|
|
t.Fatalf("Wrong context key, got %s expected %s", r.Ctx[0], key)
|
|
}
|
|
|
|
s, ok := r.Ctx[1].(string)
|
|
if !ok {
|
|
t.Fatalf("Wrong context value type, got %T expected string", r.Ctx[1])
|
|
}
|
|
|
|
exp := fmt.Sprint("log15_test.go:", line-1)
|
|
if s != exp {
|
|
t.Fatalf("Wrong context value, got %s expected string matching %s", s, exp)
|
|
}
|
|
}
|
|
|
|
func TestCallerFuncHandler(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l := New()
|
|
h, r := testHandler()
|
|
l.SetHandler(CallerFuncHandler(h))
|
|
|
|
l.Info("baz")
|
|
|
|
if len(r.Ctx) != 2 {
|
|
t.Fatalf("Expected caller in record context. Got length %d, expected %d", len(r.Ctx), 2)
|
|
}
|
|
|
|
const key = "fn"
|
|
|
|
if r.Ctx[0] != key {
|
|
t.Fatalf("Wrong context key, got %s expected %s", r.Ctx[0], key)
|
|
}
|
|
|
|
const regex = ".*\\.TestCallerFuncHandler"
|
|
|
|
s, ok := r.Ctx[1].(string)
|
|
if !ok {
|
|
t.Fatalf("Wrong context value type, got %T expected string", r.Ctx[1])
|
|
}
|
|
|
|
match, err := regexp.MatchString(regex, s)
|
|
if err != nil {
|
|
t.Fatalf("Error matching %s to regex %s: %v", s, regex, err)
|
|
}
|
|
|
|
if !match {
|
|
t.Fatalf("Wrong context value, got %s expected string matching %s", s, regex)
|
|
}
|
|
}
|
|
|
|
// https://github.com/inconshreveable/log15/issues/27
|
|
func TestCallerStackHandler(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
l := New()
|
|
h, r := testHandler()
|
|
l.SetHandler(CallerStackHandler("%#v", h))
|
|
|
|
lines := []int{}
|
|
|
|
func() {
|
|
l.Info("baz")
|
|
_, _, line, _ := runtime.Caller(0)
|
|
lines = append(lines, line-1)
|
|
}()
|
|
_, file, line, _ := runtime.Caller(0)
|
|
lines = append(lines, line-1)
|
|
|
|
if len(r.Ctx) != 2 {
|
|
t.Fatalf("Expected stack in record context. Got length %d, expected %d", len(r.Ctx), 2)
|
|
}
|
|
|
|
const key = "stack"
|
|
|
|
if r.Ctx[0] != key {
|
|
t.Fatalf("Wrong context key, got %s expected %s", r.Ctx[0], key)
|
|
}
|
|
|
|
s, ok := r.Ctx[1].(string)
|
|
if !ok {
|
|
t.Fatalf("Wrong context value type, got %T expected string", r.Ctx[1])
|
|
}
|
|
|
|
exp := "["
|
|
for i, line := range lines {
|
|
if i > 0 {
|
|
exp += " "
|
|
}
|
|
exp += fmt.Sprint(file, ":", line)
|
|
}
|
|
exp += "]"
|
|
|
|
if s != exp {
|
|
t.Fatalf("Wrong context value, got %s expected string matching %s", s, exp)
|
|
}
|
|
}
|
|
|
|
// tests that when logging concurrently to the same logger
|
|
// from multiple goroutines that the calls are handled independently
|
|
// this test tries to trigger a previous bug where concurrent calls could
|
|
// corrupt each other's context values
|
|
//
|
|
// this test runs N concurrent goroutines each logging a fixed number of
|
|
// records and a handler that buckets them based on the index passed in the context.
|
|
// if the logger is not concurrent-safe then the values in the buckets will not all be the same
|
|
//
|
|
// https://github.com/inconshreveable/log15/pull/30
|
|
func TestConcurrent(t *testing.T) {
|
|
root := New()
|
|
// this was the first value that triggered
|
|
// go to allocate extra capacity in the logger's context slice which
|
|
// was necessary to trigger the bug
|
|
const ctxLen = 34
|
|
l := root.New(make([]interface{}, ctxLen)...)
|
|
const goroutines = 8
|
|
var res [goroutines]int
|
|
l.SetHandler(SyncHandler(FuncHandler(func(r *Record) error {
|
|
res[r.Ctx[ctxLen+1].(int)]++
|
|
return nil
|
|
})))
|
|
var wg sync.WaitGroup
|
|
wg.Add(goroutines)
|
|
for i := 0; i < goroutines; i++ {
|
|
go func(idx int) {
|
|
defer wg.Done()
|
|
for j := 0; j < 10000; j++ {
|
|
l.Info("test message", "goroutine_idx", idx)
|
|
}
|
|
}(i)
|
|
}
|
|
wg.Wait()
|
|
for _, val := range res[:] {
|
|
if val != 10000 {
|
|
t.Fatalf("Wrong number of messages for context: %+v", res)
|
|
}
|
|
}
|
|
}
|