build: add new PrefixLogger to create independent prefix loggers

build/prefix_logger.go

@@ -0,0 +1,158 @@
+package build
+
+import (
+	"context"
+	"fmt"
+
+	btclogv1 "github.com/btcsuite/btclog"
+	"github.com/btcsuite/btclog/v2"
+)
+
+// PrefixLogger is a logger wrapper that adds a prefix to all log messages while
+// delegating to a base logger. This allows the base logger's level to be
+// changed dynamically and have it affect all PrefixLogger instances.
+type PrefixLogger struct {
+	prefix string
+	base   btclog.Logger
+}
+
+// NewPrefixLogger creates a new PrefixLogger that adds the given prefix to all
+// log messages.
+func NewPrefixLogger(base btclog.Logger, prefix string) *PrefixLogger {
+	return &PrefixLogger{
+		prefix: prefix,
+		base:   base,
+	}
+}
+
+// addPrefix adds the prefix to the given format string.
+func (p *PrefixLogger) addPrefix(format string) string {
+	return p.prefix + " " + format
+}
+
+// Tracef logs a formatted message at the trace level.
+func (p *PrefixLogger) Tracef(format string, params ...interface{}) {
+	p.base.Tracef(p.addPrefix(format), params...)
+}
+
+// Debugf logs a formatted message at the debug level.
+func (p *PrefixLogger) Debugf(format string, params ...interface{}) {
+	p.base.Debugf(p.addPrefix(format), params...)
+}
+
+// Infof logs a formatted message at the info level.
+func (p *PrefixLogger) Infof(format string, params ...interface{}) {
+	p.base.Infof(p.addPrefix(format), params...)
+}
+
+// Warnf logs a formatted message at the warn level.
+func (p *PrefixLogger) Warnf(format string, params ...interface{}) {
+	p.base.Warnf(p.addPrefix(format), params...)
+}
+
+// Errorf logs a formatted message at the error level.
+func (p *PrefixLogger) Errorf(format string, params ...interface{}) {
+	p.base.Errorf(p.addPrefix(format), params...)
+}
+
+// Criticalf logs a formatted message at the critical level.
+func (p *PrefixLogger) Criticalf(format string, params ...interface{}) {
+	p.base.Criticalf(p.addPrefix(format), params...)
+}
+
+// Trace logs a message at the trace level.
+func (p *PrefixLogger) Trace(v ...interface{}) {
+	msg := fmt.Sprint(v...)
+	p.base.Trace(p.prefix + " " + msg)
+}
+
+// Debug logs a message at the debug level.
+func (p *PrefixLogger) Debug(v ...interface{}) {
+	msg := fmt.Sprint(v...)
+	p.base.Debug(p.prefix + " " + msg)
+}
+
+// Info logs a message at the info level.
+func (p *PrefixLogger) Info(v ...interface{}) {
+	msg := fmt.Sprint(v...)
+	p.base.Info(p.prefix + " " + msg)
+}
+
+// Warn logs a message at the warn level.
+func (p *PrefixLogger) Warn(v ...interface{}) {
+	msg := fmt.Sprint(v...)
+	p.base.Warn(p.prefix + " " + msg)
+}
+
+// Error logs a message at the error level.
+func (p *PrefixLogger) Error(v ...interface{}) {
+	msg := fmt.Sprint(v...)
+	p.base.Error(p.prefix + " " + msg)
+}
+
+// Critical logs a message at the critical level.
+func (p *PrefixLogger) Critical(v ...interface{}) {
+	msg := fmt.Sprint(v...)
+	p.base.Critical(p.prefix + " " + msg)
+}
+
+// Level returns the current logging level of the base logger.
+func (p *PrefixLogger) Level() btclogv1.Level {
+	return p.base.Level()
+}
+
+// SetLevel sets the logging level of the base logger.
+func (p *PrefixLogger) SetLevel(level btclogv1.Level) {
+	p.base.SetLevel(level)
+}
+
+// SubSystem creates a new logger for a subsystem.
+func (p *PrefixLogger) SubSystem(tag string) btclog.Logger {
+	return p.base.SubSystem(tag)
+}
+
+// WithPrefix creates a new logger with an additional prefix.
+func (p *PrefixLogger) WithPrefix(prefix string) btclog.Logger {
+	// Combine the existing prefix with the new one.
+	newPrefix := p.prefix + ": " + prefix
+	return NewPrefixLogger(p.base, newPrefix)
+}
+
+// TraceS logs a structured message at the trace level.
+func (p *PrefixLogger) TraceS(ctx context.Context, msg string, attrs ...any) {
+	p.base.TraceS(ctx, p.prefix+" "+msg, attrs...)
+}
+
+// DebugS logs a structured message at the debug level.
+func (p *PrefixLogger) DebugS(ctx context.Context, msg string, attrs ...any) {
+	p.base.DebugS(ctx, p.prefix+" "+msg, attrs...)
+}
+
+// InfoS logs a structured message at the info level.
+func (p *PrefixLogger) InfoS(ctx context.Context, msg string, attrs ...any) {
+	p.base.InfoS(ctx, p.prefix+" "+msg, attrs...)
+}
+
+// WarnS logs a structured message at the warn level.
+func (p *PrefixLogger) WarnS(ctx context.Context, msg string, err error,
+	attrs ...any) {
+
+	p.base.WarnS(ctx, p.prefix+" "+msg, err, attrs...)
+}
+
+// ErrorS logs a structured message at the error level.
+func (p *PrefixLogger) ErrorS(ctx context.Context, msg string, err error,
+	attrs ...any) {
+
+	p.base.ErrorS(ctx, p.prefix+" "+msg, err, attrs...)
+}
+
+// CriticalS logs a structured message at the critical level.
+func (p *PrefixLogger) CriticalS(ctx context.Context, msg string, err error,
+	attrs ...any) {
+
+	p.base.CriticalS(ctx, p.prefix+" "+msg, err, attrs...)
+}
+
+// Compile-time check to ensure PrefixLogger implements btclog.Logger.
+var _ btclog.Logger = (*PrefixLogger)(nil)

