diff --git a/build/prefix_logger.go b/build/prefix_logger.go new file mode 100644 index 00000000000..6e015fc2db1 --- /dev/null +++ b/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) diff --git a/build/prefix_logger_test.go b/build/prefix_logger_test.go new file mode 100644 index 00000000000..b431e71a76a --- /dev/null +++ b/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") +} diff --git a/chainio/blockbeat.go b/chainio/blockbeat.go index 79188657fec..801eb180db7 100644 --- a/chainio/blockbeat.go +++ b/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 } diff --git a/contractcourt/contract_resolver.go b/contractcourt/contract_resolver.go index d11bd2f597a..e4efdea8f74 100644 --- a/contractcourt/contract_resolver.go +++ 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 diff --git a/htlcswitch/link.go b/htlcswitch/link.go index 1abf496a1fb..95cb975c52e 100644 --- a/htlcswitch/link.go +++ b/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(), diff --git a/htlcswitch/quiescer.go b/htlcswitch/quiescer.go index e16935d850b..9489d87719c 100644 --- a/htlcswitch/quiescer.go +++ b/htlcswitch/quiescer.go @@ -6,6 +6,7 @@ import ( "time" "github.com/btcsuite/btclog/v2" + "github.com/lightningnetwork/lnd/build" "github.com/lightningnetwork/lnd/fn/v2" "github.com/lightningnetwork/lnd/lntypes" "github.com/lightningnetwork/lnd/lnwire" @@ -173,7 +174,7 @@ func NewQuiescer(cfg QuiescerCfg) Quiescer { return &QuiescerLive{ cfg: cfg, - log: log.WithPrefix(logPrefix), + log: build.NewPrefixLogger(log, logPrefix), } } diff --git a/lnwallet/channel.go b/lnwallet/channel.go index ee45bf943d7..2695417f071 100644 --- a/lnwallet/channel.go +++ b/lnwallet/channel.go @@ -22,6 +22,7 @@ import ( "github.com/btcsuite/btcd/wire" "github.com/btcsuite/btclog/v2" "github.com/davecgh/go-spew/spew" + "github.com/lightningnetwork/lnd/build" "github.com/lightningnetwork/lnd/chainntnfs" "github.com/lightningnetwork/lnd/channeldb" "github.com/lightningnetwork/lnd/fn/v2" @@ -953,7 +954,7 @@ func NewLightningChannel(signer input.Signer, updateLogs: updateLogs, Capacity: state.Capacity, taprootNonceProducer: taprootNonceProducer, - log: walletLog.WithPrefix(logPrefix), + log: build.NewPrefixLogger(walletLog, logPrefix), opts: opts, } diff --git a/peer/brontide.go b/peer/brontide.go index 5b0d84f2f3a..acf478750f2 100644 --- a/peer/brontide.go +++ b/peer/brontide.go @@ -21,6 +21,7 @@ import ( "github.com/btcsuite/btclog/v2" "github.com/davecgh/go-spew/spew" "github.com/lightningnetwork/lnd/buffer" + "github.com/lightningnetwork/lnd/build" "github.com/lightningnetwork/lnd/chainntnfs" "github.com/lightningnetwork/lnd/channeldb" "github.com/lightningnetwork/lnd/channelnotifier" @@ -682,7 +683,7 @@ func NewBrontide(cfg Config) *Brontide { chanCloseMsgs: make(chan *closeMsg), resentChanSyncMsg: make(map[lnwire.ChannelID]struct{}), startReady: make(chan struct{}), - log: peerLog.WithPrefix(logPrefix), + log: build.NewPrefixLogger(peerLog, logPrefix), msgRouter: msgRouter, globalMsgRouter: globalMsgRouter, cg: fn.NewContextGuard(), diff --git a/protofsm/state_machine.go b/protofsm/state_machine.go index aabf69baa74..bc308a501b5 100644 --- a/protofsm/state_machine.go +++ b/protofsm/state_machine.go @@ -11,6 +11,7 @@ import ( "github.com/btcsuite/btcd/chaincfg/chainhash" "github.com/btcsuite/btcd/wire" "github.com/btcsuite/btclog/v2" + "github.com/lightningnetwork/lnd/build" "github.com/lightningnetwork/lnd/chainntnfs" "github.com/lightningnetwork/lnd/fn/v2" "github.com/lightningnetwork/lnd/lnutils" @@ -210,8 +211,8 @@ func NewStateMachine[Event any, Env Environment]( return StateMachine[Event, Env]{ cfg: cfg, - log: log.WithPrefix( - fmt.Sprintf("FSM(%v):", cfg.Env.Name()), + log: build.NewPrefixLogger( + log, fmt.Sprintf("FSM(%v):", cfg.Env.Name()), ), events: make(chan Event, 1), stateQuery: make(chan stateQuery[Event, Env]), diff --git a/routing/missioncontrol.go b/routing/missioncontrol.go index 89e14f523bc..85b4294ecdf 100644 --- a/routing/missioncontrol.go +++ b/routing/missioncontrol.go @@ -11,6 +11,7 @@ import ( "github.com/btcsuite/btcd/btcutil" "github.com/btcsuite/btclog/v2" "github.com/btcsuite/btcwallet/walletdb" + "github.com/lightningnetwork/lnd/build" "github.com/lightningnetwork/lnd/channeldb" "github.com/lightningnetwork/lnd/clock" "github.com/lightningnetwork/lnd/fn/v2" @@ -418,7 +419,7 @@ func (m *MissionController) initMissionControl(namespace string) ( ), store: store, estimator: cfg.Estimator, - log: log.WithPrefix(fmt.Sprintf("[%s]:", namespace)), + log: build.NewPrefixLogger(log, fmt.Sprintf("[%s]:", namespace)), onConfigUpdate: cfg.OnConfigUpdate, } diff --git a/routing/payment_session.go b/routing/payment_session.go index cf20251ed4b..670c92f78d8 100644 --- a/routing/payment_session.go +++ b/routing/payment_session.go @@ -5,6 +5,7 @@ import ( "github.com/btcsuite/btcd/btcec/v2" "github.com/btcsuite/btclog/v2" + "github.com/lightningnetwork/lnd/build" "github.com/lightningnetwork/lnd/channeldb" graphdb "github.com/lightningnetwork/lnd/graph/db" "github.com/lightningnetwork/lnd/graph/db/models" @@ -232,7 +233,7 @@ func newPaymentSession(p *LightningPayment, selfNode route.Vertex, pathFindingConfig: pathFindingConfig, missionControl: missionControl, minShardAmt: DefaultShardMinAmt, - log: log.WithPrefix(logPrefix), + log: build.NewPrefixLogger(log, logPrefix), }, nil } diff --git a/watchtower/wtclient/client.go b/watchtower/wtclient/client.go index 8d74e9d1f3d..09728bd450f 100644 --- a/watchtower/wtclient/client.go +++ b/watchtower/wtclient/client.go @@ -13,6 +13,7 @@ import ( "github.com/btcsuite/btcd/btcec/v2" "github.com/btcsuite/btclog/v2" + "github.com/lightningnetwork/lnd/build" "github.com/lightningnetwork/lnd/channeldb" "github.com/lightningnetwork/lnd/keychain" "github.com/lightningnetwork/lnd/lnwallet" @@ -210,7 +211,7 @@ func newClient(cfg *clientCfg) (*client, error) { if err != nil { return nil, err } - plog := log.WithPrefix(fmt.Sprintf("(%s)", identifier)) + plog := build.NewPrefixLogger(log, fmt.Sprintf("(%s)", identifier)) queueDB := cfg.DB.GetDBQueue([]byte(identifier)) queue, err := NewDiskOverflowQueue[*wtdb.BackupID](