BGP session stuck in OpenConfirm

[dslicenc]

Problem: Sessions stuck in OpenConfirm for extended periods, never proceeding to Established or going back to Idle.

Neighbor                 V         AS MsgRcvd MsgSent   TblVer  InQ OutQ  Up/Down State/PfxRcd
10.1.1.3				    4      65290    1931    1143        0    0    0 13:42:29  OpenConfirm

Very occasional problem seen by our customers (maybe 2-3 times total in the wild in the last couple of years.) Now able to reproduce in a couple of hours by one of our testers doing very unnatural things to the router (flooding it with tcp opens, clearing neighbors, etc.). Code path that creates the issue is now pretty well known but need to find the right solution to it.

In the process of going from OpenConfirm to Established, bgp_establish calls peer_xfer_conn to handle the doppelganger. If the peer xfer fails, bgp_establish returns a -1 to the caller.

        other = peer->doppelganger;
        peer = peer_xfer_conn(peer);
        if (!peer) {
                flog_err(EC_BGP_CONNECT, "%%Neighbor failed in xfer_conn");
                return -1;
        }

Since we've been able to reproduce the problem, we know based on the below error message in the log that in the cases where the session has gotten stuck in OpenConfirm, this error is hit in peer_xfer_conn:

        if (bgp_getsockname(peer) < 0) {
                flog_err(
                        EC_LIB_SOCKET,
                        "%%bgp_getsockname() failed for %s peer %s fd %d (from_peer fd %d)",
                        (CHECK_FLAG(peer->sflags, PEER_STATUS_ACCEPT_PEER)
                                 ? "accept"
                                 : ""),
                        peer->host, peer->fd, from_peer->fd);
                bgp_stop(peer);
                bgp_stop(from_peer);
                return NULL;
        }

When the Null return from peer_xfer_conn leads to the -1 return from bgp_establish, bgp_event_update takes this action:

       if (ret >= 0) {
	....snip...
        } else {
                /*
                 * If we got a return value of -1, that means there was an
                 * error, restart the FSM. Since bgp_stop() was called on the
                 * peer. only a few fields are safe to access here. In any case
                 * we need to indicate that the peer was stopped in the return
                 * code.
                 */
                if (!dyn_nbr && !passive_conn && peer->bgp) {
                        flog_err(
                                EC_BGP_FSM,
                                "%s [FSM] Failure handling event %s in state %s, "
                                "prior events %s, %s, fd %d",
                                peer->host, bgp_event_str[peer->cur_event],
                                lookup_msg(bgp_status_msg, peer->status, NULL),
                                bgp_event_str[peer->last_event],
                                bgp_event_str[peer->last_major_event],
                                peer->fd);
                        bgp_stop(peer);
                        bgp_fsm_change_status(peer, Idle);
                        bgp_timer_set(peer);
                }
                ret = FSM_PEER_STOPPED;
        }

Since in every connection, one side is the passive side until the state is changed to established, if the error above occurs to the passive peer, the call to bgp_fsm_change_status does not occur and the router stays in this state indefinitely. If anyone has ideas to deal with it, please provide ideas (or diffs!) or take the issue and solve it. We would also be glad to test any potential fix in the testbed that can recreate it.

Very difficult to reproduce. If details from our tester on how he was able to recreate it would be useful, I'll be glad to provide it.

[Spantik]

BGP RCA:

Issue is seen in a race condition where we BGP session enters established state. BGP now tries to clean up the doppelgänger, during this time if the we fail to fetch remote address then it closes both connections. With improper clean up a stale BGP session with OPENCONFIM state stays.

Steps to get in to this state:

1. Initially BGP start listening to socket.
2. Start timer expires and BGP tries to connect to peer and moved to Idle->connect (lets say peer datastructre X)
3. Connect for X succeeds and hence moved from idle ->connect with FD 27.
4. A incoming connection is accepted and a new peer datastructure Y is crated with FD 35 moves from idle->Active state.
5. Peer datastercture Y FD 35 sends out OPNE and moves to Active->Opensent state.
6. Peer datastrcture Y FD 35 receives OPEN and moved from Opensent->Openconfirm state.
7. Meanwhile on peer datastrcture X FD 27 sends out a OPEN message and moved from connect->Opensent.
8. For peer datastrcture Y FD 35 keep alive is received and it is moved from OpenConfirm->Established.
9. As part of this doppelgänger cleanup is taken up where we copy all the parameters to other if peer DS is not created due to config (accepted connection)
   1. In this case peer datastructure Y FD 35 is a accepted connection so we try to copy all its parameter to peer datastructure X and delete Y.
