From c4107ebbad8a7d503350ae0d63270e842aaedec1 Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Tue, 24 Sep 2019 15:05:40 +0200 Subject: [PATCH 1/5] build: add prefixed logger --- build/prefix_log.go | 112 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 112 insertions(+) create mode 100644 build/prefix_log.go diff --git a/build/prefix_log.go b/build/prefix_log.go new file mode 100644 index 00000000..926b3f58 --- /dev/null +++ b/build/prefix_log.go @@ -0,0 +1,112 @@ +package build + +import "github.com/btcsuite/btclog" + +// PrefixLog is a pass-through logger that adds a prefix to every logged line. +type PrefixLog struct { + log btclog.Logger + prefix string +} + +// NewPrefixLog instantiates a new prefixed logger. +func NewPrefixLog(prefix string, log btclog.Logger) *PrefixLog { + return &PrefixLog{ + prefix: prefix, + log: log, + } +} + +// addFormatPrefix prepends the prefix to a format string. +func (p *PrefixLog) addFormatPrefix(s string) string { + return p.prefix + " " + s +} + +// addArgsPrefix prepends the prefix to a list of arguments. +func (p *PrefixLog) addArgsPrefix(args []interface{}) []interface{} { + return append([]interface{}{p.prefix}, args...) +} + +// Tracef formats message according to format specifier and writes to to log +// with LevelTrace. +func (p *PrefixLog) Tracef(format string, params ...interface{}) { + p.log.Tracef(p.addFormatPrefix(format), params...) +} + +// Debugf formats message according to format specifier and writes to log with +// LevelDebug. +func (p *PrefixLog) Debugf(format string, params ...interface{}) { + p.log.Debugf(p.addFormatPrefix(format), params...) +} + +// Infof formats message according to format specifier and writes to log with +// LevelInfo. +func (p *PrefixLog) Infof(format string, params ...interface{}) { + p.log.Infof(p.addFormatPrefix(format), params...) +} + +// Warnf formats message according to format specifier and writes to to log with +// LevelWarn. +func (p *PrefixLog) Warnf(format string, params ...interface{}) { + p.log.Warnf(p.addFormatPrefix(format), params...) +} + +// Errorf formats message according to format specifier and writes to to log +// with LevelError. +func (p *PrefixLog) Errorf(format string, params ...interface{}) { + p.log.Errorf(p.addFormatPrefix(format), params...) +} + +// Criticalf formats message according to format specifier and writes to log +// with LevelCritical. +func (p *PrefixLog) Criticalf(format string, params ...interface{}) { + p.log.Criticalf(p.addFormatPrefix(format), params...) +} + +// Trace formats message using the default formats for its operands and writes +// to log with LevelTrace. +func (p *PrefixLog) Trace(v ...interface{}) { + p.log.Trace(p.addArgsPrefix(v)...) +} + +// Debug formats message using the default formats for its operands and writes +// to log with LevelDebug. +func (p *PrefixLog) Debug(v ...interface{}) { + p.log.Debug(p.addArgsPrefix(v)...) +} + +// Info formats message using the default formats for its operands and writes to +// log with LevelInfo. +func (p *PrefixLog) Info(v ...interface{}) { + p.log.Info(p.addArgsPrefix(v)...) +} + +// Warn formats message using the default formats for its operands and writes to +// log with LevelWarn. +func (p *PrefixLog) Warn(v ...interface{}) { + p.log.Warn(p.addArgsPrefix(v)...) +} + +// Error formats message using the default formats for its operands and writes +// to log with LevelError. +func (p *PrefixLog) Error(v ...interface{}) { + p.log.Error(p.addArgsPrefix(v)...) +} + +// Critical formats message using the default formats for its operands and +// writes to log with LevelCritical. +func (p *PrefixLog) Critical(v ...interface{}) { + p.log.Critical(p.addArgsPrefix(v)...) +} + +// Level returns the current logging level. +func (p *PrefixLog) Level() btclog.Level { + return p.log.Level() +} + +// SetLevel changes the logging level to the passed level. +func (p *PrefixLog) SetLevel(level btclog.Level) { + p.log.SetLevel(level) +} + +// Assert that PrefixLog fulfills the btclog.Logger interface. +var _ btclog.Logger = &PrefixLog{} From 57562d6c4d231402f6e8a3aa718897a9f7c0fe0a Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Tue, 24 Sep 2019 13:12:53 +0200 Subject: [PATCH 2/5] lnwallet: create channel specific log methods --- lnwallet/channel.go | 110 +++++++++++++++++++++----------------------- 1 file changed, 52 insertions(+), 58 deletions(-) diff --git a/lnwallet/channel.go b/lnwallet/channel.go index 720f5d0d..0f281639 100644 --- a/lnwallet/channel.go +++ b/lnwallet/channel.go @@ -13,10 +13,11 @@ import ( "github.com/btcsuite/btcd/chaincfg/chainhash" "github.com/btcsuite/btcd/txscript" "github.com/btcsuite/btcd/wire" + "github.com/btcsuite/btclog" "github.com/btcsuite/btcutil" "github.com/btcsuite/btcutil/txsort" "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/input" @@ -1377,6 +1378,9 @@ type LightningChannel struct { // channel. RemoteFundingKey *btcec.PublicKey + // log is a channel-specific logging instance. + log btclog.Logger + sync.RWMutex } @@ -1401,6 +1405,8 @@ func NewLightningChannel(signer input.Signer, localCommit.RemoteLogIndex, localCommit.RemoteHtlcIndex, ) + logPrefix := fmt.Sprintf("ChannelPoint(%v):", state.FundingOutpoint) + lc := &LightningChannel{ Signer: signer, sigPool: sigPool, @@ -1416,6 +1422,7 @@ func NewLightningChannel(signer input.Signer, Capacity: state.Capacity, LocalFundingKey: state.LocalChanCfg.MultiSigKey.PubKey, RemoteFundingKey: state.RemoteChanCfg.MultiSigKey.PubKey, + log: build.NewPrefixLog(logPrefix, walletLog), } // With the main channel struct reconstructed, we'll now restore the @@ -1651,8 +1658,8 @@ func (lc *LightningChannel) restoreCommitState( } lc.localCommitChain.addCommitment(localCommit) - walletLog.Debugf("ChannelPoint(%v), starting local commitment: %v", - lc.channelState.FundingOutpoint, newLogClosure(func() string { + lc.log.Debugf("starting local commitment: %v", + newLogClosure(func() string { return spew.Sdump(lc.localCommitChain.tail()) }), ) @@ -1667,8 +1674,8 @@ func (lc *LightningChannel) restoreCommitState( } lc.remoteCommitChain.addCommitment(remoteCommit) - walletLog.Debugf("ChannelPoint(%v), starting remote commitment: %v", - lc.channelState.FundingOutpoint, newLogClosure(func() string { + lc.log.Debugf("starting remote commitment: %v", + newLogClosure(func() string { return spew.Sdump(lc.remoteCommitChain.tail()) }), ) @@ -1702,8 +1709,7 @@ func (lc *LightningChannel) restoreCommitState( } lc.remoteCommitChain.addCommitment(pendingRemoteCommit) - walletLog.Debugf("ChannelPoint(%v), pending remote "+ - "commitment: %v", lc.channelState.FundingOutpoint, + lc.log.Debugf("pending remote commitment: %v", newLogClosure(func() string { return spew.Sdump(lc.remoteCommitChain.tip()) }), @@ -1833,7 +1839,7 @@ func (lc *LightningChannel) restoreStateLogs( lc.localUpdateLog.logIndex > 0 { payDesc.LogIndex = lc.localUpdateLog.logIndex - walletLog.Debugf("Found FeeUpdate on "+ + lc.log.Debugf("Found FeeUpdate on "+ "pendingRemoteCommitDiff without logIndex, "+ "using %v", payDesc.LogIndex) } @@ -3277,14 +3283,14 @@ func (lc *LightningChannel) SignNextCommitment() (lnwire.Sig, []lnwire.Sig, []ch return sig, htlcSigs, nil, err } - walletLog.Tracef("ChannelPoint(%v): extending remote chain to height %v, "+ + lc.log.Tracef("extending remote chain to height %v, "+ "local_log=%v, remote_log=%v", - lc.channelState.FundingOutpoint, newCommitView.height, + newCommitView.height, lc.localUpdateLog.logIndex, remoteACKedIndex) - walletLog.Tracef("ChannelPoint(%v): remote chain: our_balance=%v, "+ + lc.log.Tracef("remote chain: our_balance=%v, "+ "their_balance=%v, commit_tx: %v", - lc.channelState.FundingOutpoint, newCommitView.ourBalance, + newCommitView.ourBalance, newCommitView.theirBalance, newLogClosure(func() string { return spew.Sdump(newCommitView.txn) @@ -3422,9 +3428,8 @@ func (lc *LightningChannel) ProcessChanSyncMsg( // In this case, we'll return an error to indicate the // remote node sent us the wrong values. This will let // the caller act accordingly. - walletLog.Errorf("ChannelPoint(%v), sync failed: "+ - "remote provided invalid commit secret!", - lc.channelState.FundingOutpoint) + lc.log.Errorf("sync failed: remote provided invalid " + + "commit secret!") return nil, nil, nil, ErrInvalidLastCommitSecret } } @@ -3454,15 +3459,12 @@ func (lc *LightningChannel) ProcessChanSyncMsg( // If their reported height for our local chain tail is ahead of our // view, then we're behind! case msg.RemoteCommitTailHeight > localTailHeight || isRestoredChan: - walletLog.Errorf("ChannelPoint(%v), sync failed with local "+ - "data loss: remote believes our tail height is %v, "+ - "while we have %v!", lc.channelState.FundingOutpoint, + lc.log.Errorf("sync failed with local data loss: remote "+ + "believes our tail height is %v, while we have %v!", msg.RemoteCommitTailHeight, localTailHeight) if isRestoredChan { - walletLog.Warnf("ChannelPoint(%v): detected restored "+ - "triggering DLP", - lc.channelState.FundingOutpoint) + lc.log.Warnf("detected restored triggering DLP") } // We must check that we had recovery options to ensure the @@ -3474,9 +3476,9 @@ func (lc *LightningChannel) ProcessChanSyncMsg( // doesn't support data loss protection. In either case // it is not safe for us to keep using the channel, so // we mark it borked and fail the channel. - walletLog.Errorf("ChannelPoint(%v), sync failed: "+ - "local data loss, but no recovery option.", - lc.channelState.FundingOutpoint) + lc.log.Errorf("sync failed: local data loss, but no " + + "recovery option.") + return nil, nil, nil, ErrCannotSyncCommitChains } @@ -3491,9 +3493,8 @@ func (lc *LightningChannel) ProcessChanSyncMsg( // is behind our view of the chain, then they probably lost some state, // and we'll force close the channel. case msg.RemoteCommitTailHeight+1 < localTailHeight: - walletLog.Errorf("ChannelPoint(%v), sync failed: remote "+ - "believes our tail height is %v, while we have %v!", - lc.channelState.FundingOutpoint, + lc.log.Errorf("sync failed: remote believes our tail height is "+ + "%v, while we have %v!", msg.RemoteCommitTailHeight, localTailHeight) return nil, nil, nil, ErrCommitSyncRemoteDataLoss @@ -3506,9 +3507,8 @@ func (lc *LightningChannel) ProcessChanSyncMsg( // this case we'll re-send the last revocation message that we sent. // This will be the revocation message for our prior chain tail. case msg.RemoteCommitTailHeight+1 == localTailHeight: - walletLog.Debugf("ChannelPoint(%v), sync: remote believes "+ - "our tail height is %v, while we have %v, we owe "+ - "them a revocation", lc.channelState.FundingOutpoint, + lc.log.Debugf("sync: remote believes our tail height is %v, "+ + "while we have %v, we owe them a revocation", msg.RemoteCommitTailHeight, localTailHeight) revocationMsg, err := lc.generateRevocation( @@ -3554,9 +3554,8 @@ func (lc *LightningChannel) ProcessChanSyncMsg( // There should be no other possible states. default: - walletLog.Errorf("ChannelPoint(%v), sync failed: remote "+ - "believes our tail height is %v, while we have %v!", - lc.channelState.FundingOutpoint, + lc.log.Errorf("sync failed: remote believes our tail height is "+ + "%v, while we have %v!", msg.RemoteCommitTailHeight, localTailHeight) return nil, nil, nil, ErrCannotSyncCommitChains } @@ -3571,18 +3570,16 @@ func (lc *LightningChannel) ProcessChanSyncMsg( // or not, we will fail the channel, but should not force close it // automatically. case msg.NextLocalCommitHeight > remoteTipHeight+1: - walletLog.Errorf("ChannelPoint(%v), sync failed: remote's "+ - "next commit height is %v, while we believe it is %v!", - lc.channelState.FundingOutpoint, + lc.log.Errorf("sync failed: remote's next commit height is %v, "+ + "while we believe it is %v!", msg.NextLocalCommitHeight, remoteTipHeight) return nil, nil, nil, ErrCannotSyncCommitChains // They are waiting for a state they have already ACKed. case msg.NextLocalCommitHeight <= remoteTailHeight: - walletLog.Errorf("ChannelPoint(%v), sync failed: remote's "+ - "next commit height is %v, while we believe it is %v!", - lc.channelState.FundingOutpoint, + lc.log.Errorf("sync failed: remote's next commit height is %v, "+ + "while we believe it is %v!", msg.NextLocalCommitHeight, remoteTipHeight) // They previously ACKed our current tail, and now they are @@ -3597,9 +3594,8 @@ func (lc *LightningChannel) ProcessChanSyncMsg( // re-send all the updates necessary to recreate this state, along // with the commit sig. case msg.NextLocalCommitHeight == remoteTipHeight: - walletLog.Debugf("ChannelPoint(%v), sync: remote's next "+ - "commit height is %v, while we believe it is %v, we "+ - "owe them a commitment", lc.channelState.FundingOutpoint, + lc.log.Debugf("sync: remote's next commit height is %v, while "+ + "we believe it is %v, we owe them a commitment", msg.NextLocalCommitHeight, remoteTipHeight) // Grab the current remote chain tip from the database. This @@ -3628,9 +3624,8 @@ func (lc *LightningChannel) ProcessChanSyncMsg( // can have at most two elements. If that's the case, something is // wrong. default: - walletLog.Errorf("ChannelPoint(%v), sync failed: remote's "+ - "next commit height is %v, while we believe it is %v!", - lc.channelState.FundingOutpoint, + lc.log.Errorf("sync failed: remote's next commit height is %v, "+ + "while we believe it is %v!", msg.NextLocalCommitHeight, remoteTipHeight) return nil, nil, nil, ErrCannotSyncCommitChains } @@ -3668,9 +3663,8 @@ func (lc *LightningChannel) ProcessChanSyncMsg( if !tweakless && commitPoint != nil && !commitPoint.IsEqual(msg.LocalUnrevokedCommitPoint) { - walletLog.Errorf("ChannelPoint(%v), sync failed: remote "+ - "sent invalid commit point for height %v!", - lc.channelState.FundingOutpoint, + lc.log.Errorf("sync failed: remote sent invalid commit point "+ + "for height %v!", msg.NextLocalCommitHeight) return nil, nil, nil, ErrInvalidLocalUnrevokedCommitPoint } @@ -4032,13 +4026,13 @@ func (lc *LightningChannel) ReceiveNewCommitment(commitSig lnwire.Sig, return err } - walletLog.Tracef("ChannelPoint(%v): extending local chain to height %v, "+ + lc.log.Tracef("extending local chain to height %v, "+ "local_log=%v, remote_log=%v", - lc.channelState.FundingOutpoint, localCommitmentView.height, + localCommitmentView.height, localACKedIndex, lc.remoteUpdateLog.logIndex) - walletLog.Tracef("ChannelPoint(%v): local chain: our_balance=%v, "+ - "their_balance=%v, commit_tx: %v", lc.channelState.FundingOutpoint, + lc.log.Tracef("local chain: our_balance=%v, "+ + "their_balance=%v, commit_tx: %v", localCommitmentView.ourBalance, localCommitmentView.theirBalance, newLogClosure(func() string { return spew.Sdump(localCommitmentView.txn) @@ -4180,8 +4174,8 @@ func (lc *LightningChannel) RevokeCurrentCommitment() (*lnwire.RevokeAndAck, []c return nil, nil, err } - walletLog.Tracef("ChannelPoint(%v): revoking height=%v, now at height=%v", - lc.channelState.FundingOutpoint, lc.localCommitChain.tail().height, + lc.log.Tracef("revoking height=%v, now at height=%v", + lc.localCommitChain.tail().height, lc.currentHeight+1) // Advance our tail, as we've revoked our previous state. @@ -4197,9 +4191,9 @@ func (lc *LightningChannel) RevokeCurrentCommitment() (*lnwire.RevokeAndAck, []c return nil, nil, err } - walletLog.Tracef("ChannelPoint(%v): state transition accepted: "+ + lc.log.Tracef("state transition accepted: "+ "our_balance=%v, their_balance=%v", - lc.channelState.FundingOutpoint, chainTail.ourBalance, + chainTail.ourBalance, chainTail.theirBalance) revocationMsg.ChanID = lnwire.NewChanIDFromOutPoint( @@ -4259,8 +4253,8 @@ func (lc *LightningChannel) ReceiveRevocation(revMsg *lnwire.RevokeAndAck) ( lc.channelState.RemoteCurrentRevocation = lc.channelState.RemoteNextRevocation lc.channelState.RemoteNextRevocation = revMsg.NextRevocationKey - walletLog.Tracef("ChannelPoint(%v): remote party accepted state transition, "+ - "revoked height %v, now at %v", lc.channelState.FundingOutpoint, + lc.log.Tracef("remote party accepted state transition, revoked height "+ + "%v, now at %v", lc.remoteCommitChain.tail().height, lc.remoteCommitChain.tail().height+1) From 03ed1b0aa3f8f68a4a702cda4c00663603d2b3e3 Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Tue, 1 Oct 2019 11:06:56 +0200 Subject: [PATCH 3/5] htlcswitch: use prefix logger in link --- htlcswitch/link.go | 170 ++++++++++++++++++++------------------------- 1 file changed, 76 insertions(+), 94 deletions(-) diff --git a/htlcswitch/link.go b/htlcswitch/link.go index 0539bde1..bccb8ec4 100644 --- a/htlcswitch/link.go +++ b/htlcswitch/link.go @@ -11,8 +11,10 @@ import ( "time" "github.com/btcsuite/btcd/wire" + "github.com/btcsuite/btclog" "github.com/davecgh/go-spew/spew" "github.com/go-errors/errors" + "github.com/lightningnetwork/lnd/build" "github.com/lightningnetwork/lnd/channeldb" "github.com/lightningnetwork/lnd/contractcourt" "github.com/lightningnetwork/lnd/htlcswitch/hodl" @@ -377,6 +379,9 @@ type channelLink struct { // resolving those htlcs when we receive a message on hodlQueue. hodlMap map[channeldb.CircuitKey]hodlHtlc + // log is a link-specific logging instance. + log btclog.Logger + wg sync.WaitGroup quit chan struct{} } @@ -392,6 +397,8 @@ type hodlHtlc struct { func NewChannelLink(cfg ChannelLinkConfig, channel *lnwallet.LightningChannel) ChannelLink { + logPrefix := fmt.Sprintf("ChannelLink(%v):", channel.ShortChanID()) + return &channelLink{ cfg: cfg, channel: channel, @@ -402,6 +409,7 @@ func NewChannelLink(cfg ChannelLinkConfig, htlcUpdates: make(chan *contractcourt.ContractUpdate), hodlMap: make(map[channeldb.CircuitKey]hodlHtlc), hodlQueue: queue.NewConcurrentQueue(10), + log: build.NewPrefixLog(logPrefix, log), quit: make(chan struct{}), } } @@ -723,7 +731,7 @@ func (l *channelLink) resolveFwdPkgs() error { return err } - l.debugf("loaded %d fwd pks", len(fwdPkgs)) + l.log.Debugf("loaded %d fwd pks", len(fwdPkgs)) var needUpdate bool for _, fwdPkg := range fwdPkgs { @@ -750,13 +758,13 @@ func (l *channelLink) resolveFwdPkgs() error { func (l *channelLink) resolveFwdPkg(fwdPkg *channeldb.FwdPkg) (bool, error) { // Remove any completed packages to clear up space. if fwdPkg.State == channeldb.FwdStateCompleted { - l.debugf("removing completed fwd pkg for height=%d", + l.log.Debugf("removing completed fwd pkg for height=%d", fwdPkg.Height) err := l.channel.RemoveFwdPkg(fwdPkg.Height) if err != nil { - l.errorf("unable to remove fwd pkg for height=%d: %v", - fwdPkg.Height, err) + l.log.Errorf("unable to remove fwd pkg for height=%d: "+ + "%v", fwdPkg.Height, err) return false, err } } @@ -774,7 +782,7 @@ func (l *channelLink) resolveFwdPkg(fwdPkg *channeldb.FwdPkg) (bool, error) { fwdPkg.Source, fwdPkg.Height, fwdPkg.SettleFails, ) if err != nil { - l.errorf("Unable to process remote log updates: %v", + l.log.Errorf("Unable to process remote log updates: %v", err) return false, err } @@ -791,7 +799,7 @@ func (l *channelLink) resolveFwdPkg(fwdPkg *channeldb.FwdPkg) (bool, error) { fwdPkg.Source, fwdPkg.Height, fwdPkg.Adds, ) if err != nil { - l.errorf("Unable to process remote log updates: %v", + l.log.Errorf("Unable to process remote log updates: %v", err) return false, err } @@ -826,7 +834,8 @@ func (l *channelLink) fwdPkgGarbager() { case <-l.cfg.FwdPkgGCTicker.Ticks(): fwdPkgs, err := l.channel.LoadFwdPkgs() if err != nil { - l.warnf("unable to load fwdpkgs for gc: %v", err) + l.log.Warnf("unable to load fwdpkgs for gc: %v", + err) continue } @@ -838,7 +847,7 @@ func (l *channelLink) fwdPkgGarbager() { err = l.channel.RemoveFwdPkg(fwdPkg.Height) if err != nil { - l.warnf("unable to remove fwd pkg "+ + l.log.Warnf("unable to remove fwd pkg "+ "for height=%d: %v", fwdPkg.Height, err) } @@ -1007,7 +1016,7 @@ out: // We must always check if we failed at some point processing // the last update before processing the next. if l.failed { - l.errorf("link failed, exiting htlcManager") + l.log.Errorf("link failed, exiting htlcManager") break out } @@ -1223,7 +1232,7 @@ func (l *channelLink) processHodlEvent(hodlEvent invoices.HodlEvent, // Determine required action for the resolution. if hodlEvent.Preimage != nil { - l.debugf("Received hodl settle event for %v", circuitKey) + l.log.Debugf("Received hodl settle event for %v", circuitKey) return l.settleHTLC( *hodlEvent.Preimage, htlc.pd.HtlcIndex, @@ -1231,7 +1240,7 @@ func (l *channelLink) processHodlEvent(hodlEvent invoices.HodlEvent, ) } - l.debugf("Received hodl cancel event for %v", circuitKey) + l.log.Debugf("Received hodl cancel event for %v", circuitKey) // In case of a cancel, always return // incorrect_or_unknown_payment_details in order to avoid leaking info. @@ -1269,7 +1278,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { // arbitrary delays between the switch adding an ADD to the // mailbox, and the HTLC being added to the commitment state. if l.cfg.HodlMask.Active(hodl.AddOutgoing) { - l.warnf(hodl.AddOutgoing.Warning()) + l.log.Warnf(hodl.AddOutgoing.Warning()) l.mailBox.AckPacket(pkt.inKey()) return } @@ -1286,7 +1295,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { // The channels spare bandwidth is fully allocated, so // we'll put this HTLC into the overflow queue. case lnwallet.ErrMaxHTLCNumber: - l.infof("Downstream htlc add update with "+ + l.log.Infof("Downstream htlc add update with "+ "payment hash(%x) have been added to "+ "reprocessing queue, batch: %v", htlc.PaymentHash[:], @@ -1299,7 +1308,8 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { // machine, as a result, we'll signal the switch to // cancel the pending payment. default: - l.warnf("Unable to handle downstream add HTLC: %v", err) + l.log.Warnf("Unable to handle downstream add "+ + "HTLC: %v", err) var ( localFailure = false @@ -1324,7 +1334,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { var b bytes.Buffer err := lnwire.EncodeFailure(&b, failure, 0) if err != nil { - l.errorf("unable to encode failure: %v", err) + l.log.Errorf("unable to encode failure: %v", err) l.mailBox.AckPacket(pkt.inKey()) return } @@ -1334,7 +1344,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { var err error reason, err = pkt.obfuscator.EncryptFirstHop(failure) if err != nil { - l.errorf("unable to obfuscate error: %v", err) + l.log.Errorf("unable to obfuscate error: %v", err) l.mailBox.AckPacket(pkt.inKey()) return } @@ -1369,7 +1379,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { } } - l.tracef("Received downstream htlc: payment_hash=%x, "+ + l.log.Tracef("Received downstream htlc: payment_hash=%x, "+ "local_log_index=%v, batch_size=%v", htlc.PaymentHash[:], index, l.batchCounter+1) @@ -1377,7 +1387,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { pkt.outgoingHTLCID = index htlc.ID = index - l.debugf("Queueing keystone of ADD open circuit: %s->%s", + l.log.Debugf("Queueing keystone of ADD open circuit: %s->%s", pkt.inKey(), pkt.outKey()) l.openedCircuits = append(l.openedCircuits, pkt.inKey()) @@ -1391,7 +1401,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { // SETTLE to the mailbox, and the HTLC being added to the // commitment state. if l.cfg.HodlMask.Active(hodl.SettleOutgoing) { - l.warnf(hodl.SettleOutgoing.Warning()) + l.log.Warnf(hodl.SettleOutgoing.Warning()) l.mailBox.AckPacket(pkt.inKey()) return } @@ -1408,7 +1418,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { &inKey, ) if err != nil { - l.errorf("unable to settle incoming HTLC for "+ + l.log.Errorf("unable to settle incoming HTLC for "+ "circuit-key=%v: %v", inKey, err) // If the HTLC index for Settle response was not known @@ -1427,8 +1437,8 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { return } - l.debugf("Queueing removal of SETTLE closed circuit: %s->%s", - pkt.inKey(), pkt.outKey()) + l.log.Debugf("Queueing removal of SETTLE closed circuit: "+ + "%s->%s", pkt.inKey(), pkt.outKey()) l.closedCircuits = append(l.closedCircuits, pkt.inKey()) @@ -1449,7 +1459,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { // the mailbox, and the HTLC being added to the commitment // state. if l.cfg.HodlMask.Active(hodl.FailOutgoing) { - l.warnf(hodl.FailOutgoing.Warning()) + l.log.Warnf(hodl.FailOutgoing.Warning()) l.mailBox.AckPacket(pkt.inKey()) return } @@ -1465,7 +1475,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { &inKey, ) if err != nil { - l.errorf("unable to cancel incoming HTLC for "+ + l.log.Errorf("unable to cancel incoming HTLC for "+ "circuit-key=%v: %v", inKey, err) // If the HTLC index for Fail response was not known to @@ -1484,7 +1494,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { return } - l.debugf("Queueing removal of FAIL closed circuit: %s->%s", + l.log.Debugf("Queueing removal of FAIL closed circuit: %s->%s", pkt.inKey(), pkt.outKey()) l.closedCircuits = append(l.closedCircuits, pkt.inKey()) @@ -1522,13 +1532,13 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { func (l *channelLink) cleanupSpuriousResponse(pkt *htlcPacket) { inKey := pkt.inKey() - l.debugf("Cleaning up spurious response for incoming circuit-key=%v", - inKey) + l.log.Debugf("Cleaning up spurious response for incoming "+ + "circuit-key=%v", inKey) // If the htlc packet doesn't have a source reference, it is unsafe to // proceed, as skipping this ack may cause the htlc to be reforwarded. if pkt.sourceRef == nil { - l.errorf("uanble to cleanup response for incoming "+ + l.log.Errorf("uanble to cleanup response for incoming "+ "circuit-key=%v, does not contain source reference", inKey) return @@ -1539,7 +1549,7 @@ func (l *channelLink) cleanupSpuriousResponse(pkt *htlcPacket) { // of the incoming HTLC belonging to this link. err := l.channel.AckAddHtlcs(*pkt.sourceRef) if err != nil { - l.errorf("unable to ack AddRef for incoming "+ + l.log.Errorf("unable to ack AddRef for incoming "+ "circuit-key=%v: %v", inKey, err) // If this operation failed, it is unsafe to attempt removal of @@ -1562,19 +1572,19 @@ func (l *channelLink) cleanupSpuriousResponse(pkt *htlcPacket) { if pkt.destRef != nil { err := l.channel.AckSettleFails(*pkt.destRef) if err != nil { - l.errorf("unable to ack SettleFailRef "+ + l.log.Errorf("unable to ack SettleFailRef "+ "for incoming circuit-key=%v: %v", inKey, err) } } - l.debugf("Deleting circuit for incoming circuit-key=%x", inKey) + l.log.Debugf("Deleting circuit for incoming circuit-key=%x", inKey) // With all known references acked, we can now safely delete the circuit // from the switch's circuit map, as the state is no longer needed. err = l.cfg.Circuits.DeleteCircuits(inKey) if err != nil { - l.errorf("unable to delete circuit for "+ + l.log.Errorf("unable to delete circuit for "+ "circuit-key=%v: %v", inKey, err) } } @@ -1596,7 +1606,7 @@ func (l *channelLink) handleUpstreamMsg(msg lnwire.Message) { return } - l.tracef("Receive upstream htlc with payment hash(%x), "+ + l.log.Tracef("Receive upstream htlc with payment hash(%x), "+ "assigning index: %v", msg.PaymentHash[:], index) case *lnwire.UpdateFulfillHTLC: @@ -1670,7 +1680,7 @@ func (l *channelLink) handleUpstreamMsg(msg lnwire.Message) { // form. var b bytes.Buffer if err := lnwire.EncodeFailure(&b, failure, 0); err != nil { - l.errorf("unable to encode malformed error: %v", err) + l.log.Errorf("unable to encode malformed error: %v", err) return } @@ -1918,7 +1928,7 @@ func (l *channelLink) ackDownStreamPackets() error { continue } - l.debugf("removing Add packet %s from mailbox", inKey) + l.log.Debugf("removing Add packet %s from mailbox", inKey) l.mailBox.AckPacket(inKey) } @@ -1932,7 +1942,7 @@ func (l *channelLink) ackDownStreamPackets() error { // Successful deletion. default: - l.errorf("unable to delete %d circuits: %v", + l.log.Errorf("unable to delete %d circuits: %v", len(l.closedCircuits), err) return err } @@ -1943,7 +1953,8 @@ func (l *channelLink) ackDownStreamPackets() error { // the circuits must have been removed at some point, so it is now safe // to un-queue the corresponding Settle/Fails. for _, inKey := range l.closedCircuits { - l.debugf("removing Fail/Settle packet %s from mailbox", inKey) + l.log.Debugf("removing Fail/Settle packet %s from mailbox", + inKey) l.mailBox.AckPacket(inKey) } @@ -1975,14 +1986,14 @@ func (l *channelLink) updateCommitTx() error { // permits testing of either the switch or link's ability to trim // circuits that have been opened, but unsuccessfully committed. if l.cfg.HodlMask.Active(hodl.Commit) { - l.warnf(hodl.Commit.Warning()) + l.log.Warnf(hodl.Commit.Warning()) return nil } theirCommitSig, htlcSigs, pendingHTLCs, err := l.channel.SignNextCommitment() if err == lnwallet.ErrNoWindow { - l.tracef("revocation window exhausted, unable to send: %v, "+ - "dangling_opens=%v, dangling_closes%v", + l.log.Tracef("revocation window exhausted, unable to send: "+ + "%v, dangling_opens=%v, dangling_closes%v", l.batchCounter, newLogClosure(func() string { return spew.Sdump(l.openedCircuits) }), @@ -2076,14 +2087,14 @@ func (l *channelLink) UpdateShortChanID() (lnwire.ShortChannelID, error) { // short channel ID. err := l.channel.State().RefreshShortChanID() if err != nil { - l.errorf("unable to refresh short_chan_id for chan_id=%v: %v", - chanID, err) + l.log.Errorf("unable to refresh short_chan_id for chan_id=%v: "+ + "%v", chanID, err) return hop.Source, err } sid := l.channel.ShortChanID() - l.infof("Updating to short_chan_id=%v for chan_id=%v", sid, chanID) + l.log.Infof("Updating to short_chan_id=%v for chan_id=%v", sid, chanID) l.Lock() l.shortChanID = sid @@ -2205,8 +2216,9 @@ func (l *channelLink) HtlcSatifiesPolicy(payHash [32]byte, // any case, we'll cancel this HTLC. actualFee := incomingHtlcAmt - amtToForward if incomingHtlcAmt < amtToForward || actualFee < expectedFee { - l.errorf("outgoing htlc(%x) has insufficient fee: expected %v, "+ - "got %v", payHash[:], int64(expectedFee), int64(actualFee)) + l.log.Errorf("outgoing htlc(%x) has insufficient fee: "+ + "expected %v, got %v", + payHash[:], int64(expectedFee), int64(actualFee)) // As part of the returned error, we'll send our latest routing // policy so the sending node obtains the most up to date data. @@ -2229,7 +2241,7 @@ func (l *channelLink) HtlcSatifiesPolicy(payHash [32]byte, // sender messed up, or an intermediate node tampered with the HTLC. timeDelta := policy.TimeLockDelta if incomingTimeout < outgoingTimeout+timeDelta { - l.errorf("Incoming htlc(%x) has incorrect time-lock value: "+ + l.log.Errorf("Incoming htlc(%x) has incorrect time-lock value: "+ "expected at least %v block delta, got %v block delta", payHash[:], timeDelta, incomingTimeout-outgoingTimeout) @@ -2281,7 +2293,7 @@ func (l *channelLink) htlcSatifiesPolicyOutgoing(policy ForwardingPolicy, // too small for the next hop. If so, then we'll cancel the HTLC // directly. if amt < policy.MinHTLC { - l.errorf("outgoing htlc(%x) is too small: min_htlc=%v, "+ + l.log.Errorf("outgoing htlc(%x) is too small: min_htlc=%v, "+ "htlc_value=%v", payHash[:], policy.MinHTLC, amt) @@ -2303,7 +2315,7 @@ func (l *channelLink) htlcSatifiesPolicyOutgoing(policy ForwardingPolicy, // Next, ensure that the passed HTLC isn't too large. If so, we'll cancel // the HTLC directly. if policy.MaxHTLC != 0 && amt > policy.MaxHTLC { - l.errorf("outgoing htlc(%x) is too large: max_htlc=%v, "+ + l.log.Errorf("outgoing htlc(%x) is too large: max_htlc=%v, "+ "htlc_value=%v", payHash[:], policy.MaxHTLC, amt) // As part of the returned error, we'll send our latest routing policy @@ -2323,7 +2335,7 @@ func (l *channelLink) htlcSatifiesPolicyOutgoing(policy ForwardingPolicy, // future, so we'll reject an HTLC if the outgoing expiration time is // too close to the current height. if timeout <= heightNow+l.cfg.OutgoingCltvRejectDelta { - l.errorf("htlc(%x) has an expiry that's too soon: "+ + l.log.Errorf("htlc(%x) has an expiry that's too soon: "+ "outgoing_expiry=%v, best_height=%v", payHash[:], timeout, heightNow) @@ -2342,8 +2354,8 @@ func (l *channelLink) htlcSatifiesPolicyOutgoing(policy ForwardingPolicy, // Check absolute max delta. if timeout > l.cfg.MaxOutgoingCltvExpiry+heightNow { - l.errorf("outgoing htlc(%x) has a time lock too far in the "+ - "future: got %v, but maximum is %v", payHash[:], + l.log.Errorf("outgoing htlc(%x) has a time lock too far in "+ + "the future: got %v, but maximum is %v", payHash[:], timeout-heightNow, l.cfg.MaxOutgoingCltvExpiry) return &lnwire.FailExpiryTooFar{} @@ -2376,7 +2388,7 @@ func (l *channelLink) String() string { // // NOTE: Part of the ChannelLink interface. func (l *channelLink) HandleSwitchPacket(pkt *htlcPacket) error { - l.tracef("received switch packet inkey=%v, outkey=%v", + l.log.Tracef("received switch packet inkey=%v, outkey=%v", pkt.inKey(), pkt.outKey()) l.mailBox.AddPacket(pkt) @@ -2457,7 +2469,7 @@ func (l *channelLink) processRemoteSettleFails(fwdPkg *channeldb.FwdPkg, // forward the SETTLE to the switch and will not signal // a free slot on the commitment transaction. if l.cfg.HodlMask.Active(hodl.SettleIncoming) { - l.warnf(hodl.SettleIncoming.Warning()) + l.log.Warnf(hodl.SettleIncoming.Warning()) continue } @@ -2485,7 +2497,7 @@ func (l *channelLink) processRemoteSettleFails(fwdPkg *channeldb.FwdPkg, // forward the FAIL to the switch and will not signal a // free slot on the commitment transaction. if l.cfg.HodlMask.Active(hodl.FailIncoming) { - l.warnf(hodl.FailIncoming.Warning()) + l.log.Warnf(hodl.FailIncoming.Warning()) continue } @@ -2537,7 +2549,7 @@ func (l *channelLink) processRemoteSettleFails(fwdPkg *channeldb.FwdPkg, func (l *channelLink) processRemoteAdds(fwdPkg *channeldb.FwdPkg, lockedInHtlcs []*lnwallet.PaymentDescriptor) bool { - l.tracef("processing %d remote adds for height %d", + l.log.Tracef("processing %d remote adds for height %d", len(lockedInHtlcs), fwdPkg.Height) decodeReqs := make( @@ -2687,7 +2699,7 @@ func (l *channelLink) processRemoteAdds(fwdPkg *channeldb.FwdPkg, // validate the forwarded ADD, nor will we send the // packet to the htlc switch. if l.cfg.HodlMask.Active(hodl.AddIncoming) { - l.warnf(hodl.AddIncoming.Warning()) + l.log.Warnf(hodl.AddIncoming.Warning()) continue } @@ -2824,7 +2836,7 @@ func (l *channelLink) processRemoteAdds(fwdPkg *channeldb.FwdPkg, return needUpdate } - l.debugf("forwarding %d packets to switch", len(switchPackets)) + l.log.Debugf("forwarding %d packets to switch", len(switchPackets)) // NOTE: This call is made synchronous so that we ensure all circuits // are committed in the exact order that they are processed in the link. @@ -2846,7 +2858,7 @@ func (l *channelLink) processExitHop(pd *lnwallet.PaymentDescriptor, // ADD, nor will we settle the corresponding invoice or respond with the // preimage. if l.cfg.HodlMask.Active(hodl.ExitSettle) { - l.warnf(hodl.ExitSettle.Warning()) + l.log.Warnf(hodl.ExitSettle.Warning()) return false, nil } @@ -2938,7 +2950,7 @@ func (l *channelLink) settleHTLC(preimage lntypes.Preimage, htlcIndex uint64, hash := preimage.Hash() - l.infof("settling htlc %v as exit hop", hash) + l.log.Infof("settling htlc %v as exit hop", hash) err := l.channel.SettleHTLC( preimage, htlcIndex, sourceRef, nil, nil, @@ -2950,7 +2962,7 @@ func (l *channelLink) settleHTLC(preimage lntypes.Preimage, htlcIndex uint64, // If the link is in hodl.BogusSettle mode, replace the preimage with a // fake one before sending it to the peer. if l.cfg.HodlMask.Active(hodl.BogusSettle) { - l.warnf(hodl.BogusSettle.Warning()) + l.log.Warnf(hodl.BogusSettle.Warning()) preimage = [32]byte{} copy(preimage[:], bytes.Repeat([]byte{2}, 32)) } @@ -3001,7 +3013,7 @@ func (l *channelLink) handleBatchFwdErrs(errChan chan error) { continue } - l.errorf("unhandled error while forwarding htlc packet over "+ + l.log.Errorf("unhandled error while forwarding htlc packet over "+ "htlcswitch: %v", err) } } @@ -3061,45 +3073,15 @@ func (l *channelLink) fail(linkErr LinkFailureError, // Return if we have already notified about a failure. if l.failed { - l.warnf("Ignoring link failure (%v), as link already failed", - reason) + l.log.Warnf("Ignoring link failure (%v), as link already "+ + "failed", reason) return } - l.errorf("Failing link: %s", reason) + l.log.Errorf("Failing link: %s", reason) // Set failed, such that we won't process any more updates, and notify // the peer about the failure. l.failed = true l.cfg.OnChannelFailure(l.ChanID(), l.ShortChanID(), linkErr) } - -// infof prefixes the channel's identifier before printing to info log. -func (l *channelLink) infof(format string, a ...interface{}) { - msg := fmt.Sprintf(format, a...) - log.Infof("ChannelLink(%s) %s", l.ShortChanID(), msg) -} - -// debugf prefixes the channel's identifier before printing to debug log. -func (l *channelLink) debugf(format string, a ...interface{}) { - msg := fmt.Sprintf(format, a...) - log.Debugf("ChannelLink(%s) %s", l.ShortChanID(), msg) -} - -// warnf prefixes the channel's identifier before printing to warn log. -func (l *channelLink) warnf(format string, a ...interface{}) { - msg := fmt.Sprintf(format, a...) - log.Warnf("ChannelLink(%s) %s", l.ShortChanID(), msg) -} - -// errorf prefixes the channel's identifier before printing to error log. -func (l *channelLink) errorf(format string, a ...interface{}) { - msg := fmt.Sprintf(format, a...) - log.Errorf("ChannelLink(%s) %s", l.ShortChanID(), msg) -} - -// tracef prefixes the channel's identifier before printing to trace log. -func (l *channelLink) tracef(format string, a ...interface{}) { - msg := fmt.Sprintf(format, a...) - log.Tracef("ChannelLink(%s) %s", l.ShortChanID(), msg) -} From 654b3cc7183c9c7876e52cfe125fbfca0f16d7dd Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Tue, 1 Oct 2019 11:16:24 +0200 Subject: [PATCH 4/5] htlcswitch: use prefix logger for remaining log statements in link --- htlcswitch/link.go | 98 ++++++++++++++++++----------------------- htlcswitch/link_test.go | 1 + 2 files changed, 45 insertions(+), 54 deletions(-) diff --git a/htlcswitch/link.go b/htlcswitch/link.go index bccb8ec4..97581ae7 100644 --- a/htlcswitch/link.go +++ b/htlcswitch/link.go @@ -425,11 +425,11 @@ var _ ChannelLink = (*channelLink)(nil) func (l *channelLink) Start() error { if !atomic.CompareAndSwapInt32(&l.started, 0, 1) { err := errors.Errorf("channel link(%v): already started", l) - log.Warn(err) + l.log.Warn("already started") return err } - log.Infof("ChannelLink(%v) is starting", l) + l.log.Info("starting") // If the config supplied watchtower client, ensure the channel is // registered before trying to use it during operation. @@ -482,8 +482,7 @@ func (l *channelLink) Start() error { err := l.cfg.UpdateContractSignals(signals) if err != nil { - log.Errorf("Unable to update signals for "+ - "ChannelLink(%v)", l) + l.log.Errorf("Unable to update signals") } }() } @@ -502,11 +501,11 @@ func (l *channelLink) Start() error { // NOTE: Part of the ChannelLink interface. func (l *channelLink) Stop() { if !atomic.CompareAndSwapInt32(&l.shutdown, 0, 1) { - log.Warnf("channel link(%v): already stopped", l) + l.log.Warn("already stopped") return } - log.Infof("ChannelLink(%v) is stopping", l) + l.log.Info("stopping") // As the link is stopping, we are no longer interested in hodl events // coming from the invoice registry. @@ -531,7 +530,7 @@ func (l *channelLink) Stop() { // we had learned them at some point. err := l.cfg.PreimageCache.AddPreimages(l.uncommittedPreimages...) if err != nil { - log.Errorf("Unable to add preimages=%v to cache: %v", + l.log.Errorf("Unable to add preimages=%v to cache: %v", l.uncommittedPreimages, err) } } @@ -578,8 +577,8 @@ func (l *channelLink) sampleNetworkFee() (lnwallet.SatPerKWeight, error) { return 0, err } - log.Debugf("ChannelLink(%v): sampled fee rate for 3 block conf: %v "+ - "sat/kw", l, int64(feePerKw)) + l.log.Debugf("sampled fee rate for 3 block conf: %v sat/kw", + int64(feePerKw)) return feePerKw, nil } @@ -610,8 +609,7 @@ func shouldAdjustCommitFee(netFee, chanFee lnwallet.SatPerKWeight) bool { // flow. We'll compare out commitment chains with the remote party, and re-send // either a danging commit signature, a revocation, or both. func (l *channelLink) syncChanStates() error { - log.Infof("Attempting to re-resynchronize ChannelPoint(%v)", - l.channel.ChannelPoint()) + l.log.Info("Attempting to re-resynchronize") // First, we'll generate our ChanSync message to send to the other // side. Based on this message, the remote party will decide if they @@ -650,9 +648,7 @@ func (l *channelLink) syncChanStates() error { localChanSyncMsg.NextLocalCommitHeight == 1 && !l.channel.IsPending() { - log.Infof("ChannelPoint(%v): resending "+ - "FundingLocked message to peer", - l.channel.ChannelPoint()) + l.log.Infof("resending FundingLocked message to peer") nextRevocation, err := l.channel.NextRevocationKey() if err != nil { @@ -671,8 +667,7 @@ func (l *channelLink) syncChanStates() error { } // In any case, we'll then process their ChanSync message. - log.Infof("Received re-establishment message from remote side "+ - "for channel(%v)", l.channel.ChannelPoint()) + l.log.Info("Received re-establishment message from remote side") var ( openedCircuits []CircuitKey @@ -701,9 +696,8 @@ func (l *channelLink) syncChanStates() error { } if len(msgsToReSend) > 0 { - log.Infof("Sending %v updates to synchronize the "+ - "state for ChannelPoint(%v)", len(msgsToReSend), - l.channel.ChannelPoint()) + l.log.Infof("Sending %v updates to synchronize the "+ + "state", len(msgsToReSend)) } // If we have any messages to retransmit, we'll do so @@ -872,11 +866,10 @@ func (l *channelLink) htlcManager() { defer func() { l.cfg.BatchTicker.Stop() l.wg.Done() - log.Infof("ChannelLink(%v) has exited", l) + l.log.Infof("exited") }() - log.Infof("HTLC manager for ChannelPoint(%v) started, "+ - "bandwidth=%v", l.channel.ChannelPoint(), l.Bandwidth()) + l.log.Infof("HTLC manager started, bandwidth=%v", l.Bandwidth()) // TODO(roasbeef): need to call wipe chan whenever D/C? @@ -887,14 +880,14 @@ func (l *channelLink) htlcManager() { if l.cfg.SyncStates { err := l.syncChanStates() if err != nil { - log.Warnf("Error when syncing channel states: %v", err) + l.log.Warnf("Error when syncing channel states: %v", err) errDataLoss, localDataLoss := err.(*lnwallet.ErrCommitSyncLocalDataLoss) switch { case err == ErrLinkShuttingDown: - log.Debugf("unable to sync channel states, " + + l.log.Debugf("unable to sync channel states, " + "link is shutting down") return @@ -942,7 +935,7 @@ func (l *channelLink) htlcManager() { errDataLoss.CommitPoint, ) if err != nil { - log.Errorf("Unable to mark channel "+ + l.log.Errorf("Unable to mark channel "+ "data loss: %v", err) } @@ -953,7 +946,7 @@ func (l *channelLink) htlcManager() { // cases where this error is returned? case err == lnwallet.ErrCannotSyncCommitChains: if err := l.channel.MarkBorked(); err != nil { - log.Errorf("Unable to mark channel "+ + l.log.Errorf("Unable to mark channel "+ "borked: %v", err) } @@ -1044,7 +1037,8 @@ out: // blocks. netFee, err := l.sampleNetworkFee() if err != nil { - log.Errorf("unable to sample network fee: %v", err) + l.log.Errorf("unable to sample network fee: %v", + err) continue } @@ -1063,7 +1057,8 @@ out: // If we do, then we'll send a new UpdateFee message to // the remote party, to be locked in with a new update. if err := l.updateChannelFee(newCommitFee); err != nil { - log.Errorf("unable to update fee rate: %v", err) + l.log.Errorf("unable to update fee rate: %v", + err) continue } @@ -1074,15 +1069,15 @@ out: // // TODO(roasbeef): add force closure? also breach? case <-l.cfg.ChainEvents.RemoteUnilateralClosure: - log.Warnf("Remote peer has closed ChannelPoint(%v) on-chain", - l.channel.ChannelPoint()) + l.log.Warnf("Remote peer has closed on-chain") // TODO(roasbeef): remove all together go func() { chanPoint := l.channel.ChannelPoint() err := l.cfg.Peer.WipeChannel(chanPoint) if err != nil { - log.Errorf("unable to wipe channel %v", err) + l.log.Errorf("unable to wipe channel "+ + "%v", err) } }() @@ -1129,7 +1124,7 @@ out: // to continue propagating within the network. case packet := <-l.overflowQueue.outgoingPkts: msg := packet.htlc.(*lnwire.UpdateAddHTLC) - log.Tracef("Reprocessing downstream add update "+ + l.log.Tracef("Reprocessing downstream add update "+ "with payment hash(%x)", msg.PaymentHash[:]) l.handleDownStreamPkt(packet, true) @@ -1144,7 +1139,7 @@ out: // failed, then we'll free up a new slot. htlc, ok := pkt.htlc.(*lnwire.UpdateAddHTLC) if ok && l.overflowQueue.Length() != 0 { - log.Infof("Downstream htlc add update with "+ + l.log.Infof("Downstream htlc add update with "+ "payment hash(%x) have been added to "+ "reprocessing queue, batch_size=%v", htlc.PaymentHash[:], @@ -1659,7 +1654,7 @@ func (l *channelLink) handleUpstreamMsg(msg lnwire.Message) { OnionSHA256: msg.ShaOnionBlob, } default: - log.Warnf("Unexpected failure code received in "+ + l.log.Warnf("Unexpected failure code received in "+ "UpdateFailMailformedHTLC: %v", msg.FailureCode) // We don't just pass back the error we received from @@ -1767,7 +1762,7 @@ func (l *channelLink) handleUpstreamMsg(msg lnwire.Message) { // state. nextRevocation, currentHtlcs, err := l.channel.RevokeCurrentCommitment() if err != nil { - log.Errorf("unable to revoke commitment: %v", err) + l.log.Errorf("unable to revoke commitment: %v", err) return } l.cfg.Peer.SendMessage(false, nextRevocation) @@ -1903,8 +1898,7 @@ func (l *channelLink) handleUpstreamMsg(msg lnwire.Message) { "ChannelPoint(%v): received error from peer: %v", l.channel.ChannelPoint(), msg.Error()) default: - log.Warnf("ChannelPoint(%v): received unknown message of type %T", - l.channel.ChannelPoint(), msg) + l.log.Warnf("received unknown message of type %T", msg) } } @@ -2106,8 +2100,7 @@ func (l *channelLink) UpdateShortChanID() (lnwire.ShortChannelID, error) { ShortChanID: sid, }) if err != nil { - log.Errorf("Unable to update signals for "+ - "ChannelLink(%v)", l) + l.log.Errorf("Unable to update signals") } }() @@ -2407,14 +2400,12 @@ func (l *channelLink) HandleChannelUpdate(message lnwire.Message) { // committing to an update_fee message. func (l *channelLink) updateChannelFee(feePerKw lnwallet.SatPerKWeight) error { - log.Infof("ChannelPoint(%v): updating commit fee to %v sat/kw", l, - feePerKw) + l.log.Infof("updating commit fee to %v sat/kw", feePerKw) // We skip sending the UpdateFee message if the channel is not // currently eligible to forward messages. if !l.EligibleToForward() { - log.Debugf("ChannelPoint(%v): skipping fee update for "+ - "inactive channel", l.ChanID()) + l.log.Debugf("skipping fee update for inactive channel") return nil } @@ -2444,8 +2435,7 @@ func (l *channelLink) processRemoteSettleFails(fwdPkg *channeldb.FwdPkg, return } - log.Debugf("ChannelLink(%v): settle-fail-filter %v", - l.ShortChanID(), fwdPkg.SettleFailFilter) + l.log.Debugf("settle-fail-filter %v", fwdPkg.SettleFailFilter) var switchPackets []*htlcPacket for i, pd := range settleFails { @@ -2631,7 +2621,7 @@ func (l *channelLink) processRemoteAdds(fwdPkg *channeldb.FwdPkg, onionBlob[:], pd.SourceRef) needUpdate = true - log.Errorf("unable to decode onion hop "+ + l.log.Errorf("unable to decode onion hop "+ "iterator: %v", failureCode) continue } @@ -2650,7 +2640,7 @@ func (l *channelLink) processRemoteAdds(fwdPkg *channeldb.FwdPkg, ) needUpdate = true - log.Errorf("unable to decode onion "+ + l.log.Errorf("unable to decode onion "+ "obfuscator: %v", failureCode) continue } @@ -2670,7 +2660,7 @@ func (l *channelLink) processRemoteAdds(fwdPkg *channeldb.FwdPkg, ) needUpdate = true - log.Errorf("Unable to decode forwarding "+ + l.log.Errorf("Unable to decode forwarding "+ "instructions: %v", err) continue } @@ -2770,7 +2760,7 @@ func (l *channelLink) processRemoteAdds(fwdPkg *channeldb.FwdPkg, buf := bytes.NewBuffer(addMsg.OnionBlob[0:0]) err := chanIterator.EncodeNextHop(buf) if err != nil { - log.Errorf("unable to encode the "+ + l.log.Errorf("unable to encode the "+ "remaining route %v", err) var failure lnwire.FailureMessage @@ -2868,7 +2858,7 @@ func (l *channelLink) processExitHop(pd *lnwallet.PaymentDescriptor, // matches the HTLC we were extended. if pd.Amount != fwdInfo.AmountToForward { - log.Errorf("Onion payload of incoming htlc(%x) has incorrect "+ + l.log.Errorf("Onion payload of incoming htlc(%x) has incorrect "+ "value: expected %v, got %v", pd.RHash, pd.Amount, fwdInfo.AmountToForward) @@ -2881,7 +2871,7 @@ func (l *channelLink) processExitHop(pd *lnwallet.PaymentDescriptor, // We'll also ensure that our time-lock value has been computed // correctly. if pd.Timeout != fwdInfo.OutgoingCTLV { - log.Errorf("Onion payload of incoming htlc(%x) has incorrect "+ + l.log.Errorf("Onion payload of incoming htlc(%x) has incorrect "+ "time-lock: expected %v, got %v", pd.RHash[:], pd.Timeout, fwdInfo.OutgoingCTLV) @@ -3025,13 +3015,13 @@ func (l *channelLink) sendHTLCError(htlcIndex uint64, failure lnwire.FailureMess reason, err := e.EncryptFirstHop(failure) if err != nil { - log.Errorf("unable to obfuscate error: %v", err) + l.log.Errorf("unable to obfuscate error: %v", err) return } err = l.channel.FailHTLC(htlcIndex, reason, sourceRef, nil, nil) if err != nil { - log.Errorf("unable cancel htlc: %v", err) + l.log.Errorf("unable cancel htlc: %v", err) return } @@ -3050,7 +3040,7 @@ func (l *channelLink) sendMalformedHTLCError(htlcIndex uint64, shaOnionBlob := sha256.Sum256(onionBlob) err := l.channel.MalformedFailHTLC(htlcIndex, code, shaOnionBlob, sourceRef) if err != nil { - log.Errorf("unable cancel htlc: %v", err) + l.log.Errorf("unable cancel htlc: %v", err) return } diff --git a/htlcswitch/link_test.go b/htlcswitch/link_test.go index c6bc3be1..60d05eca 100644 --- a/htlcswitch/link_test.go +++ b/htlcswitch/link_test.go @@ -5417,6 +5417,7 @@ func TestHtlcSatisfyPolicy(t *testing.T) { FetchLastChannelUpdate: fetchLastChannelUpdate, MaxOutgoingCltvExpiry: DefaultMaxOutgoingCltvExpiry, }, + log: log, } var hash [32]byte From 536dd47ce984877e6a2c0c6e16a92914d6c5ac3d Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Wed, 2 Oct 2019 15:53:29 +0200 Subject: [PATCH 5/5] htlcswitch: log in lower case --- htlcswitch/link.go | 66 +++++++++++++++++++++++----------------------- 1 file changed, 33 insertions(+), 33 deletions(-) diff --git a/htlcswitch/link.go b/htlcswitch/link.go index 97581ae7..e82bb24b 100644 --- a/htlcswitch/link.go +++ b/htlcswitch/link.go @@ -482,7 +482,7 @@ func (l *channelLink) Start() error { err := l.cfg.UpdateContractSignals(signals) if err != nil { - l.log.Errorf("Unable to update signals") + l.log.Errorf("unable to update signals") } }() } @@ -530,7 +530,7 @@ func (l *channelLink) Stop() { // we had learned them at some point. err := l.cfg.PreimageCache.AddPreimages(l.uncommittedPreimages...) if err != nil { - l.log.Errorf("Unable to add preimages=%v to cache: %v", + l.log.Errorf("unable to add preimages=%v to cache: %v", l.uncommittedPreimages, err) } } @@ -609,7 +609,7 @@ func shouldAdjustCommitFee(netFee, chanFee lnwallet.SatPerKWeight) bool { // flow. We'll compare out commitment chains with the remote party, and re-send // either a danging commit signature, a revocation, or both. func (l *channelLink) syncChanStates() error { - l.log.Info("Attempting to re-resynchronize") + l.log.Info("attempting to re-resynchronize") // First, we'll generate our ChanSync message to send to the other // side. Based on this message, the remote party will decide if they @@ -667,7 +667,7 @@ func (l *channelLink) syncChanStates() error { } // In any case, we'll then process their ChanSync message. - l.log.Info("Received re-establishment message from remote side") + l.log.Info("received re-establishment message from remote side") var ( openedCircuits []CircuitKey @@ -696,7 +696,7 @@ func (l *channelLink) syncChanStates() error { } if len(msgsToReSend) > 0 { - l.log.Infof("Sending %v updates to synchronize the "+ + l.log.Infof("sending %v updates to synchronize the "+ "state", len(msgsToReSend)) } @@ -776,7 +776,7 @@ func (l *channelLink) resolveFwdPkg(fwdPkg *channeldb.FwdPkg) (bool, error) { fwdPkg.Source, fwdPkg.Height, fwdPkg.SettleFails, ) if err != nil { - l.log.Errorf("Unable to process remote log updates: %v", + l.log.Errorf("unable to process remote log updates: %v", err) return false, err } @@ -793,7 +793,7 @@ func (l *channelLink) resolveFwdPkg(fwdPkg *channeldb.FwdPkg) (bool, error) { fwdPkg.Source, fwdPkg.Height, fwdPkg.Adds, ) if err != nil { - l.log.Errorf("Unable to process remote log updates: %v", + l.log.Errorf("unable to process remote log updates: %v", err) return false, err } @@ -880,7 +880,7 @@ func (l *channelLink) htlcManager() { if l.cfg.SyncStates { err := l.syncChanStates() if err != nil { - l.log.Warnf("Error when syncing channel states: %v", err) + l.log.Warnf("error when syncing channel states: %v", err) errDataLoss, localDataLoss := err.(*lnwallet.ErrCommitSyncLocalDataLoss) @@ -935,7 +935,7 @@ func (l *channelLink) htlcManager() { errDataLoss.CommitPoint, ) if err != nil { - l.log.Errorf("Unable to mark channel "+ + l.log.Errorf("unable to mark channel "+ "data loss: %v", err) } @@ -946,7 +946,7 @@ func (l *channelLink) htlcManager() { // cases where this error is returned? case err == lnwallet.ErrCannotSyncCommitChains: if err := l.channel.MarkBorked(); err != nil { - l.log.Errorf("Unable to mark channel "+ + l.log.Errorf("unable to mark channel "+ "borked: %v", err) } @@ -1069,7 +1069,7 @@ out: // // TODO(roasbeef): add force closure? also breach? case <-l.cfg.ChainEvents.RemoteUnilateralClosure: - l.log.Warnf("Remote peer has closed on-chain") + l.log.Warnf("remote peer has closed on-chain") // TODO(roasbeef): remove all together go func() { @@ -1124,7 +1124,7 @@ out: // to continue propagating within the network. case packet := <-l.overflowQueue.outgoingPkts: msg := packet.htlc.(*lnwire.UpdateAddHTLC) - l.log.Tracef("Reprocessing downstream add update "+ + l.log.Tracef("reprocessing downstream add update "+ "with payment hash(%x)", msg.PaymentHash[:]) l.handleDownStreamPkt(packet, true) @@ -1139,7 +1139,7 @@ out: // failed, then we'll free up a new slot. htlc, ok := pkt.htlc.(*lnwire.UpdateAddHTLC) if ok && l.overflowQueue.Length() != 0 { - l.log.Infof("Downstream htlc add update with "+ + l.log.Infof("downstream htlc add update with "+ "payment hash(%x) have been added to "+ "reprocessing queue, batch_size=%v", htlc.PaymentHash[:], @@ -1227,7 +1227,7 @@ func (l *channelLink) processHodlEvent(hodlEvent invoices.HodlEvent, // Determine required action for the resolution. if hodlEvent.Preimage != nil { - l.log.Debugf("Received hodl settle event for %v", circuitKey) + l.log.Debugf("received hodl settle event for %v", circuitKey) return l.settleHTLC( *hodlEvent.Preimage, htlc.pd.HtlcIndex, @@ -1235,7 +1235,7 @@ func (l *channelLink) processHodlEvent(hodlEvent invoices.HodlEvent, ) } - l.log.Debugf("Received hodl cancel event for %v", circuitKey) + l.log.Debugf("received hodl cancel event for %v", circuitKey) // In case of a cancel, always return // incorrect_or_unknown_payment_details in order to avoid leaking info. @@ -1290,7 +1290,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { // The channels spare bandwidth is fully allocated, so // we'll put this HTLC into the overflow queue. case lnwallet.ErrMaxHTLCNumber: - l.log.Infof("Downstream htlc add update with "+ + l.log.Infof("downstream htlc add update with "+ "payment hash(%x) have been added to "+ "reprocessing queue, batch: %v", htlc.PaymentHash[:], @@ -1303,7 +1303,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { // machine, as a result, we'll signal the switch to // cancel the pending payment. default: - l.log.Warnf("Unable to handle downstream add "+ + l.log.Warnf("unable to handle downstream add "+ "HTLC: %v", err) var ( @@ -1374,7 +1374,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { } } - l.log.Tracef("Received downstream htlc: payment_hash=%x, "+ + l.log.Tracef("received downstream htlc: payment_hash=%x, "+ "local_log_index=%v, batch_size=%v", htlc.PaymentHash[:], index, l.batchCounter+1) @@ -1382,7 +1382,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { pkt.outgoingHTLCID = index htlc.ID = index - l.log.Debugf("Queueing keystone of ADD open circuit: %s->%s", + l.log.Debugf("queueing keystone of ADD open circuit: %s->%s", pkt.inKey(), pkt.outKey()) l.openedCircuits = append(l.openedCircuits, pkt.inKey()) @@ -1432,7 +1432,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { return } - l.log.Debugf("Queueing removal of SETTLE closed circuit: "+ + l.log.Debugf("queueing removal of SETTLE closed circuit: "+ "%s->%s", pkt.inKey(), pkt.outKey()) l.closedCircuits = append(l.closedCircuits, pkt.inKey()) @@ -1489,7 +1489,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { return } - l.log.Debugf("Queueing removal of FAIL closed circuit: %s->%s", + l.log.Debugf("queueing removal of FAIL closed circuit: %s->%s", pkt.inKey(), pkt.outKey()) l.closedCircuits = append(l.closedCircuits, pkt.inKey()) @@ -1527,7 +1527,7 @@ func (l *channelLink) handleDownStreamPkt(pkt *htlcPacket, isReProcess bool) { func (l *channelLink) cleanupSpuriousResponse(pkt *htlcPacket) { inKey := pkt.inKey() - l.log.Debugf("Cleaning up spurious response for incoming "+ + l.log.Debugf("cleaning up spurious response for incoming "+ "circuit-key=%v", inKey) // If the htlc packet doesn't have a source reference, it is unsafe to @@ -1573,7 +1573,7 @@ func (l *channelLink) cleanupSpuriousResponse(pkt *htlcPacket) { } } - l.log.Debugf("Deleting circuit for incoming circuit-key=%x", inKey) + l.log.Debugf("deleting circuit for incoming circuit-key=%x", inKey) // With all known references acked, we can now safely delete the circuit // from the switch's circuit map, as the state is no longer needed. @@ -1601,7 +1601,7 @@ func (l *channelLink) handleUpstreamMsg(msg lnwire.Message) { return } - l.log.Tracef("Receive upstream htlc with payment hash(%x), "+ + l.log.Tracef("receive upstream htlc with payment hash(%x), "+ "assigning index: %v", msg.PaymentHash[:], index) case *lnwire.UpdateFulfillHTLC: @@ -1654,7 +1654,7 @@ func (l *channelLink) handleUpstreamMsg(msg lnwire.Message) { OnionSHA256: msg.ShaOnionBlob, } default: - l.log.Warnf("Unexpected failure code received in "+ + l.log.Warnf("unexpected failure code received in "+ "UpdateFailMailformedHTLC: %v", msg.FailureCode) // We don't just pass back the error we received from @@ -2088,7 +2088,7 @@ func (l *channelLink) UpdateShortChanID() (lnwire.ShortChannelID, error) { sid := l.channel.ShortChanID() - l.log.Infof("Updating to short_chan_id=%v for chan_id=%v", sid, chanID) + l.log.Infof("updating to short_chan_id=%v for chan_id=%v", sid, chanID) l.Lock() l.shortChanID = sid @@ -2100,7 +2100,7 @@ func (l *channelLink) UpdateShortChanID() (lnwire.ShortChannelID, error) { ShortChanID: sid, }) if err != nil { - l.log.Errorf("Unable to update signals") + l.log.Errorf("unable to update signals") } }() @@ -2234,7 +2234,7 @@ func (l *channelLink) HtlcSatifiesPolicy(payHash [32]byte, // sender messed up, or an intermediate node tampered with the HTLC. timeDelta := policy.TimeLockDelta if incomingTimeout < outgoingTimeout+timeDelta { - l.log.Errorf("Incoming htlc(%x) has incorrect time-lock value: "+ + l.log.Errorf("incoming htlc(%x) has incorrect time-lock value: "+ "expected at least %v block delta, got %v block delta", payHash[:], timeDelta, incomingTimeout-outgoingTimeout) @@ -2660,7 +2660,7 @@ func (l *channelLink) processRemoteAdds(fwdPkg *channeldb.FwdPkg, ) needUpdate = true - l.log.Errorf("Unable to decode forwarding "+ + l.log.Errorf("unable to decode forwarding "+ "instructions: %v", err) continue } @@ -2858,7 +2858,7 @@ func (l *channelLink) processExitHop(pd *lnwallet.PaymentDescriptor, // matches the HTLC we were extended. if pd.Amount != fwdInfo.AmountToForward { - l.log.Errorf("Onion payload of incoming htlc(%x) has incorrect "+ + l.log.Errorf("onion payload of incoming htlc(%x) has incorrect "+ "value: expected %v, got %v", pd.RHash, pd.Amount, fwdInfo.AmountToForward) @@ -2871,7 +2871,7 @@ func (l *channelLink) processExitHop(pd *lnwallet.PaymentDescriptor, // We'll also ensure that our time-lock value has been computed // correctly. if pd.Timeout != fwdInfo.OutgoingCTLV { - l.log.Errorf("Onion payload of incoming htlc(%x) has incorrect "+ + l.log.Errorf("onion payload of incoming htlc(%x) has incorrect "+ "time-lock: expected %v, got %v", pd.RHash[:], pd.Timeout, fwdInfo.OutgoingCTLV) @@ -3063,12 +3063,12 @@ func (l *channelLink) fail(linkErr LinkFailureError, // Return if we have already notified about a failure. if l.failed { - l.log.Warnf("Ignoring link failure (%v), as link already "+ + l.log.Warnf("ignoring link failure (%v), as link already "+ "failed", reason) return } - l.log.Errorf("Failing link: %s", reason) + l.log.Errorf("failing link: %s", reason) // Set failed, such that we won't process any more updates, and notify // the peer about the failure.