Lighthouse: Intermittent invalid Discv5 session w/ enr=None causes panic

[jrhea]

Description

When connecting to the topaz testnet it eventually crashes with this error:

thread 'tokio-runtime-worker' panicked at 'Should never be None at this point', src/libcore/option.rs:1188:5

Version

libp2p:

libp2p =  { git = "https://github.com/sigp/rust-libp2p", rev = "37b7e9349cf3e724da02bbd4b5dd6c054c2d56d3", package = "libp2p"}

Note: using prrkl/imp & mothra instead of lighthouse

Present Behaviour

I can connect to the topaz testnet, discover peers, and listen to gossip messages for 30 mins just fine, but eventually the error mentioned above crashes the app. I have recreated the issue twice and captured the logs when running with: RUST_LOG=libp2p_discv5=debug

The problem starts when we send a RandomPacket to Node_Id: 0xce3f..25b4

[2020-04-21T03:51:22Z DEBUG libp2p_discv5::behaviour] Sending RPC Request: FindNode { distance: 252 } to node: 0xce3f..25b4
[2020-04-21T03:51:22Z DEBUG libp2p_discv5::session_service] No session established, sending a random packet to: 0xce3f..25b4 

After a timeout elapses it is sent again:

[2020-04-21T03:51:33Z DEBUG libp2p_discv5::session_service] Resending message: RandomPacket { tag: [175, 216, 26, 111, 250, 203, 9, 215, 34, 146, 151, 242, 200, 167, 196, 78, 54, 184, 109, 44, 93, 219, 104, 187, 156, 156, 233, 63, 64, 109, 232, 36], auth_tag: [87, 26, 94, 20, 96, 111, 241, 216, 69, 225, 39, 64], data: [2, 188, 126, 225, 255, 252, 120, 26, 225, 29, 189, 251, 148, 66, 237, 28, 101, 171, 196, 63, 214, 75, 188, 84, 181, 176, 143, 231, 215, 95, 79, 147, 179, 240, 168, 116, 133, 2, 65, 146, 116, 128, 144, 23] } to node: 0xce3f..25b4

• session_service.rs::handle_message(): we find the session where RandomPacket was sent (line: 526)
  
  
  
  • line 543: detects session.is_random_sent() is true and "upgrades it to WhoAreYou" and inserts it into the list of events to be processed - self.events
  
  
  • on line 565:let message = match session.decrypt_message(auth_tag, message, &tag) results in error
  
  
  • on line then on line 573: the error message you see below is posted:
  
  
  • on line 575-580: we add A SECOND WhoAreYou (in addition to the one from line 543) to self.events
  
  
  • on line 574: self.sessions.remove(&src_id); we remove the session where the random packet was originally sent
  
  

[2020-04-21T03:51:34Z DEBUG libp2p_discv5::session_service] Message from node: 0xce3f..25b4 is not encrypted with known session keys. Requesting a WHOAREYOU packet

A few things to note at this point:
1) we remove the RandomPacket session from self.sessions, but left it in self.pending_requests
2) We have now added two WhoAreYou events to self.events

Next, the following code in src/behaviour.rs: line: 1084

     // do not know of this peer
    debug!("NodeId unknown, requesting ENR. NodeId: {}", src_id);
    self.service.send_whoareyou(src, &src_id, 0, None, auth_tag)

results in this error message

2020-04-21T03:51:34Z DEBUG libp2p_discv5::behaviour] NodeId unknown, requesting ENR. NodeId: 0xce3f..25b4

Notice that the call to: self.service.send_whoareyou(src, &src_id, 0, None, auth_tag) passes in None for remote_enr. Next, at src/session_service.rs: line 289 inside send_whoareyou() a previous session is NOT found for the node_id: 0xce3f so remote_enr stays None

Next we see the following message and

• new_whoareyou(node_id, enr_seq, remote_enr, auth_tag) is called with remote_enr=None resulting in a new session that is inserted into self.sessions on session_service.rs: line 301

[2020-04-21T03:51:34Z DEBUG libp2p_discv5::session_service] Sending WHOAREYOU packet to: 0xce3f..25b4 

Remember when we inserted two WHOAREYOU requests into the even queue? I believe we now see the second one processed. I think it is benign bc the code recognizes that an existing session exists, but it should probably be reviewed.

[2020-04-21T03:51:34Z DEBUG libp2p_discv5::behaviour] NodeId unknown, requesting ENR. NodeId: 0xce3f..25b4  
[2020-04-21T03:51:34Z WARN  libp2p_discv5::session_service] Session exists. WhoAreYou packet not sent               

finally, we have the final log entry originating from handle_whoareyou() session_service.rs followed by the error:

[2020-04-21T03:51:34Z DEBUG libp2p_discv5::session_service] Received a WHOAREYOU packet. Source: 192.252.232.65:12000 
thread 'tokio-runtime-worker' panicked at 'Should never be None at this point', src/libcore/option.rs:1188:5

My take on what is happening is:

• on line: 339 we retrieve the req corresponding to a RandomPacket request from self.pending_requests
• on line: 343 we the log prints out telling us that we are processing a WHOAREYOU packet (YIKES)

#### Remember, the session for the RandomPacket was removed, but not the pending request. I (think) this means that we have a session with a Enr=None corresponding to a pending request for a RandomPacket. ####

If the pending_request had been a WhoAreYou, then the following code on line 377 would have exited the routine:

