Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Always print why we disconnect explicitly #3309

Merged
merged 1 commit into from
Sep 10, 2024
Merged

Always print why we disconnect explicitly #3309

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 5 additions & 5 deletions lightning/src/ln/peer_handler.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1333,8 +1333,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
match self.do_read_event(peer_descriptor, data) {
Ok(res) => Ok(res),
Err(e) => {
log_trace!(self.logger, "Disconnecting peer due to a protocol error (usually a duplicate connection).");
self.disconnect_event_internal(peer_descriptor);
self.disconnect_event_internal(peer_descriptor, "of a protocol error");
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

how does this "drop protocol error message when we get a duplicate connection from a peer." ?

I don't see any handling change related to duplicate connection.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, sorry, its very subtle - In do_read_event if we hit a duplicate peer we'll unset their_node_id before returning the error. Then, we'll call disconnect_event_internal which won't print anything if their_node_id is None.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, ok i would have never guessed it.
maybe should have been a comment on top of "if let Some((node_id, _)) = peer.their_node_id".

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Right, probably should have explained it in the commit message, though not entirely sure why we'd comment it - logging without a peer id doesn't make much sense (what are we telling the user?), and we already log in do_read_event saying that its a second connection.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

because it also has a hidden behaviour, don't log when "duplicate connection from a peer" because their_node_id is None. Maybe not the right place for it though.

Err(e)
}
}
Expand Down Expand Up @@ -2435,7 +2434,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM

/// Indicates that the given socket descriptor's connection is now closed.
pub fn socket_disconnected(&self, descriptor: &Descriptor) {
self.disconnect_event_internal(descriptor);
self.disconnect_event_internal(descriptor, "the socket was disconnected");
}

fn do_disconnect(&self, mut descriptor: Descriptor, peer: &Peer, reason: &'static str) {
Expand All @@ -2455,7 +2454,7 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
descriptor.disconnect_socket();
}

fn disconnect_event_internal(&self, descriptor: &Descriptor) {
fn disconnect_event_internal(&self, descriptor: &Descriptor, reason: &'static str) {
let mut peers = self.peers.write().unwrap();
let peer_option = peers.remove(descriptor);
match peer_option {
Expand All @@ -2467,7 +2466,8 @@ impl<Descriptor: SocketDescriptor, CM: Deref, RM: Deref, OM: Deref, L: Deref, CM
Some(peer_lock) => {
let peer = peer_lock.lock().unwrap();
if let Some((node_id, _)) = peer.their_node_id {
log_trace!(WithContext::from(&self.logger, Some(node_id), None, None), "Handling disconnection of peer {}", log_pubkey!(node_id));
let logger = WithContext::from(&self.logger, Some(node_id), None, None);
log_trace!(logger, "Handling disconnection of peer {} because {}", log_pubkey!(node_id), reason);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: Looks like we include the node_id in the logger context and the log itself, which is a bit redundant

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yea, we do that in a lot of places very much on purpose - not all our users (yet) print context info in their logs (hell, LDK-sample doesn't, even) so if we get logs from users we don't want to be super confused even if we're missing context.

let removed = self.node_id_to_descriptor.lock().unwrap().remove(&node_id);
debug_assert!(removed.is_some(), "descriptor maps should be consistent");
if !peer.handshake_complete() { return; }
Expand Down
Loading