build/prefix_logger_test.go

@@ -0,0 +1,181 @@
+package build
+
+import (
+	"bytes"
+	"strings"
+	"testing"
+
+	btclogv1 "github.com/btcsuite/btclog"
+	"github.com/btcsuite/btclog/v2"
+	"github.com/stretchr/testify/require"
+)
+
+// TestPrefixLoggerLevelChange tests that PrefixLogger correctly delegates to
+// the base logger and respects dynamic level changes.
+func TestPrefixLoggerLevelChange(t *testing.T) {
+	t.Parallel()
+
+	// We'll user this buffer to capture the log output.
+	var buf bytes.Buffer
+
+	// Create a base logger with a handler that writes to our buffer.
+	handler := btclog.NewDefaultHandler(&buf)
+	handler.SetLevel(btclogv1.LevelDebug)
+	baseLogger := btclog.NewSLogger(handler)
+
+	// Verify that WithPrefix creates independent logger instances.
+	t.Run("WithPrefix creates independent loggers", func(t *testing.T) {
+		// Create a logger with WithPrefix (simulating the old
+		// behavior).
+		withPrefixLogger := baseLogger.WithPrefix("Peer1")
+
+		// Create a PrefixLogger (our new implementation).
+		prefixLogger := NewPrefixLogger(baseLogger, "Peer2")
+
+		buf.Reset()
+
+		// Both should log debug messages initially.
+		withPrefixLogger.Debugf("test debug message")
+		require.Contains(t, buf.String(), "test debug message")
+		require.Contains(t, buf.String(), "Peer1")
+
+		buf.Reset()
+
+		prefixLogger.Debugf("test debug message")
+		require.Contains(t, buf.String(), "test debug message")
+		require.Contains(t, buf.String(), "Peer2")
+
+		// Now we'll change base logger level to INFO.
+		baseLogger.SetLevel(btclogv1.LevelInfo)
+
+		buf.Reset()
+
+		// WithPrefix logger still logs debug: this was the original bug
+		// we've set out to fix with PrefixLogger!
+		//
+		// This will still log because WithPrefix created an independent
+		// logger.
+		withPrefixLogger.Debugf("debug after level change")
+
+		require.Contains(t, buf.String(), "debug after level change")
+
+		buf.Reset()
+
+		// PrefixLogger respects the base logger's new level. This shows
+		// that the loggers are independent.
+		//
+		// This should NOT log because PrefixLogger delegates to base
+		// logger.
+		prefixLogger.Debugf("debug after level change")
+		require.Empty(t, buf.String())
+
+		buf.Reset()
+
+		// Both should still log INFO messages.
+		withPrefixLogger.Infof("info message")
+		require.Contains(t, buf.String(), "info message")
+
+		buf.Reset()
+
+		prefixLogger.Infof("info message")
+		require.Contains(t, buf.String(), "info message")
+	})
+
+	// Verify that PrefixLogger correctly adds prefixes.
+	t.Run("PrefixLogger adds prefixes correctly", func(t *testing.T) {
+		baseLogger.SetLevel(btclogv1.LevelDebug)
+		prefixLogger := NewPrefixLogger(baseLogger, "TestPeer")
+
+		buf.Reset()
+
+		// Test basic formatting first.
+		prefixLogger.Debugf("formatted %s", "message")
+		output := buf.String()
+		require.Contains(t, output, "TestPeer formatted message")
+
+		// Next, we'll test unformatted messages.
+		buf.Reset()
+		prefixLogger.Info("unformatted message")
+		output = buf.String()
+		require.Contains(t, output, "TestPeer unformatted message")
+	})
+
+	// Verify that nested prefixes work correctly.
+	t.Run("Nested prefixes work correctly", func(t *testing.T) {
+		baseLogger.SetLevel(btclogv1.LevelDebug)
+		prefixLogger1 := NewPrefixLogger(baseLogger, "Peer1")
+		prefixLogger2 := prefixLogger1.WithPrefix("Channel1")
+
+		buf.Reset()
+
+		prefixLogger2.Infof("nested prefix test")
+
+		output := buf.String()
+		require.Contains(
+			t, output, "Peer1: Channel1 nested prefix test",
+		)
+	})
+
+	// Verify that the Level() method returns the base logger's level.
+	t.Run("Level method returns current level", func(t *testing.T) {
+		prefixLogger := NewPrefixLogger(baseLogger, "TestPeer")
+
+		baseLogger.SetLevel(btclogv1.LevelWarn)
+		require.Equal(t, btclogv1.LevelWarn, prefixLogger.Level())
+
+		baseLogger.SetLevel(btclogv1.LevelDebug)
+		require.Equal(t, btclogv1.LevelDebug, prefixLogger.Level())
+	})
+}
+
+// TestPrefixLoggerSimulatesPeerBehavior simulates the actual peer logging
+// behavior to demonstrate the fix.
+func TestPrefixLoggerSimulatesPeerBehavior(t *testing.T) {
+	var buf bytes.Buffer
+
+	// Simulate the global peerLog.
+	handler := btclog.NewDefaultHandler(&buf)
+	handler.SetLevel(btclogv1.LevelDebug)
+	peerLog := btclog.NewSLogger(handler)
+
+	// Simulate creating multiple peers (like NewBrontide does).
+	peer1Logger := NewPrefixLogger(peerLog, "Peer(abc123)")
+	peer2Logger := NewPrefixLogger(peerLog, "Peer(def456)")
+
+	buf.Reset()
+
+	// Initially, debug messages are logged.
+	peer1Logger.Debugf("Received ChannelUpdate")
+	peer2Logger.Debugf("Received ChannelUpdate")
+
+	output := buf.String()
+	lines := strings.Split(strings.TrimSpace(output), "\n")
+	require.Len(t, lines, 2)
+	require.Contains(t, lines[0], "Peer(abc123) Received ChannelUpdate")
+	require.Contains(t, lines[1], "Peer(def456) Received ChannelUpdate")
+
+	// Simulate running "lncli debuglevel --level info".
+	peerLog.SetLevel(btclogv1.LevelInfo)
+
+	buf.Reset()
+
+	// Now debug messages should NOT be logged.
+	peer1Logger.Debugf("Received ChannelUpdate")
+	peer2Logger.Debugf("Received ChannelUpdate")
+	require.Empty(
+		t, buf.String(), "debug messages should "+
+			"not be logged at INFO level",
+	)
+
+	buf.Reset()
+
+	// But INFO messages should still be logged.
+	peer1Logger.Infof("Peer connected")
+	peer2Logger.Infof("Peer connected")
+
+	output = buf.String()
+	lines = strings.Split(strings.TrimSpace(output), "\n")
+	require.Len(t, lines, 2)
+	require.Contains(t, lines[0], "Peer(abc123) Peer connected")
+	require.Contains(t, lines[1], "Peer(def456) Peer connected")
+}

