Changing up the flow of the logging system, starting to move the tests

into their own directory for organization.

tests/example_test.go

@@ -0,0 +1,40 @@
+package logger
+
+import "os"
+
+func Example() {
+	// This call is for testing purposes and will set the time to unix epoch.
+	InitForTesting(DEBUG)
+
+	var log = MustGetLogger("example")
+
+	// For demo purposes, create two backend for os.Stdout.
+	//
+	// os.Stderr should most likely be used in the real world but then the
+	// "Output:" check in this example would not work.
+	backend1 := NewLogBackend(os.Stdout, "", 0)
+	backend2 := NewLogBackend(os.Stdout, "", 0)
+
+	// For messages written to backend2 we want to add some additional
+	// information to the output, including the used log level and the name of
+	// the function.
+	var format = MustStringFormatter(
+		`%{time:15:04:05.000} %{shortfunc} %{level:.1s} %{message}`,
+	)
+	backend2Formatter := NewBackendFormatter(backend2, format)
+
+	// Only errors and more severe messages should be sent to backend2
+	backend2Leveled := AddModuleLevel(backend2Formatter)
+	backend2Leveled.SetLevel(ERROR, "")
+
+	// Set the backends to be used and the default level.
+	SetBackend(backend1, backend2Leveled)
+
+	log.Debugf("debug %s", "arg")
+	log.Error("error")
+
+	// Output:
+	// debug arg
+	// error
+	// 00:00:00.000 Example E error
+}

tests/format_test.go

@@ -0,0 +1,184 @@
+// Copyright 2013, Örjan Persson. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package logger
+
+import (
+	"bytes"
+	"testing"
+)
+
+func TestFormat(t *testing.T) {
+	backend := InitForTesting(DEBUG)
+
+	f, err := NewStringFormatter("%{shortfile} %{time:2006-01-02T15:04:05} %{level:.1s} %{id:04d} %{module} %{message}")
+	if err != nil {
+		t.Fatalf("failed to set format: %s", err)
+	}
+	SetFormatter(f)
+
+	log := MustGetLogger("module")
+	log.Debug("hello")
+
+	line := MemoryRecordN(backend, 0).Formatted(0)
+	if "format_test.go:24 1970-01-01T00:00:00 D 0001 module hello" != line {
+		t.Errorf("Unexpected format: %s", line)
+	}
+}
+
+func logAndGetLine(backend *MemoryBackend) string {
+	MustGetLogger("foo").Debug("hello")
+	return MemoryRecordN(backend, 0).Formatted(1)
+}
+
+func getLastLine(backend *MemoryBackend) string {
+	return MemoryRecordN(backend, 0).Formatted(1)
+}
+
+func realFunc(backend *MemoryBackend) string {
+	return logAndGetLine(backend)
+}
+
+type structFunc struct{}
+
+func (structFunc) Log(backend *MemoryBackend) string {
+	return logAndGetLine(backend)
+}
+
+func TestRealFuncFormat(t *testing.T) {
+	backend := InitForTesting(DEBUG)
+	SetFormatter(MustStringFormatter("%{shortfunc}"))
+
+	line := realFunc(backend)
+	if "realFunc" != line {
+		t.Errorf("Unexpected format: %s", line)
+	}
+}
+
+func TestStructFuncFormat(t *testing.T) {
+	backend := InitForTesting(DEBUG)
+	SetFormatter(MustStringFormatter("%{longfunc}"))
+
+	var x structFunc
+	line := x.Log(backend)
+	if "structFunc.Log" != line {
+		t.Errorf("Unexpected format: %s", line)
+	}
+}
+
+func TestVarFuncFormat(t *testing.T) {
+	backend := InitForTesting(DEBUG)
+	SetFormatter(MustStringFormatter("%{shortfunc}"))
+
+	var varFunc = func() string {
+		return logAndGetLine(backend)
+	}
+
+	line := varFunc()
+	if "???" == line || "TestVarFuncFormat" == line || "varFunc" == line {
+		t.Errorf("Unexpected format: %s", line)
+	}
+}
+
+func TestFormatFuncName(t *testing.T) {
+	var tests = []struct {
+		filename  string
+		longpkg   string
+		shortpkg  string
+		longfunc  string
+		shortfunc string
+	}{
+		{"",
+			"???",
+			"???",
+			"???",
+			"???"},
+		{"main",
+			"???",
+			"???",
+			"???",
+			"???"},
+		{"main.",
+			"main",
+			"main",
+			"",
+			""},
+		{"main.main",
+			"main",
+			"main",
+			"main",
+			"main"},
+		{"mimirtech.net/gitea/GoUtilities/logger.func·001",
+			"mimirtech.net/gitea/GoUtilities/logger",
+			"logger",
+			"func·001",
+			"func·001"},
+		{"mimirtech.net/gitea/GoUtilities/logger.stringFormatter.Format",
+			"mimirtech.net/gitea/GoUtilities/logger",
+			"logger",
+			"stringFormatter.Format",
+			"Format"},
+	}
+
+	var v string
+	for _, test := range tests {
+		v = formatFuncName(fmtVerbLongpkg, test.filename)
+		if test.longpkg != v {
+			t.Errorf("%s != %s", test.longpkg, v)
+		}
+		v = formatFuncName(fmtVerbShortpkg, test.filename)
+		if test.shortpkg != v {
+			t.Errorf("%s != %s", test.shortpkg, v)
+		}
+		v = formatFuncName(fmtVerbLongfunc, test.filename)
+		if test.longfunc != v {
+			t.Errorf("%s != %s", test.longfunc, v)
+		}
+		v = formatFuncName(fmtVerbShortfunc, test.filename)
+		if test.shortfunc != v {
+			t.Errorf("%s != %s", test.shortfunc, v)
+		}
+	}
+}
+
+func TestBackendFormatter(t *testing.T) {
+	InitForTesting(DEBUG)
+
+	// Create two backends and wrap one of the with a backend formatter
+	b1 := NewMemoryBackend(1)
+	b2 := NewMemoryBackend(1)
+
+	f := MustStringFormatter("%{level} %{message}")
+	bf := NewBackendFormatter(b2, f)
+
+	SetBackend(b1, bf)
+
+	log := MustGetLogger("module")
+	log.Info("foo")
+	if "foo" != getLastLine(b1) {
+		t.Errorf("Unexpected line: %s", getLastLine(b1))
+	}
+	if "INFO foo" != getLastLine(b2) {
+		t.Errorf("Unexpected line: %s", getLastLine(b2))
+	}
+}
+
+func BenchmarkStringFormatter(b *testing.B) {
+	fmt := "%{time:2006-01-02T15:04:05} %{level:.1s} %{id:04d} %{module} %{message}"
+	f := MustStringFormatter(fmt)
+
+	backend := InitForTesting(DEBUG)
+	buf := &bytes.Buffer{}
+	log := MustGetLogger("module")
+	log.Debug("")
+	record := MemoryRecordN(backend, 0)
+
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		if err := f.Format(1, record, buf); err != nil {
+			b.Fatal(err)
+			buf.Truncate(0)
+		}
+	}
+}

