bft/testutil/logger.go

// Copyright (C) 2019-2025, Ava Labs, Inc. All rights reserved.
// See the file LICENSE for licensing terms.

package testutil

import (
	"fmt"
	"io"
	"os"
	"path/filepath"
	"runtime"
	"strings"
	"sync"
	"testing"
	"time"

	"github.com/luxfi/log"
)

const (
	LOG_LEVEL      = "LOG_LEVEL"
	INFO_LOG_LEVEL = "info"
)

// LogEntry is what an Intercept hook observes. It carries only the level and
// the message because that is all any caller reads — the fields stay with the
// formatted output.
type LogEntry struct {
	Level   log.Level
	Message string
}

// TestLogger is the common.Logger a test wires into an instance. Every policy —
// level, keyword filter, hook, panic-on-warn/error — is applied in one place,
// emit, rather than layered as separate cores and encoders.
//
// One funnel, but TWO gates, because reporting and writing are different
// questions. Whether an observer SEES an entry is decided by level and
// keywords; whether a sink RECORDS it additionally depends on which sink. The
// layered original expressed those at different depths of the stack — a level
// on the core, debug suppression in the encoder — so collapsing them into a
// single predicate silently blinds every Intercept hook the moment debug output
// is quieted, which is precisely the configuration the test script runs under.
type TestLogger struct {
	t *testing.T

	mu       sync.Mutex
	stdout   io.Writer // nil when not writing to stdout
	file     io.Writer // nil when no file sink was supplied
	level    log.Level
	keywords []string
	hook     func(entry LogEntry) error

	panicOnError bool
	panicOnWarn  bool

	// quietDebugOnStdout suppresses debug lines on stdout only. A file sink
	// exists to be read after the fact, so it always keeps full fidelity.
	quietDebugOnStdout bool

	prefix string
}

// Intercept installs a hook that observes every entry that passes the level and
// keyword filters. Entries filtered out are not delivered, matching the order in
// which a level check precedes a write.
func (tl *TestLogger) Intercept(hook func(entry LogEntry) error) {
	tl.mu.Lock()
	defer tl.mu.Unlock()
	tl.hook = hook
}

// Silence drops everything below Fatal.
func (tl *TestLogger) Silence() {
	tl.SetLevel(log.FatalLevel)
}

// SilenceExceptKeywords silences all logs EXCEPT those whose message contains
// at least one of the provided keywords.
//
// Last call wins. The layered original nested a filtering core per call, so
// successive calls intersected their keyword sets; this replaces them. No caller
// invokes it twice — the sole caller is BasicNode.SilenceExceptKeywords — so the
// difference is recorded rather than preserved.
func (tl *TestLogger) SilenceExceptKeywords(keywords ...string) {
	tl.mu.Lock()
	defer tl.mu.Unlock()
	tl.keywords = keywords
}

func (tl *TestLogger) SetLevel(level log.Level) {
	tl.mu.Lock()
	defer tl.mu.Unlock()
	tl.level = level
}

func (tl *TestLogger) SetPanicOnError(panicOnError bool) {
	tl.mu.Lock()
	defer tl.mu.Unlock()
	tl.panicOnError = panicOnError
}

func (tl *TestLogger) SetPanicOnWarn(panicOnWarn bool) {
	tl.mu.Lock()
	defer tl.mu.Unlock()
	tl.panicOnWarn = panicOnWarn
}

// Trace and Verbo both report at Debug so that a suite running at the default
// level sees them, which is the level the layered implementation routed them to.
//
// They now also reach Intercept hooks. The layered original sent them through a
// second logger that never carried hooks, so hooks saw nothing from Trace or
// Verbo — except after SilenceExceptKeywords, which rebuilt that second logger
// from a hook-carrying core and started delivering them. This is uniform
// instead. No hook predicate in the tree matches any Trace or Verbo message, so
// nothing changes today; a future one would need to tolerate the delivery,
// since several hooks close channels or call WaitGroup.Done.
func (tl *TestLogger) Trace(msg string, fields ...log.Field) {
	tl.emit(log.DebugLevel, msg, fields)
}

func (tl *TestLogger) Verbo(msg string, fields ...log.Field) {
	tl.emit(log.DebugLevel, msg, fields)
}

func (tl *TestLogger) Debug(msg string, fields ...log.Field) {
	tl.emit(log.DebugLevel, msg, fields)
}

func (tl *TestLogger) Info(msg string, fields ...log.Field) {
	tl.emit(log.InfoLevel, msg, fields)
}

