logger/logger_test.go

/*
This Source Code Form is subject to the terms of the Mozilla Public
License, v. 2.0. If a copy of the MPL was not distributed with this
file, You can obtain one at https://mozilla.org/MPL/2.0/.
*/
package logger

import (
	"bytes"
	"fmt"
	"os"
	"os/exec"
	"runtime"
	"strings"
	"testing"
)

func bufLogger() (*Logger, *bytes.Buffer) {
	logger := NewLogger()
	logger.SetFlags(0)

	b := bytes.NewBufferString("")
	logger.SetOutput(b)

	return logger, b
}

func TestLogging(t *testing.T) {
	t.Run(
		"The default level is warn.",
		func(t *testing.T) {
			expected := LogLevelWarn

			logger := NewLogger()

			actual := logger.Level()
			if actual != expected {
				t.Errorf("Expected %v but got %v.", expected, actual)
			}
		},
	)
	t.Run(
		"Changes to logging level persist.",
		func(t *testing.T) {
			expected := LogLevelSilent

			logger := NewLogger()
			logger.SetLevel(LogLevelSilent)

			actual := logger.Level()
			if actual != expected {
				t.Errorf("Expected %v but got %v.", expected, actual)
			}
		},
	)
	t.Run(
		"A new logger uses the declared default flags.",
		func(t *testing.T) {
			expected := FlagsDefault

			logger := NewLogger()

			actual := logger.Flags()
			if actual != expected {
				t.Errorf("Expected %v but got %v.", expected, actual)
			}
		},
	)
	t.Run(
		"The default flags are nonzero.",
		func(t *testing.T) {
			if FlagsDefault == 0 {
				t.Errorf("Expected default flags to be nonzero.")
			}
		},
	)
	t.Run(
		"Changes to flags persist.",
		func(t *testing.T) {
			expected := 0

			logger := NewLogger()
			logger.SetFlags(0)

			actual := logger.Flags()
			if actual != expected {
				t.Errorf("Expected %v but got %v.", expected, actual)
			}
		},
	)
	t.Run(
		"A new logger logs a warning.",
		func(t *testing.T) {
			expected := "[Warn] a message\n"

			logger, buf := bufLogger()
			logger.Warn("%s", "a message")

			actual := buf.String()
			if actual != expected {
				t.Errorf("Expected %#v but got %#v.", expected, actual)
			}
		},
	)
	t.Run(
		"A new logger does not log an informational message.",
		func(t *testing.T) {
			expected := ""

			logger, buf := bufLogger()
			logger.Info("%s", "an informational message")

			actual := buf.String()
			if actual != expected {
				t.Errorf("Expected %#v but got %#v.", expected, actual)
			}
		},
	)
	t.Run(
		"Pushed contexts persist.",
		func(t *testing.T) {
			expected := "[Warn] some context: a message\n"

			logger, buf := bufLogger()
			logger = logger.Push("some context")
			logger.Warn("%s", "a message")

			actual := buf.String()
			if actual != expected {
				t.Errorf("Expected %#v but got %#v.", expected, actual)
			}
		},
	)
	t.Run(
		"Logging methods apply expected prefixes.",
		testLoggingMethodsApplyExpectedPrefixes,
	)
}

func testLoggingMethodsApplyExpectedPrefixes(t *testing.T) {
	logger, buf := bufLogger()
	logger.SetLevel(LogLevelDebug)

	for i, fun := range []func(string, ...any){
		nil,
		nil, // We have to test Fatal elsewhere
		logger.Error,
		logger.Warn,
		logger.Info,
		logger.Debug,
	} {
		if fun == nil {
			continue
		}
		prefix := logLevelPrefix[i]
		buf.Truncate(0)

		t.Run(
			"Log level has correct prefix.",
			func(t *testing.T) {
				buf := buf
				expected := "[" + prefix + "] \n"

				fun("")

				actual := buf.String()
				if actual != expected {
					t.Fatalf("Expected %#v but got %#v.", expected, actual)
				}
			},
		)
	}
}

/********************* Fatal tests ************************/

func TestASilentLoggerDoesNotLogFatalMessages(t *testing.T) {
	expected := ""

	_, stderr, succ, err :=
		runFatal(aSilentLoggerDoesNotLogFatalMessages)

	if _, ok := err.(*exec.ExitError); ok && succ {
		t.Fatal("Expected exit but none observed.")
	}

	actual := string(stderr)
	if actual != expected {
		t.Fatalf("Expected %#v but got %#v.", expected, actual)
	}
}

func aSilentLoggerDoesNotLogFatalMessages() {
	logger := NewLogger()
	logger.SetFlags(0)
	logger.SetLevel(LogLevelSilent)
	logger.Fatal("fatal message")
}

func TestFatalAppliesCorrectPrefix(t *testing.T) {
	expected := "[FATAL] \n"

	_, stderr, succ, err :=
		runFatal(fatalAppliesCorrectPrefix)

	if _, ok := err.(*exec.ExitError); ok && succ {
		t.Fatal("Expected exit but none observed.")
	}

	actual := string(stderr)
	if actual != expected {
		t.Fatalf("Expected %#v but got %#v.", expected, actual)
	}
}

func fatalAppliesCorrectPrefix() {
	logger := NewLogger()
	logger.SetFlags(0)
	logger.Fatal("")
}

// fatal test helper
func runFatal(
	fun func(),
) (stdout, stderr string, succ bool, err error) {
	// avoid infinite recursion
	if os.Getenv("CRASH") == "1" {
		fun()
		return
	}
	var caller string

	pc, _, _, ok := runtime.Caller(1)
	details := runtime.FuncForPC(pc)
	if ok && details != nil {
		caller = details.Name()
		tmp := strings.Split(details.Name(), ".")
		caller = tmp[len(tmp)-1]
	}
	if caller == "" {
		panic("Could not obtain caller")
	}

	cmd := exec.Command(
		os.Args[0],
		fmt.Sprintf("-test.run=%s", caller),
	)
	cmd.Env = append(os.Environ(), "CRASH=1")

	out, err := cmd.Output() // Output gives us stderr
	stdout = string(out)
	e, ok := err.(*exec.ExitError)
	if !ok {
		return
	}
	stderr = string(e.Stderr)
	succ = e.Success()
	return
}