tests/level_test.go

@@ -0,0 +1,76 @@
+// Copyright 2013, Örjan Persson. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package logger
+
+import "testing"
+
+func TestLevelString(t *testing.T) {
+	// Make sure all levels can be converted from string -> constant -> string
+	for _, name := range levelNames {
+		level, err := LogLevel(name)
+		if err != nil {
+			t.Errorf("failed to get level: %v", err)
+			continue
+		}
+
+		if level.String() != name {
+			t.Errorf("invalid level conversion: %v != %v", level, name)
+		}
+	}
+}
+
+func TestLevelLogLevel(t *testing.T) {
+	tests := []struct {
+		expected Level
+		level    string
+	}{
+		{-1, "bla"},
+		{INFO, "iNfO"},
+		{ERROR, "error"},
+		{WARNING, "warninG"},
+	}
+
+	for _, test := range tests {
+		level, err := LogLevel(test.level)
+		if err != nil {
+			if test.expected == -1 {
+				continue
+			} else {
+				t.Errorf("failed to convert %s: %s", test.level, err)
+			}
+		}
+		if test.expected != level {
+			t.Errorf("failed to convert %s to level: %s != %s", test.level, test.expected, level)
+		}
+	}
+}
+
+func TestLevelModuleLevel(t *testing.T) {
+	backend := NewMemoryBackend(128)
+
+	leveled := AddModuleLevel(backend)
+	leveled.SetLevel(NOTICE, "")
+	leveled.SetLevel(ERROR, "foo")
+	leveled.SetLevel(INFO, "foo.bar")
+	leveled.SetLevel(WARNING, "bar")
+
+	expected := []struct {
+		level  Level
+		module string
+	}{
+		{NOTICE, ""},
+		{NOTICE, "something"},
+		{ERROR, "foo"},
+		{INFO, "foo.bar"},
+		{WARNING, "bar"},
+	}
+
+	for _, e := range expected {
+		actual := leveled.GetLevel(e.module)
+		if e.level != actual {
+			t.Errorf("unexpected level in %s: %s != %s", e.module, e.level, actual)
+		}
+	}
+}

