CI: Test_NeighborAddDel failure #25637
Description
CI failure
Hit in #25469: https://jenkins.cilium.io/job/Cilium-PR-Runtime-kernel-net-next/123/testReport/(root)/Suite-runtime/RuntimeDatapathPrivilegedUnitTests_Run_Tests/
[07:37:34] ┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓
[07:37:34] ┃ FAIL package: github.com/cilium/cilium/pkg/bgpv1/test ┃
[07:37:34] ┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛
[07:37:34]
[07:37:34] --- FAIL: Test_NeighborAddDel (9.14s)
[07:37:34]
[07:37:34] time="2023-05-24T07:33:39Z" level=info msg="deleting dummy links"
[07:37:34] time="2023-05-24T07:33:39Z" level=info msg="adding dummy links"
[07:37:34] time="2023-05-24T07:33:39Z" level=info msg="GoBGP test instance: starting"
[07:37:34] time="2023-05-24T07:33:39Z" level=info msg="Add a peer configuration" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGPsubsys=basic
[07:37:34] time="2023-05-24T07:33:39Z" level=debug msg="IdleHoldTimer expired" Duration=0 Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGPsubsys=basic
[07:37:34] time="2023-05-24T07:33:39Z" level=info msg="GoBGP test instance: starting"
[07:37:34] time="2023-05-24T07:33:39Z" level=info msg="Add a peer configuration" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGPsubsys=basic
[07:37:34] time="2023-05-24T07:33:39Z" level=debug msg="IdleHoldTimer expired" Duration=0 Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGPsubsys=basic
[07:37:34] time="2023-05-24T07:33:39Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP new=BGP_FSM_ACTIVEold=BGP_FSM_IDLE reason=idle-hold-timer-expired subsys=basic
[07:37:34] level=info msg=Invoked duration="78.81µs" function="test.newFixture.func6 (fixtures.go:155)" subsys=hive
[07:37:34] level=info msg=Starting subsys=hive
[07:37:34] level=info msg="Start hook executed" duration="1.682µs" function="*resource.resource[*github.com/cilium/cilium/pkg/k8s/slim/k8s/api/corev1.Service].Start" subsys=hive
[07:37:34] time="2023-05-24T07:33:39Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP new=BGP_FSM_ACTIVEold=BGP_FSM_IDLE reason=idle-hold-timer-expired subsys=basic
[07:37:34] level=info msg="Start hook executed" duration=101.056956ms function="*manager.diffStore[*github.com/cilium/cilium/pkg/k8s/slim/k8s/apicore/v1.Service].Start" subsys=hive
[07:37:34] level=info msg="Start hook executed" duration="1.257µs" function="*resource.resource[*github.com/cilium/cilium/pkg/k8s/apis/cilium.iov2alpha1.CiliumBGPPeeringPolicy].Start" subsys=hive
[07:37:34] level=info msg="Start hook executed" duration="1.215µs" function="*resource.resource[*github.com/cilium/cilium/pkg/k8s/slim/k8s/api/corev1.Node].Start" subsys=hive
[07:37:34] level=info msg="Start hook executed" duration=427ns function="*resource.resource[*github.com/cilium/cilium/pkg/k8s/apis/cilium.io/v2CiliumNode].Start" subsys=hive
[07:37:34] level=info msg="Start hook executed" duration="38.391µs" function="*agent.kubernetesNodeSpecer.Start" subsys=hive
[07:37:34] level=info msg="Start hook executed" duration=101.291452ms function="*agent.Controller.Start" subsys=hive
[07:37:34]
[07:37:34] --- FAIL: Test_NeighborAddDel/add_two_neighbors (8.80s)
[07:37:34]
[07:37:34] time="2023-05-24T07:33:39Z" level=info msg="GoBGP test instance: Peer Event: {0 IDLE}"
[07:37:34] level=info msg="Cilium BGP Control Plane Controller now running..." component=Controller.Run subsys=bgp-control-plane
[07:37:34] level=info msg="Cilium BGP Control Plane Controller woken for reconciliation" component=Controller.Run subsys=bgp-control-plane
[07:37:34] level=info msg="Registering BGP servers for policy with local ASN 65001" component=manager.registerBGPServer subsys=bgp-control-plane
[07:37:34] level=info msg="Reconciling peers for virtual router with local ASN 65001" component=manager.neighborReconciler subsys=bgp-control-plane
[07:37:34] level=info msg="Adding peer 172.16.100.2/32 65011 to local ASN 65001" component=manager.neighborReconciler subsys=bgp-control-plane
[07:37:34] level=info msg="Add a peer configuration" Key=172.16.100.2 Topic=Peer asn=65001 component=gobgp.BgpServerInstance subsys=bgp-control-plane
[07:37:34] level=info msg="Done reconciling peers for virtual router with local ASN 65001" component=manager.neighborReconcilersubsys=bgp-control-plane
[07:37:34] level=info msg="Successfully registered GoBGP servers for policy with local ASN 65001" component=manager.registerBGPServersubsys=bgp-control-plane
[07:37:34] time="2023-05-24T07:33:39Z" level=info msg="GoBGP test instance: Peer Event: {65001 IDLE}"
[07:37:34] time="2023-05-24T07:33:39Z" level=info msg="GoBGP test instance: Peer Event: {65001 ACTIVE}"
[07:37:34] level=info msg="Cilium BGP Control Plane Controller woken for reconciliation" component=Controller.Run subsys=bgp-control-plane
[07:37:34] level=info msg="Reconciling peers for virtual router with local ASN 65001" component=manager.neighborReconciler subsys=bgp-control-plane
[07:37:34] level=info msg="Adding peer 172.16.100.3/32 65012 to local ASN 65001" component=manager.neighborReconciler subsys=bgp-control-plane
[07:37:34] level=info msg="Add a peer configuration" Key=172.16.100.3 Topic=Peer asn=65001 component=gobgp.BgpServerInstance subsys=bgp-control-plane
[07:37:34] level=info msg="Done reconciling peers for virtual router with local ASN 65001" component=manager.neighborReconcilersubsys=bgp-control-plane
[07:37:34] level=info msg="type:STATE peer:{conf:{local_asn:65001 neighbor_address:\"172.16.100.2\" peer_asn:65011} state:{local_asn:65001 neighbor_address:\"172.16.100.2\" peer_asn:65011 session_state:IDLE router_id:\"<nil>\"} transport:{local_address:\"<nil>\"}}"
[07:37:34] level=info msg="type:STATE peer:{conf:{local_asn:65001 neighbor_address:\"172.16.100.2\" peer_asn:65011} state:{local_asn:65001 neighbor_address:\"172.16.100.2\" peer_asn:65011 session_state:ACTIVE router_id:\"<nil>\"} transport:{local_address:\"<nil>\"}}"
[07:37:34] level=info msg="type:STATE peer:{conf:{local_asn:65001 neighbor_address:\"172.16.100.3\" peer_asn:65012} state:{local_asn:65001 neighbor_address:\"172.16.100.3\" peer_asn:65012 session_state:IDLE router_id:\"<nil>\"} transport:{local_address:\"<nil>\"}}"
[07:37:34] level=info msg="type:STATE peer:{conf:{local_asn:65001 neighbor_address:\"172.16.100.3\" peer_asn:65012} state:{local_asn:65001 neighbor_address:\"172.16.100.3\" peer_asn:65012 session_state:ACTIVE router_id:\"<nil>\"} transport:{local_address:\"<nil>\"}}"
[07:37:34] time="2023-05-24T07:33:46Z" level=debug msg="try to connect" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP subsys=basic
[07:37:34] time="2023-05-24T07:33:46Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP new=BGP_FSM_OPENSENTold=BGP_FSM_ACTIVE reason=new-connection subsys=basic
[07:37:34] time="2023-05-24T07:33:46Z" level=info msg="GoBGP test instance: Peer Event: {65001 OPENSENT}"
[07:37:34] level=info msg="type:STATE peer:{conf:{local_asn:65001 neighbor_address:\"172.16.100.2\" peer_asn:65011} state:{local_asn:65001 neighbor_address:\"172.16.100.2\" peer_asn:65011 session_state:OPENSENT router_id:\"<nil>\"} transport:{local_address:\"172.16.100.1\" local_port:1790 remote_port:40939}}"
[07:37:34] level=info msg="type:STATE peer:{conf:{local_asn:65001 neighbor_address:\"172.16.100.2\" peer_asn:65011} state:{local_asn:65001 neighbor_address:\"172.16.100.2\" peer_asn:65011 session_state:OPENCONFIRM router_id:\"172.16.100.2\"} transport:{local_address:\"172.16.100.1\" local_port:1790 remote_port:40939}}"
[07:37:34] time="2023-05-24T07:33:46Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGPnew=BGP_FSM_OPENCONFIRM old=BGP_FSM_OPENSENT reason=open-msg-received subsys=basic
[07:37:34] time="2023-05-24T07:33:46Z" level=info msg="GoBGP test instance: Peer Event: {65001 OPENCONFIRM}"
[07:37:34] time="2023-05-24T07:33:46Z" level=info msg="Peer Up" Key=172.16.100.1 State=BGP_FSM_OPENCONFIRM Topic=Peer asn=65011 component=tests.BGPsubsys=basic
[07:37:34] time="2023-05-24T07:33:46Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGPnew=BGP_FSM_ESTABLISHED old=BGP_FSM_OPENCONFIRM reason=open-msg-negotiated subsys=basic
[07:37:34] time="2023-05-24T07:33:46Z" level=info msg="GoBGP test instance: Peer Event: {65001 ESTABLISHED}"
[07:37:34] time="2023-05-24T07:33:46Z" level=info msg="GoBGP test instance: Peer Event: {0 IDLE}"
[07:37:34] time="2023-05-24T07:33:46Z" level=info msg="GoBGP test instance: Peer Event: {65001 IDLE}"
[07:37:34] time="2023-05-24T07:33:46Z" level=info msg="GoBGP test instance: Peer Event: {65001 ACTIVE}"
[07:37:34] level=info msg="Peer Up" Key=172.16.100.2 State=BGP_FSM_OPENCONFIRM Topic=Peer asn=65001 component=gobgp.BgpServerInstancesubsys=bgp-control-plane
[07:37:34] level=info msg="type:STATE peer:{conf:{local_asn:65001 neighbor_address:\"172.16.100.2\" peer_asn:65011} state:{local_asn:65001 neighbor_address:\"172.16.100.2\" peer_asn:65011 session_state:ESTABLISHED router_id:\"172.16.100.2\"} transport:{local_address:\"172.16.100.1\" local_port:1790 remote_port:40939}}"
[07:37:34] time="2023-05-24T07:33:48Z" level=debug msg="try to connect" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP subsys=basic
[07:37:34] time="2023-05-24T07:33:48Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP new=BGP_FSM_OPENSENTold=BGP_FSM_ACTIVE reason=new-connection subsys=basic
[07:37:34] time="2023-05-24T07:33:48Z" level=info msg="GoBGP test instance: Peer Event: {65001 OPENSENT}"
[07:37:34] level=info msg="type:STATE peer:{conf:{local_asn:65001 neighbor_address:\"172.16.100.3\" peer_asn:65012} state:{local_asn:65001 neighbor_address:\"172.16.100.3\" peer_asn:65012 session_state:OPENSENT router_id:\"<nil>\"} transport:{local_address:\"172.16.100.1\" local_port:1790 remote_port:56241}}"
[07:37:34] level=info msg="type:STATE peer:{conf:{local_asn:65001 neighbor_address:\"172.16.100.3\" peer_asn:65012} state:{local_asn:65001 neighbor_address:\"172.16.100.3\" peer_asn:65012 session_state:OPENCONFIRM router_id:\"172.16.100.2\"} transport:{local_address:\"172.16.100.1\" local_port:1790 remote_port:56241}}"
[07:37:34] time="2023-05-24T07:33:48Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGPnew=BGP_FSM_OPENCONFIRM old=BGP_FSM_OPENSENT reason=open-msg-received subsys=basic
[07:37:34] time="2023-05-24T07:33:48Z" level=info msg="GoBGP test instance: Peer Event: {65001 OPENCONFIRM}"
[07:37:34] time="2023-05-24T07:33:48Z" level=info msg="Peer Up" Key=172.16.100.1 State=BGP_FSM_OPENCONFIRM Topic=Peer asn=65011 component=tests.BGPsubsys=basic
[07:37:34] time="2023-05-24T07:33:48Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGPnew=BGP_FSM_ESTABLISHED old=BGP_FSM_OPENCONFIRM reason=open-msg-negotiated subsys=basic
[07:37:34] time="2023-05-24T07:33:48Z" level=info msg="GoBGP test instance: Peer Event: {65001 ESTABLISHED}"
[07:37:34] level=info msg="Peer Up" Key=172.16.100.3 State=BGP_FSM_OPENCONFIRM Topic=Peer asn=65001 component=gobgp.BgpServerInstancesubsys=bgp-control-plane
[07:37:34] neighbor_test.go:117:
[07:37:34] Error Trace: /home/vagrant/go/src/github.com/cilium/cilium/pkg/bgpv1/test/neighbor_test.go:117
[07:37:34] Error: elements differ
[07:37:34]
[07:37:34] extra elements in list A:
[07:37:34] ([]interface {}) (len=1) {
[07:37:34] (test.peeringState) {
[07:37:34] peerASN: (uint32) 65012,
[07:37:34] peerAddr: (string) (len=12) "172.16.100.3",
[07:37:34] peerSession: (string) (len=11) "established"
[07:37:34] }
[07:37:34] }
[07:37:34]
[07:37:34]
[07:37:34] extra elements in list B:
[07:37:34] ([]interface {}) (len=1) {
[07:37:34] (test.peeringState) {
[07:37:34] peerASN: (uint32) 65012,
[07:37:34] peerAddr: (string) (len=12) "172.16.100.3",
[07:37:34] peerSession: (string) (len=12) "open_confirm"
[07:37:34] }
[07:37:34] }
[07:37:34]
[07:37:34]
[07:37:34] listA:
[07:37:34] ([]test.peeringState) (len=2) {
[07:37:34] (test.peeringState) {
[07:37:34] peerASN: (uint32) 65011,
[07:37:34] peerAddr: (string) (len=12) "172.16.100.2",
[07:37:34] peerSession: (string) (len=11) "established"
[07:37:34] },
[07:37:34] (test.peeringState) {
[07:37:34] peerASN: (uint32) 65012,
[07:37:34] peerAddr: (string) (len=12) "172.16.100.3",
[07:37:34] peerSession: (string) (len=11) "established"
[07:37:34] }
[07:37:34] }
[07:37:34]
[07:37:34]
[07:37:34] listB:
[07:37:34] ([]test.peeringState) (len=2) {
[07:37:34] (test.peeringState) {
[07:37:34] peerASN: (uint32) 65011,
[07:37:34] peerAddr: (string) (len=12) "172.16.100.2",
[07:37:34] peerSession: (string) (len=11) "established"
[07:37:34] },
[07:37:34] (test.peeringState) {
[07:37:34] peerASN: (uint32) 65012,
[07:37:34] peerAddr: (string) (len=12) "172.16.100.3",
[07:37:34] peerSession: (string) (len=12) "open_confirm"
[07:37:34] }
[07:37:34] }
[07:37:34] Test: Test_NeighborAddDel/add_two_neighbors
[07:37:34] Messages: add two neighbors
[07:37:34] level=info msg="type:STATE peer:{conf:{local_asn:65001 neighbor_address:\"172.16.100.3\" peer_asn:65012} state:{local_asn:65001 neighbor_address:\"172.16.100.3\" peer_asn:65012 session_state:ESTABLISHED router_id:\"172.16.100.2\"} transport:{local_address:\"172.16.100.1\" local_port:1790 remote_port:56241}}"