asynq/internal/log/log_test.go

// Copyright 2020 Kentaro Hibino. All rights reserved.
// Use of this source code is governed by a MIT license
// that can be found in the LICENSE file.

package log

import (
	"bytes"
	"fmt"
	"regexp"
	"testing"
)

// regexp for timestamps
const (
	rgxPID          = `[0-9]+`
	rgxdate         = `[0-9][0-9][0-9][0-9]/[0-9][0-9]/[0-9][0-9]`
	rgxtime         = `[0-9][0-9]:[0-9][0-9]:[0-9][0-9]`
	rgxmicroseconds = `\.[0-9][0-9][0-9][0-9][0-9][0-9]`
)

type tester struct {
	desc        string
	message     string
	wantPattern string // regexp that log output must match
}

func TestLoggerDebug(t *testing.T) {
	tests := []tester{
		{
			desc:    "without trailing newline, logger adds newline",
			message: "hello, world!",
			wantPattern: fmt.Sprintf("^asynq: pid=%s %s %s%s DEBUG: hello, world!\n$",
				rgxPID, rgxdate, rgxtime, rgxmicroseconds),
		},
		{
			desc:    "with trailing newline, logger preserves newline",
			message: "hello, world!\n",
			wantPattern: fmt.Sprintf("^asynq: pid=%s %s %s%s DEBUG: hello, world!\n$",
				rgxPID, rgxdate, rgxtime, rgxmicroseconds),
		},
	}

	for _, tc := range tests {
		var buf bytes.Buffer
		logger := NewLogger(newBase(&buf))

		logger.Debug(tc.message)

		got := buf.String()
		matched, err := regexp.MatchString(tc.wantPattern, got)
		if err != nil {
			t.Fatal("pattern did not compile:", err)
		}
		if !matched {
			t.Errorf("logger.Debug(%q) outputted %q, should match pattern %q",
				tc.message, got, tc.wantPattern)
		}
	}
}

func TestLoggerInfo(t *testing.T) {
	tests := []tester{
		{
			desc:    "without trailing newline, logger adds newline",
			message: "hello, world!",
			wantPattern: fmt.Sprintf("^asynq: pid=%s %s %s%s INFO: hello, world!\n$",
				rgxPID, rgxdate, rgxtime, rgxmicroseconds),
		},
		{
			desc:    "with trailing newline, logger preserves newline",
			message: "hello, world!\n",
			wantPattern: fmt.Sprintf("^asynq: pid=%s %s %s%s INFO: hello, world!\n$",
				rgxPID, rgxdate, rgxtime, rgxmicroseconds),
		},
	}

	for _, tc := range tests {
		var buf bytes.Buffer
		logger := NewLogger(newBase(&buf))

		logger.Info(tc.message)

		got := buf.String()
		matched, err := regexp.MatchString(tc.wantPattern, got)
		if err != nil {
			t.Fatal("pattern did not compile:", err)
		}
		if !matched {
			t.Errorf("logger.Info(%q) outputted %q, should match pattern %q",
				tc.message, got, tc.wantPattern)
		}
	}
}

func TestLoggerWarn(t *testing.T) {
	tests := []tester{
		{
			desc:    "without trailing newline, logger adds newline",
			message: "hello, world!",
			wantPattern: fmt.Sprintf("^asynq: pid=%s %s %s%s WARN: hello, world!\n$",
				rgxPID, rgxdate, rgxtime, rgxmicroseconds),
		},
		{
			desc:    "with trailing newline, logger preserves newline",
			message: "hello, world!\n",
			wantPattern: fmt.Sprintf("^asynq: pid=%s %s %s%s WARN: hello, world!\n$",
				rgxPID, rgxdate, rgxtime, rgxmicroseconds),
		},
	}

	for _, tc := range tests {
		var buf bytes.Buffer
		logger := NewLogger(newBase(&buf))

		logger.Warn(tc.message)

		got := buf.String()
		matched, err := regexp.MatchString(tc.wantPattern, got)
		if err != nil {
			t.Fatal("pattern did not compile:", err)
		}
		if !matched {
			t.Errorf("logger.Warn(%q) outputted %q, should match pattern %q",
				tc.message, got, tc.wantPattern)
		}
	}
}

