From 57562d6c4d231402f6e8a3aa718897a9f7c0fe0a Mon Sep 17 00:00:00 2001 From: Joost Jager Date: Tue, 24 Sep 2019 13:12:53 +0200 Subject: [PATCH] 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 720f5d0de..0f281639d 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)