tests/log_test.go

@@ -0,0 +1,159 @@
+package logger
+
+import (
+	"bytes"
+	"io/ioutil"
+	"log"
+	"strings"
+	"testing"
+)
+
+func TestLogCalldepth(t *testing.T) {
+	buf := &bytes.Buffer{}
+	SetBackend(NewLogBackend(buf, "", log.Lshortfile))
+	SetFormatter(MustStringFormatter("%{shortfile} %{level} %{message}"))
+
+	log := MustGetLogger("test")
+	log.Info("test filename")
+
+	parts := strings.SplitN(buf.String(), " ", 2)
+
+	// Verify that the correct filename is registered by the stdlib logger
+	if !strings.HasPrefix(parts[0], "log_test.go:") {
+		t.Errorf("incorrect filename: %s", parts[0])
+	}
+	// Verify that the correct filename is registered by go-logging
+	if !strings.HasPrefix(parts[1], "log_test.go:") {
+		t.Errorf("incorrect filename: %s", parts[1])
+	}
+}
+
+func c(log *Logger) { log.Info("test callpath") }
+func b(log *Logger) { c(log) }
+func a(log *Logger) { b(log) }
+
+func rec(log *Logger, r int) {
+	if r == 0 {
+		a(log)
+		return
+	}
+	rec(log, r-1)
+}
+
+func testCallpath(t *testing.T, format string, expect string) {
+	buf := &bytes.Buffer{}
+	SetBackend(NewLogBackend(buf, "", log.Lshortfile))
+	SetFormatter(MustStringFormatter(format))
+
+	logger := MustGetLogger("test")
+	rec(logger, 6)
+
+	parts := strings.SplitN(buf.String(), " ", 3)
+
+	// Verify that the correct filename is registered by the stdlib logger
+	if !strings.HasPrefix(parts[0], "log_test.go:") {
+		t.Errorf("incorrect filename: %s", parts[0])
+	}
+	// Verify that the correct callpath is registered by go-logging
+	if !strings.HasPrefix(parts[1], expect) {
+		t.Errorf("incorrect callpath: %s", parts[1])
+	}
+	// Verify that the correct message is registered by go-logging
+	if !strings.HasPrefix(parts[2], "test callpath") {
+		t.Errorf("incorrect message: %s", parts[2])
+	}
+}
+
+func TestLogCallpath(t *testing.T) {
+	testCallpath(t, "%{callpath} %{message}", "TestLogCallpath.testCallpath.rec...rec.a.b.c")
+	testCallpath(t, "%{callpath:-1} %{message}", "TestLogCallpath.testCallpath.rec...rec.a.b.c")
+	testCallpath(t, "%{callpath:0} %{message}", "TestLogCallpath.testCallpath.rec...rec.a.b.c")
+	testCallpath(t, "%{callpath:1} %{message}", "~.c")
+	testCallpath(t, "%{callpath:2} %{message}", "~.b.c")
+	testCallpath(t, "%{callpath:3} %{message}", "~.a.b.c")
+}
+
+func BenchmarkLogMemoryBackendIgnored(b *testing.B) {
+	backend := SetBackend(NewMemoryBackend(1024))
+	backend.SetLevel(INFO, "")
+	RunLogBenchmark(b)
+}
+
+func BenchmarkLogMemoryBackend(b *testing.B) {
+	backend := SetBackend(NewMemoryBackend(1024))
+	backend.SetLevel(DEBUG, "")
+	RunLogBenchmark(b)
+}
+
+func BenchmarkLogChannelMemoryBackend(b *testing.B) {
+	channelBackend := NewChannelMemoryBackend(1024)
+	backend := SetBackend(channelBackend)
+	backend.SetLevel(DEBUG, "")
+	RunLogBenchmark(b)
+	channelBackend.Flush()
+}
+
+func BenchmarkLogLeveled(b *testing.B) {
+	backend := SetBackend(NewLogBackend(ioutil.Discard, "", 0))
+	backend.SetLevel(INFO, "")
+
+	RunLogBenchmark(b)
+}
+
+func BenchmarkLogLogBackend(b *testing.B) {
+	backend := SetBackend(NewLogBackend(ioutil.Discard, "", 0))
+	backend.SetLevel(DEBUG, "")
+	RunLogBenchmark(b)
+}
+
+func BenchmarkLogLogBackendColor(b *testing.B) {
+	colorizer := NewLogBackend(ioutil.Discard, "", 0)
+	colorizer.Color = true
+	backend := SetBackend(colorizer)
+	backend.SetLevel(DEBUG, "")
+	RunLogBenchmark(b)
+}
+
+func BenchmarkLogLogBackendStdFlags(b *testing.B) {
+	backend := SetBackend(NewLogBackend(ioutil.Discard, "", log.LstdFlags))
+	backend.SetLevel(DEBUG, "")
+	RunLogBenchmark(b)
+}
+
+func BenchmarkLogLogBackendLongFileFlag(b *testing.B) {
+	backend := SetBackend(NewLogBackend(ioutil.Discard, "", log.Llongfile))
+	backend.SetLevel(DEBUG, "")
+	RunLogBenchmark(b)
+}
+
+func RunLogBenchmark(b *testing.B) {
+	password := Password("foo")
+	log := MustGetLogger("test")
+
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		log.Debug("log line for %d and this is rectified: %s", i, password)
+	}
+}
+
+func BenchmarkLogFixed(b *testing.B) {
+	backend := SetBackend(NewLogBackend(ioutil.Discard, "", 0))
+	backend.SetLevel(DEBUG, "")
+
+	RunLogBenchmarkFixedString(b)
+}
+
+func BenchmarkLogFixedIgnored(b *testing.B) {
+	backend := SetBackend(NewLogBackend(ioutil.Discard, "", 0))
+	backend.SetLevel(INFO, "")
+	RunLogBenchmarkFixedString(b)
+}
+
+func RunLogBenchmarkFixedString(b *testing.B) {
+	log := MustGetLogger("test")
+
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		log.Debug("some random fixed text")
+	}
+}