10. During this process TCP connection for the accepted connection goes down and hence get remote address and port fails.
11. With this failure bgp_stop function for both peer datastrure X and peer datastructure Y is called.
12. By this time all the parameters include state for datastrcture for X and Y are exchanged. Peer Y FD 35 when it entered this function had state OpenConfirm still which has been moved to peer datastrcture X.
13. In bgp_stop it will stop all the timers and take action only if peer is in established state. Now that peer datastrcture X and Y are not in established state (in this function) it will simply close all timers and close the socket and assigns socket for both the peer datastrcture to -1.
14. Peer datastrcture Y will be deleted as it is a datastrcture created due to accept of connection where as peer datastrcture X will be held as it is created with configuration.
15. Now peer datastrcture X now holds a state of OpenConfirm without any timers running.
16. With this any new incoming connection will never be able to establish as there is config connection X which is stuck in OpenConfirm.

Logs:

Peer datastrcture X with connect success:
2020/08/17 13:00:39.558083 BGP: 169.254.32.3 [FSM] Timer (start timer expire).
2020/08/17 13:00:39.558142 BGP: 169.254.32.3 [FSM] BGP_Start (Idle->Connect), fd -1
2020/08/17 13:00:39.558189 BGP: 169.254.32.3 [Event] Connect start to 169.254.32.3 fd 27

Peer datastrcture Y with accept connection
2020/08/17 13:00:39.559563 BGP: [Event] BGP connection from host 169.254.32.3 fd 35
2020/08/17 13:00:39.559908 BGP: 169.254.32.3 (0x19703c00b690 35) went from Idle to Active
2020/08/17 13:00:39.559923 BGP: 169.254.32.3 [FSM] TCP_connection_open (Active->OpenSent), fd 35

peer datastrcture Y receeived open and goes to Openconfirm
2020/08/17 13:00:39.560116 BGP: 169.254.32.3 rcvd OPEN w/ optional parameter type 2 (Capability) len 10
2020/08/17 13:00:39.560137 BGP: 169.254.32.3 [FSM] Receive_OPEN_message (OpenSent->OpenConfirm), fd 35
2020/08/17 13:00:39.560194 BGP: 169.254.32.3 (0x19703c00b690 35) went from OpenSent to OpenConfirm
2020/08/17 13:00:39.560198 BGP: 169.254.32.3: peer keepalive being added, acquiring lock
2020/08/17 13:00:39.560242 BGP: 169.254.32.3: peer keepalive added

peer datastrcture X sent OPEN to move to opensent
2020/08/17 13:00:39.560985 BGP: 169.254.32.3 [FSM] TCP_connection_open (Connect->OpenSent), fd 27
2020/08/17 13:00:39.561055 BGP: 169.254.32.3 sending OPEN, version 4, my as 450, holdtime 3, id 125.10.11.2

Peer datastrcture Y received keepalive and moved to Established.
2020/08/17 13:00:39.562305 BGP: 169.254.32.3 [FSM] Receive_KEEPALIVE_message (OpenConfirm->Established), fd 35

Cleanup process starts for X and Y
2020/08/17 13:00:39.562353 BGP: 169.254.32.3: peer transfer 0x19703c00b690 fd 35 -> 0x19703b711570 fd 27)
2020/08/17 13:00:39.562514 BGP: 169.254.32.3: peer keepalive removed

Connection for Y has gone down and fails to get remote address.
2020/08/17 13:00:39.562554 BGP: [EC 100663299] Can't get remote address and port: Transport endpoint is not connected
2020/08/17 13:00:39.562561 BGP: [EC 100663299] %bgp_getsockname() failed for peer 169.254.32.3 fd 35 (from_peer fd 27)

triggers failure and calls bgp_stop for both X and Y.
2020/08/17 13:00:39.562655 BGP: 169.254.32.3(0x19703b711570): close file descriptor
2020/08/17 13:00:39.562836 BGP: 169.254.32.3(0x19703c00b690): close file descriptor
2020/08/17 13:00:39.563627 BGP: 169.254.32.3 (0x19703c00b690 -1) went from OpenSent to Deleted
2020/08/17 13:00:39.563752 BGP: [EC 33554464] %Neighbor failed in xfer_conn

[patrasar]

Raised PR
#6959

[yasliang]

Could you share the details how to reproduce？Thank you.

yasliang@tencent.com