func (tl *TestLogger) Warn(msg string, fields ...log.Field) {
	tl.emit(log.WarnLevel, msg, fields)
	if tl.panics(&tl.panicOnWarn) {
		panic(fmt.Sprintf("WARN during test %s: %s", tl.t.Name(), msg))
	}
}

func (tl *TestLogger) Error(msg string, fields ...log.Field) {
	tl.emit(log.ErrorLevel, msg, fields)
	if tl.panics(&tl.panicOnError) {
		panic(fmt.Sprintf("ERROR during test %s: %s", tl.t.Name(), msg))
	}
}

// Fatal panics instead of exiting. The one production caller reports an
// impossible node role, so a test that reaches it has found a real defect —
// exiting the process would take the whole suite down with no attribution,
// while a panic fails the test that caused it and keeps the stack.
func (tl *TestLogger) Fatal(msg string, fields ...log.Field) {
	tl.emit(log.FatalLevel, msg, fields)
	panic(fmt.Sprintf("FATAL during test %s: %s", tl.t.Name(), msg))
}

func (tl *TestLogger) panics(flag *bool) bool {
	tl.mu.Lock()
	defer tl.mu.Unlock()
	return *flag
}

// emit is the only path to the sinks. It decides whether the entry is reported
// at all, delivers it to the hook, then decides separately which sinks record
// it. Suppressing debug output must NOT withhold the entry from the hook: the
// hook is the harness's observation channel, and a test that waits on a debug
// message would otherwise wait forever whenever output is quieted.
func (tl *TestLogger) emit(level log.Level, msg string, fields []log.Field) {
	tl.mu.Lock()
	report := level >= tl.level
	if report && len(tl.keywords) > 0 {
		report = false
		for _, kw := range tl.keywords {
			if strings.Contains(msg, kw) {
				report = true
				break
			}
		}
	}
	hook, stdout, file := tl.hook, tl.stdout, tl.file
	quietDebug, prefix := tl.quietDebugOnStdout, tl.prefix
	tl.mu.Unlock()

	if !report {
		return
	}

	// Outside the lock: a hook may log, and holding the lock across it would
	// deadlock the test rather than fail it.
	if hook != nil {
		_ = hook(LogEntry{Level: level, Message: msg})
	}

	var b strings.Builder
	b.WriteString(time.Now().Format("[01-02|15:04:05.000] "))
	b.WriteString(strings.ToUpper(level.String()))
	if _, callerFile, line, ok := runtime.Caller(2); ok {
		fmt.Fprintf(&b, " %s:%d", filepath.Base(callerFile), line)
	}
	b.WriteByte(' ')
	b.WriteString(msg)
	b.WriteString(prefix)
	for _, f := range fields {
		fmt.Fprintf(&b, " %s=%v", f.Key, f.Value)
	}
	b.WriteByte('\n')
	line := b.String()

	tl.mu.Lock()
	defer tl.mu.Unlock()
	if file != nil {
		_, _ = io.WriteString(file, line)
	}
	if stdout != nil && !(quietDebug && level <= log.DebugLevel) {
		_, _ = io.WriteString(stdout, line)
	}
}

func MakeLogger(t *testing.T, node ...int) *TestLogger {
	// Preserve existing behavior: logs to stdout by default.
	return MakeLoggerWithFile(t, nil, true, node...)
}

// MakeLoggerWithFile creates a TestLogger that can write to a file and optionally to stdout.
// - If writeStdout is true, logs may be written to stdout.
// - If fileWriter is non-nil, logs may be written to that fileWriter.
// - If both are enabled, logs go to both.
// - If neither is enabled, logs are discarded.
//
// Concurrent writes are safe because emit serialises them; the writer itself
// needs no synchronisation of its own.
func MakeLoggerWithFile(t *testing.T, fileWriter io.Writer, writeStdout bool, node ...int) *TestLogger {
	prefix := fmt.Sprintf(" test=%s", t.Name())
	if len(node) > 0 {
		prefix += fmt.Sprintf(" myNodeID=%d", node[0])
	}

	tl := &TestLogger{t: t, file: fileWriter, prefix: prefix}
	if writeStdout {
		tl.stdout = os.Stdout
		// LOG_LEVEL=info quiets debug on STDOUT only. The layered version read
		// "LOG_LEVEL" for the stdout sink and "log_level" for the file sink, and
		// since only the former is ever set, a file sink kept every debug line
		// while stdout dropped them. That asymmetry is worth keeping — a
		// post-mortem log is read precisely because something went wrong — so it
		// is stated here as one deliberate rule instead of two spellings that
		// happen to disagree.
		tl.quietDebugOnStdout = strings.EqualFold(os.Getenv(LOG_LEVEL), INFO_LOG_LEVEL)
	}
	return tl
}