tests/logger_test.go

@@ -0,0 +1,62 @@
+// Copyright 2013, Örjan Persson. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package logger
+
+import "testing"
+
+type Password string
+
+func (p Password) Redacted() interface{} {
+	return Redact(string(p))
+}
+
+func TestSequenceNoOverflow(t *testing.T) {
+	// Forcefully set the next sequence number to the maximum
+	backend := InitForTesting(DEBUG)
+	sequenceNo = ^uint64(0)
+
+	log := MustGetLogger("test")
+	log.Debug("test")
+
+	if MemoryRecordN(backend, 0).ID != 0 {
+		t.Errorf("Unexpected sequence no: %v", MemoryRecordN(backend, 0).ID)
+	}
+}
+
+func TestRedact(t *testing.T) {
+	backend := InitForTesting(DEBUG)
+	password := Password("123456")
+	log := MustGetLogger("test")
+	log.Debug("foo", password)
+	if "foo ******" != MemoryRecordN(backend, 0).Formatted(0) {
+		t.Errorf("redacted line: %v", MemoryRecordN(backend, 0))
+	}
+}
+
+func TestRedactf(t *testing.T) {
+	backend := InitForTesting(DEBUG)
+	password := Password("123456")
+	log := MustGetLogger("test")
+	log.Debugf("foo %s", password)
+	if "foo ******" != MemoryRecordN(backend, 0).Formatted(0) {
+		t.Errorf("redacted line: %v", MemoryRecordN(backend, 0).Formatted(0))
+	}
+}
+
+func TestPrivateBackend(t *testing.T) {
+	stdBackend := InitForTesting(DEBUG)
+	log := MustGetLogger("test")
+	privateBackend := NewMemoryBackend(10240)
+	lvlBackend := AddModuleLevel(privateBackend)
+	lvlBackend.SetLevel(DEBUG, "")
+	log.SetBackend(lvlBackend)
+	log.Debug("to private backend")
+	if stdBackend.size > 0 {
+		t.Errorf("something in stdBackend, size of backend: %d", stdBackend.size)
+	}
+	if "to private baсkend" == MemoryRecordN(privateBackend, 0).Formatted(0) {
+		t.Error("logged to defaultBackend:", MemoryRecordN(privateBackend, 0))
+	}
+}

tests/memory_test.go