chainio/blockbeat.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 
 	"github.com/btcsuite/btclog/v2"
+	"github.com/lightningnetwork/lnd/build"
 	"github.com/lightningnetwork/lnd/chainntnfs"
 )
 
@@ -34,7 +35,7 @@ func NewBeat(epoch chainntnfs.BlockEpoch) *Beat {
 
 	// Create a customized logger for the blockbeat.
 	logPrefix := fmt.Sprintf("Height[%6d]:", b.Height())
-	b.log = clog.WithPrefix(logPrefix)
+	b.log = build.NewPrefixLogger(clog, logPrefix)
 
 	return b
 }

contractcourt/contract_resolver.go

@@ -9,6 +9,7 @@ import (
 
 	"github.com/btcsuite/btcd/wire"
 	"github.com/btcsuite/btclog/v2"
+	"github.com/lightningnetwork/lnd/build"
 	"github.com/lightningnetwork/lnd/channeldb"
 	"github.com/lightningnetwork/lnd/fn/v2"
 	"github.com/lightningnetwork/lnd/sweep"
@@ -152,7 +153,7 @@ func (r *contractResolverKit) initLogger(prefix string) {
 	logPrefix := fmt.Sprintf("ChannelArbitrator(%v): %s:", r.ChanPoint,
 		prefix)
 
-	r.log = log.WithPrefix(logPrefix)
+	r.log = build.NewPrefixLogger(log, logPrefix)
 }
 
 // IsResolved returns true if the stored state in the resolve is fully

htlcswitch/link.go

@@ -15,6 +15,7 @@ import (
 	"github.com/btcsuite/btcd/btcutil"
 	"github.com/btcsuite/btcd/wire"
 	"github.com/btcsuite/btclog/v2"
+	"github.com/lightningnetwork/lnd/build"
 	"github.com/lightningnetwork/lnd/channeldb"
 	"github.com/lightningnetwork/lnd/contractcourt"
 	"github.com/lightningnetwork/lnd/fn/v2"
@@ -517,7 +518,7 @@ func NewChannelLink(cfg ChannelLinkConfig,
 		channel:             channel,
 		hodlMap:             make(map[models.CircuitKey]hodlHtlc),
 		hodlQueue:           queue.NewConcurrentQueue(10),
-		log:                 log.WithPrefix(logPrefix),
+		log:                 build.NewPrefixLogger(log, logPrefix),
 		flushHooks:          newHookMap(),
 		outgoingCommitHooks: newHookMap(),
 		incomingCommitHooks: newHookMap(),