Packet::WhoAreYou { .. } => {
                    // a WhoAreYou packet was received in response to a WHOAREYOU.
                    warn!("A WHOAREYOU packet was received in response to a WHOAREYOU. Dropping packet and marking messages as failed");
                    return Err(());
                }

instead condition on line 360 evaluates true:

               Packet::RandomPacket { .. } => {
                    // get the messages that are waiting for an established session
                    let messages = self
                        .pending_messages
                        .get_mut(&src_id)
                        .ok_or_else(|| warn!("No pending messages found for WHOAREYOU request."))?;

                    if messages.is_empty() {
                        // This could happen for an established connection and another peer (from the
                        // the same socketaddr) sends a WHOAREYOU packet
                        debug!("No pending messages found for WHOAREYOU request.");
                        return Err(());
                    }
                    // select the first message in the queue
                    messages.remove(0)
                }

and as result on line 400 session.encrypt_with_header() is called:

        let (encryption_key, decryption_key, auth_resp_key, ephem_pubkey) =
            crypto::generate_session_keys(
                local_node_id,
                self.remote_enr
                    .as_ref()
                    .expect("Should never be None at this point"),
                id_nonce,
            )?;

and the error is triggered.

Here is a link to the full log:
imp.log

Steps to resolve

Problem 1:

The fact that the session for the RandomPacket is removed from the sessions list in in src/session_service.rs handle_message() later causes a new session to be created with a an ENR=None. The problem is made worse by the fact that the RandomPacket request still exists in the pending_requests list. If it wasn't then handle_whoareyou() would have exited the routine with an error at line 371.

Is there a way to synchronize the sessions and pending_requests more easily?

Problem 2 (may not be critical, but should be looked at):

in src/session_service.rs handle_message()

two WHOAREYOU's are added to the event queue:

1. line 542-550

        // if we have sent a random packet, upgrade to a WhoAreYou request
        if session.is_random_sent() {
            let event = SessionEvent::WhoAreYouRequest {
                src,
                src_id: src_id.clone(),
                auth_tag,
            };
            self.events.push_back(event);
        }

1. line 564-580

        // attempt to decrypt and process the message.
        let message = match session.decrypt_message(auth_tag, message, &tag) {
            Ok(m) => ProtocolMessage::decode(m)
                .map_err(|e| warn!("Failed to decode message. Error: {:?}", e))?,
            Err(_) => {
                // We have a session, but the message could not be decrypted. It is likely the node
                // sending this message has dropped their session. In this case, this message is a
                // Random packet and we should reply with a WHOAREYOU.
                // This means we need to drop the current session and re-establish.
                debug!("Message from node: {} is not encrypted with known session keys. Requesting a WHOAREYOU packet", src_id);
                self.sessions.remove(&src_id);
                let event = SessionEvent::WhoAreYouRequest {
                    src,
                    src_id: src_id.clone(),
                    auth_tag,
                };
                self.events.push_back(event);
                return Ok(());
            }
        };

[AgeManning]

@jrhea Thank you VERY much for this detailed trace of this error. Has saved me lots of time!!

I think what you are seeing here is the following:

• You are trying to discover a new node
• You send a RandomPacket to the new node to establish an encryption handshake
• Based on whatever config value is set for the timeout of a packet, the random packet times out.
• You have retries set to something other than 1 so your node attempts the random packet again.
• For whatever reason, the node you are connecting to has a session established with you, so tried to send you an encrypted message, or is also sending you a random packet to discover you.

The current implementation was expecting a WHOAREYOU response to the random packet, but got an encrypted message. The logic should have been to ignore the original random packet set and instead send a WHOAREYOU in response to this new random packet. The code missed a return and continued to try to decrypt the message without knowing any keys (this is the code path that duplicated WHOAREYOU's in the events).

• Your node does successfully send a WHOAREYOU packet in response to this encrypted message.
• The node is slow, and finally responds with it's WHOAREYOU response to your original (now expired) RandomPacket. Because the RandomPacket was not removed from self.pending_requests as you rightfully point out, we don't drop this packet instead try to process it, assuming the session state is still in the "random_sent" state (but we've upgraded to a whoareyou). Whoareyou states cannot establish any kind of crypto and we get the error you have seen.

The logic should go:

• Receive encrypted message after we sent a random request, remove random request, and ask for a WhoAreYou (keeping the random session as is).
• The behaviour looks for a better ENR, if it finds one it uses it, if not, it uses the enr that is in the existing random session.
• Sends the WhoAreYou and awaits the response
• Drops old WhoareYou packets as they no longer match any random request.

I've made these changes in this commit: https://github.com/sigp/rust-libp2p/commit/46415e9467a42e70c6bb3d2525354e648867c6a3

I've merged this into lighthouse. Let me know if this doesn't resolve your issue.

Thanks again!

I agree there should be some kind of re-write that simplifies a lot of this timing logic and complexities. When it was first written, the idea was to keep layers, the behaviour layer, the session layer then the packet layer. Each of them operate independently with each being somewhat opaque to each other. i.e someone working on the queries in the behaviour can be completely ignorant about any handshakes and packet timing being established.
The sessions are long-lasting and individual packets time-out quickly which is why they are distinct. I also have no heartbeat, where everything gets checked and updated, instead opted for exact timings for everything which leads to arbitrary events firing all the time. I'm always open to suggestions on code improvement, maybe one day I'll update this given some free time :)

[AgeManning]

I'm preemptively consider this closed, please re-open if the bug persists.