func TestLoggerError(t *testing.T) {
	tests := []tester{
		{
			desc:    "without trailing newline, logger adds newline",
			message: "hello, world!",
			wantPattern: fmt.Sprintf("^asynq: pid=%s %s %s%s ERROR: hello, world!\n$",
				rgxPID, rgxdate, rgxtime, rgxmicroseconds),
		},
		{
			desc:    "with trailing newline, logger preserves newline",
			message: "hello, world!\n",
			wantPattern: fmt.Sprintf("^asynq: pid=%s %s %s%s ERROR: hello, world!\n$",
				rgxPID, rgxdate, rgxtime, rgxmicroseconds),
		},
	}

	for _, tc := range tests {
		var buf bytes.Buffer
		logger := NewLogger(newBase(&buf))

		logger.Error(tc.message)

		got := buf.String()
		matched, err := regexp.MatchString(tc.wantPattern, got)
		if err != nil {
			t.Fatal("pattern did not compile:", err)
		}
		if !matched {
			t.Errorf("logger.Error(%q) outputted %q, should match pattern %q",
				tc.message, got, tc.wantPattern)
		}
	}
}

type formatTester struct {
	desc        string
	format      string
	args        []interface{}
	wantPattern string // regexp that log output must match
}

func TestLoggerDebugf(t *testing.T) {
	tests := []formatTester{
		{
			desc:   "Formats message with DEBUG prefix",
			format: "hello, %s!",
			args:   []interface{}{"Gopher"},
			wantPattern: fmt.Sprintf("^asynq: pid=%s %s %s%s DEBUG: hello, Gopher!\n$",
				rgxPID, rgxdate, rgxtime, rgxmicroseconds),
		},
	}

	for _, tc := range tests {
		var buf bytes.Buffer
		logger := NewLogger(newBase(&buf))

		logger.Debugf(tc.format, tc.args...)

		got := buf.String()
		matched, err := regexp.MatchString(tc.wantPattern, got)
		if err != nil {
			t.Fatal("pattern did not compile:", err)
		}
		if !matched {
			t.Errorf("logger.Debugf(%q, %v) outputted %q, should match pattern %q",
				tc.format, tc.args, got, tc.wantPattern)
		}
	}
}

func TestLoggerInfof(t *testing.T) {
	tests := []formatTester{
		{
			desc:   "Formats message with INFO prefix",
			format: "%d,%d,%d",
			args:   []interface{}{1, 2, 3},
			wantPattern: fmt.Sprintf("^asynq: pid=%s %s %s%s INFO: 1,2,3\n$",
				rgxPID, rgxdate, rgxtime, rgxmicroseconds),
		},
	}

	for _, tc := range tests {
		var buf bytes.Buffer
		logger := NewLogger(newBase(&buf))

		logger.Infof(tc.format, tc.args...)

		got := buf.String()
		matched, err := regexp.MatchString(tc.wantPattern, got)
		if err != nil {
			t.Fatal("pattern did not compile:", err)
		}
		if !matched {
			t.Errorf("logger.Infof(%q, %v) outputted %q, should match pattern %q",
				tc.format, tc.args, got, tc.wantPattern)
		}
	}
}

func TestLoggerWarnf(t *testing.T) {
	tests := []formatTester{
		{
			desc:   "Formats message with WARN prefix",
			format: "hello, %s",
			args:   []interface{}{"Gophers"},
			wantPattern: fmt.Sprintf("^asynq: pid=%s %s %s%s WARN: hello, Gophers\n$",
				rgxPID, rgxdate, rgxtime, rgxmicroseconds),
		},
	}

	for _, tc := range tests {
		var buf bytes.Buffer
		logger := NewLogger(newBase(&buf))

		logger.Warnf(tc.format, tc.args...)

		got := buf.String()
		matched, err := regexp.MatchString(tc.wantPattern, got)
		if err != nil {
			t.Fatal("pattern did not compile:", err)
		}
		if !matched {
			t.Errorf("logger.Warnf(%q, %v) outputted %q, should match pattern %q",
				tc.format, tc.args, got, tc.wantPattern)
		}
	}
}

