diff --git a/discovery/gossiper.go b/discovery/gossiper.go index 89b72ca32..e96c1bfb9 100644 --- a/discovery/gossiper.go +++ b/discovery/gossiper.go @@ -757,6 +757,8 @@ func (d *deDupedAnnouncements) reset() { // and the set of senders is updated to reflect which node sent us this // message. func (d *deDupedAnnouncements) addMsg(message networkMsg) { + log.Tracef("Adding network message: %v to batch", message.msg.MsgType()) + // Depending on the message type (channel announcement, channel update, // or node announcement), the message is added to the corresponding map // in deDupedAnnouncements. Because each identifying key can have at @@ -806,6 +808,10 @@ func (d *deDupedAnnouncements) addMsg(message networkMsg) { // If we already had this message with a strictly newer // timestamp, then we'll just discard the message we got. if oldTimestamp > msg.Timestamp { + log.Debugf("Ignored outdated network message: "+ + "peer=%v, source=%x, msg=%s, ", message.peer, + message.source.SerializeCompressed(), + msg.MsgType()) return } @@ -1025,6 +1031,9 @@ func (d *AuthenticatedGossiper) networkHandler() { // sub-systems below us, then craft, sign, and broadcast a new // ChannelUpdate for the set of affected clients. case policyUpdate := <-d.chanPolicyUpdates: + log.Tracef("Received channel %d policy update requests", + len(policyUpdate.edgesToUpdate)) + // First, we'll now create new fully signed updates for // the affected channels and also update the underlying // graph with the new state. @@ -1044,6 +1053,13 @@ func (d *AuthenticatedGossiper) networkHandler() { announcements.AddMsgs(newChanUpdates...) case announcement := <-d.networkMsgs: + log.Tracef("Received network message: "+ + "peer=%v, source=%x, msg=%s, is_remote=%v", + announcement.peer, + announcement.source.SerializeCompressed(), + announcement.msg.MsgType(), + announcement.isRemote) + // We should only broadcast this message forward if it // originated from us or it wasn't received as part of // our initial historical sync. @@ -1057,6 +1073,11 @@ func (d *AuthenticatedGossiper) networkHandler() { emittedAnnouncements, _ := d.processNetworkAnnouncement( announcement, ) + log.Debugf("Processed network message %s, "+ + "returned len(announcements)=%v", + announcement.msg.MsgType(), + len(emittedAnnouncements)) + if emittedAnnouncements != nil { announcements.AddMsgs( emittedAnnouncements..., @@ -1111,6 +1132,13 @@ func (d *AuthenticatedGossiper) networkHandler() { announcement, ) + log.Tracef("Processed network message %s, "+ + "returned len(announcements)=%v, "+ + "allowDependents=%v", + announcement.msg.MsgType(), + len(emittedAnnouncements), + allowDependents) + // If this message had any dependencies, then // we can now signal them to continue. validationBarrier.SignalDependants( @@ -1589,6 +1617,10 @@ func (d *AuthenticatedGossiper) addNode(msg *lnwire.NodeAnnouncement, func (d *AuthenticatedGossiper) processNetworkAnnouncement( nMsg *networkMsg) ([]networkMsg, bool) { + log.Debugf("Processing network message: peer=%v, source=%x, msg=%s, "+ + "is_remote=%v", nMsg.peer, nMsg.source.SerializeCompressed(), + nMsg.msg.MsgType(), nMsg.isRemote) + isPremature := func(chanID lnwire.ShortChannelID, delta uint32) bool { // TODO(roasbeef) make height delta 6 // * or configurable @@ -1616,17 +1648,25 @@ func (d *AuthenticatedGossiper) processNetworkAnnouncement( // newer update for this node so we can skip validating // signatures if not required. if d.cfg.Router.IsStaleNode(msg.NodeID, timestamp) { + log.Debugf("Skipped processing stale node: %x", + msg.NodeID) nMsg.err <- nil return nil, true } if err := d.addNode(msg, schedulerOp...); err != nil { - if routing.IsError(err, routing.ErrOutdated, - routing.ErrIgnored) { + log.Debugf("Adding node: %x got error: %v", + msg.NodeID, err) - log.Debug(err) - } else if err != routing.ErrVBarrierShuttingDown { + switch { + case routing.IsError(err, routing.ErrOutdated, + routing.ErrIgnored): + + case err == routing.ErrVBarrierShuttingDown: + + default: log.Error(err) + } nMsg.err <- err @@ -1817,7 +1857,7 @@ func (d *AuthenticatedGossiper) processNetworkAnnouncement( log.Debugf("Router rejected channel "+ "edge: %v", err) } else { - log.Tracef("Router rejected channel "+ + log.Debugf("Router rejected channel "+ "edge: %v", err) key := newRejectCacheKey( @@ -1943,6 +1983,12 @@ func (d *AuthenticatedGossiper) processNetworkAnnouncement( if d.cfg.Router.IsStaleEdgePolicy( msg.ShortChannelID, timestamp, msg.ChannelFlags, ) { + + log.Debugf("Ignored stale edge policy: peer=%v, "+ + "source=%x, msg=%s, is_remote=%v", nMsg.peer, + nMsg.source.SerializeCompressed(), + nMsg.msg.MsgType(), nMsg.isRemote) + nMsg.err <- nil return nil, true } @@ -2166,6 +2212,10 @@ func (d *AuthenticatedGossiper) processNetworkAnnouncement( chanInfo, msg.ChannelFlags, ) + log.Debugf("The message %v has no AuthProof, sending "+ + "the update to remote peer %x", + msg.MsgType(), remotePubKey) + // Now, we'll attempt to send the channel update message // reliably to the remote peer in the background, so // that we don't block if the peer happens to be offline diff --git a/discovery/sync_manager.go b/discovery/sync_manager.go index 68c277c6a..e5edb7744 100644 --- a/discovery/sync_manager.go +++ b/discovery/sync_manager.go @@ -492,6 +492,10 @@ func (m *SyncManager) createGossipSyncer(peer lnpeer.Peer) *GossipSyncer { // handle any sync transitions. s.setSyncState(chansSynced) s.setSyncType(PassiveSync) + + log.Debugf("Created new GossipSyncer[state=%s type=%s] for peer=%v", + s.syncState(), s.SyncType(), peer) + return s }