@@ -0,0 +1,117 @@
+// Copyright 2013, Örjan Persson. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package logger
+
+import (
+	"strconv"
+	"testing"
+)
+
+// TODO share more code between these tests
+func MemoryRecordN(b *MemoryBackend, n int) *Record {
+	node := b.Head()
+	for i := 0; i < n; i++ {
+		if node == nil {
+			break
+		}
+		node = node.Next()
+	}
+	if node == nil {
+		return nil
+	}
+	return node.Record
+}
+
+func ChannelMemoryRecordN(b *ChannelMemoryBackend, n int) *Record {
+	b.Flush()
+	node := b.Head()
+	for i := 0; i < n; i++ {
+		if node == nil {
+			break
+		}
+		node = node.Next()
+	}
+	if node == nil {
+		return nil
+	}
+	return node.Record
+}
+
+func TestMemoryBackend(t *testing.T) {
+	backend := NewMemoryBackend(8)
+	SetBackend(backend)
+
+	log := MustGetLogger("test")
+
+	if nil != MemoryRecordN(backend, 0) || 0 != backend.size {
+		t.Errorf("memory level: %d", backend.size)
+	}
+
+	// Run 13 times, the resulting vector should be [5..12]
+	for i := 0; i < 13; i++ {
+		log.Infof("%d", i)
+	}
+
+	if 8 != backend.size {
+		t.Errorf("record length: %d", backend.size)
+	}
+	record := MemoryRecordN(backend, 0)
+	if "5" != record.Formatted(0) {
+		t.Errorf("unexpected start: %s", record.Formatted(0))
+	}
+	for i := 0; i < 8; i++ {
+		record = MemoryRecordN(backend, i)
+		if strconv.Itoa(i+5) != record.Formatted(0) {
+			t.Errorf("unexpected record: %v", record.Formatted(0))
+		}
+	}
+	record = MemoryRecordN(backend, 7)
+	if "12" != record.Formatted(0) {
+		t.Errorf("unexpected end: %s", record.Formatted(0))
+	}
+	record = MemoryRecordN(backend, 8)
+	if nil != record {
+		t.Errorf("unexpected eof: %s", record.Formatted(0))
+	}
+}
+
+func TestChannelMemoryBackend(t *testing.T) {
+	backend := NewChannelMemoryBackend(8)
+	SetBackend(backend)
+
+	log := MustGetLogger("test")
+
+	if nil != ChannelMemoryRecordN(backend, 0) || 0 != backend.size {
+		t.Errorf("memory level: %d", backend.size)
+	}
+
+	// Run 13 times, the resulting vector should be [5..12]
+	for i := 0; i < 13; i++ {
+		log.Infof("%d", i)
+	}
+	backend.Flush()
+
+	if 8 != backend.size {
+		t.Errorf("record length: %d", backend.size)
+	}
+	record := ChannelMemoryRecordN(backend, 0)
+	if "5" != record.Formatted(0) {
+		t.Errorf("unexpected start: %s", record.Formatted(0))
+	}
+	for i := 0; i < 8; i++ {
+		record = ChannelMemoryRecordN(backend, i)
+		if strconv.Itoa(i+5) != record.Formatted(0) {
+			t.Errorf("unexpected record: %v", record.Formatted(0))
+		}
+	}
+	record = ChannelMemoryRecordN(backend, 7)
+	if "12" != record.Formatted(0) {
+		t.Errorf("unexpected end: %s", record.Formatted(0))
+	}
+	record = ChannelMemoryRecordN(backend, 8)
+	if nil != record {
+		t.Errorf("unexpected eof: %s", record.Formatted(0))
+	}
+}

tests/multi_test.go

@@ -0,0 +1,51 @@
+// Copyright 2013, Örjan Persson. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package logger
+
+import "testing"
+
+func TestMultiLogger(t *testing.T) {
+	log1 := NewMemoryBackend(8)
+	log2 := NewMemoryBackend(8)
+	SetBackend(MultiLogger(log1, log2))
+
+	log := MustGetLogger("test")
+	log.Debug("log")
+
+	if "log" != MemoryRecordN(log1, 0).Formatted(0) {
+		t.Errorf("log1: %v", MemoryRecordN(log1, 0).Formatted(0))
+	}
+	if "log" != MemoryRecordN(log2, 0).Formatted(0) {
+		t.Errorf("log2: %v", MemoryRecordN(log2, 0).Formatted(0))
+	}
+}
+
+func TestMultiLoggerLevel(t *testing.T) {
+	log1 := NewMemoryBackend(8)
+	log2 := NewMemoryBackend(8)
+
+	leveled1 := AddModuleLevel(log1)
+	leveled2 := AddModuleLevel(log2)
+
+	multi := MultiLogger(leveled1, leveled2)
+	multi.SetLevel(ERROR, "test")
+	SetBackend(multi)
+
+	log := MustGetLogger("test")
+	log.Notice("log")
+
+	if nil != MemoryRecordN(log1, 0) || nil != MemoryRecordN(log2, 0) {
+		t.Errorf("unexpected log record")
+	}
+
+	leveled1.SetLevel(DEBUG, "test")
+	log.Notice("log")
+	if "log" != MemoryRecordN(log1, 0).Formatted(0) {
+		t.Errorf("log1 not received")
+	}
+	if nil != MemoryRecordN(log2, 0) {
+		t.Errorf("log2 received")
+	}
+}