func TestLoggerErrorf(t *testing.T) {
	tests := []formatTester{
		{
			desc:   "Formats message with ERROR prefix",
			format: "hello, %s",
			args:   []interface{}{"Gophers"},
			wantPattern: fmt.Sprintf("^asynq: pid=%s %s %s%s ERROR: hello, Gophers\n$",
				rgxPID, rgxdate, rgxtime, rgxmicroseconds),
		},
	}

	for _, tc := range tests {
		var buf bytes.Buffer
		logger := NewLogger(newBase(&buf))

		logger.Errorf(tc.format, tc.args...)

		got := buf.String()
		matched, err := regexp.MatchString(tc.wantPattern, got)
		if err != nil {
			t.Fatal("pattern did not compile:", err)
		}
		if !matched {
			t.Errorf("logger.Errorf(%q, %v) outputted %q, should match pattern %q",
				tc.format, tc.args, got, tc.wantPattern)
		}
	}
}

func TestLoggerWithLowerLevels(t *testing.T) {
	// Logger should not log messages at a level
	// lower than the specified level.
	tests := []struct {
		level Level
		op    string
	}{
		// with level one above
		{InfoLevel, "Debug"},
		{InfoLevel, "Debugf"},
		{WarnLevel, "Info"},
		{WarnLevel, "Infof"},
		{ErrorLevel, "Warn"},
		{ErrorLevel, "Warnf"},
		{FatalLevel, "Error"},
		{FatalLevel, "Errorf"},
		// with skip level
		{WarnLevel, "Debug"},
		{ErrorLevel, "Infof"},
	}

	for _, tc := range tests {
		var buf bytes.Buffer
		logger := NewLogger(newBase(&buf))
		logger.SetLevel(tc.level)

		switch tc.op {
		case "Debug":
			logger.Debug("hello")
		case "Debugf":
			logger.Debugf("hello, %s", "world")
		case "Info":
			logger.Info("hello")
		case "Infof":
			logger.Infof("hello, %s", "world")
		case "Warn":
			logger.Warn("hello")
		case "Warnf":
			logger.Warnf("hello, %s", "world")
		case "Error":
			logger.Error("hello")
		case "Errorf":
			logger.Errorf("hello, %s", "world")
		default:
			t.Fatalf("unexpected op: %q", tc.op)
		}

		if buf.String() != "" {
			t.Errorf("logger.%s outputted log message when level is set to %v", tc.op, tc.level)
		}
	}
}

func TestLoggerWithSameOrHigherLevels(t *testing.T) {
	// Logger should log messages at a level
	// same as or higher than the specified level.
	tests := []struct {
		level Level
		op    string
	}{
		// same level
		{DebugLevel, "Debug"},
		{InfoLevel, "Infof"},
		{WarnLevel, "Warn"},
		{ErrorLevel, "Errorf"},
		// higher level
		{DebugLevel, "Info"},
		{InfoLevel, "Warnf"},
		{WarnLevel, "Error"},
	}

	for _, tc := range tests {
		var buf bytes.Buffer
		logger := NewLogger(newBase(&buf))
		logger.SetLevel(tc.level)

		switch tc.op {
		case "Debug":
			logger.Debug("hello")
		case "Debugf":
			logger.Debugf("hello, %s", "world")
		case "Info":
			logger.Info("hello")
		case "Infof":
			logger.Infof("hello, %s", "world")
		case "Warn":
			logger.Warn("hello")
		case "Warnf":
			logger.Warnf("hello, %s", "world")
		case "Error":
			logger.Error("hello")
		case "Errorf":
			logger.Errorf("hello, %s", "world")
		default:
			t.Fatalf("unexpected op: %q", tc.op)
		}

		if buf.String() == "" {
			t.Errorf("logger.%s did not output log message when level is set to %v", tc.op, tc.level)
		}
	}
}