Skip to content

CI: privileged: bgpv1/test: Test_NeighborAddDel: did not receive expected peering state ["ESTABLISHED"]: context deadline exceeded #35872

@joestringer

Description

@joestringer

CI failure

https://github.com/cilium/cilium/actions/runs/11748172520/job/32731731791#step:17:11239

┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓
┃   FAIL  package: github.com/cilium/cilium/pkg/bgpv1/test   ┃
┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛

--- FAIL: Test_NeighborAddDel (60.07s)

time="2024-11-08T19:33:04Z" level=info msg="deleting dummy links"
time="2024-11-08T19:33:04Z" level=info msg="adding dummy links"
time="2024-11-08T19:33:04Z" level=info msg="GoBGP test instance: starting"
time="2024-11-08T19:33:04Z" level=info msg="Add a peer configuration" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP subsys=basic
time="2024-11-08T19:33:04Z" level=debug msg="IdleHoldTimer expired" Duration=0 Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP subsys=basic
time="2024-11-08T19:33:04Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP new=BGP_FSM_ACTIVE old=BGP_FSM_IDLE reason=idle-hold-timer-expired subsys=basic
time="2024-11-08T19:33:04Z" level=info msg="GoBGP test instance: starting"
time="2024-11-08T19:33:04Z" level=info msg="Add a peer configuration" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:33:04Z" level=debug msg="IdleHoldTimer expired" Duration=0 Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:33:04Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_ACTIVE old=BGP_FSM_IDLE reason=idle-hold-timer-expired subsys=basic
    logger.go:257: time=2024-11-08T19:33:04.380Z level=INFO source=/host/vendor/github.com/cilium/hive/hive.go:338 msg=Starting
time="2024-11-08T19:33:04.383648555Z" level=info msg="Using v1.Endpoints" subsys=k8s
    logger.go:257: time=2024-11-08T19:33:04.384Z level=INFO source=/host/vendor/github.com/cilium/hive/hive.go:342 msg=Started duration=2.678335ms
time="2024-11-08T19:34:04Z" level=info msg="GoBGP test instance: stopping"
time="2024-11-08T19:34:04Z" level=info msg="Delete a peer configuration" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP subsys=basic
time="2024-11-08T19:34:04Z" level=debug msg="stop connect loop" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP subsys=basic
time="2024-11-08T19:34:04Z" level=debug msg="freed fsm.h" Key=172.16.100.1 State=BGP_FSM_ACTIVE Topic=Peer asn=65011 component=tests.BGP subsys=basic
time="2024-11-08T19:34:04Z" level=info msg="GoBGP test instance: stopping"
time="2024-11-08T19:34:04Z" level=info msg="Delete a peer configuration" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:34:04Z" level=debug msg="stop connect loop" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:34:04Z" level=debug msg="freed fsm.h" Key=172.16.100.1 State=BGP_FSM_ACTIVE Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:34:04Z" level=error msg="failed to close existing tcp connection" Key=172.16.100.1 State=BGP_FSM_ACTIVE Topic=Peer asn=65012 component=tests.BGP subsys=basic
    logger.go:257: time=2024-11-08T19:34:04.337Z level=INFO source=/host/vendor/github.com/cilium/hive/hive.go:354 msg=Stopping
time="2024-11-08T19:34:04Z" level=info msg="deleting dummy links"

--- FAIL: Test_NeighborAddDel/add_two_neighbors (59.95s)

time="2024-11-08T19:33:04Z" level=info msg="GoBGP test instance: Peer Event: {0 IDLE}"
time="2024-11-08T19:33:04Z" level=info msg="GoBGP test instance: Peer Event: {65001 IDLE}"
time="2024-11-08T19:33:04Z" level=info msg="GoBGP test instance: Peer Event: {65001 ACTIVE}"
time="2024-11-08T19:33:04.485413958Z" level=info msg="Cilium BGP Control Plane Controller now running..." component=Controller.Run subsys=bgp-control-plane
time="2024-11-08T19:33:04.485621917Z" level=info msg="Registering BGP servers for policy with local ASN 65001" component=manager.registerBGPServer subsys=bgp-control-plane
time="2024-11-08T19:33:04.485892571Z" level=error msg="Error while registering new BGP server for local ASN 65001." component=manager.add error="failed initial reconciliation for peer config with local ASN 65001: reconciliation of virtual router with local ASN 65001 failed: failed to list endpoints from diffstore: the store has not initialized yet" subsys=bgp-control-plane
time="2024-11-08T19:33:10Z" level=debug msg="try to connect" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP subsys=basic
time="2024-11-08T19:33:10Z" level=debug msg="try to connect" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:33:10Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_OPENSENT old=BGP_FSM_ACTIVE reason=new-connection subsys=basic
time="2024-11-08T19:33:10.376033165Z" level=info msg="Can't find configuration for a new passive connection" Key=172.16.100.3 Topic=Peer asn=65001 component=gobgp.BgpServerInstance subsys=bgp-control-plane
time="2024-11-08T19:33:10Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_IDLE old=BGP_FSM_OPENSENT reason=read-failed subsys=basic
time="2024-11-08T19:33:14Z" level=debug msg="failed to connect" Error="dial tcp 172.16.100.2:0->172.16.100.1:1790: i/o timeout" Key=172.16.100.1 Topic=Peer asn=65011 component=tests.BGP subsys=basic
time="2024-11-08T19:33:15Z" level=debug msg="IdleHoldTimer expired" Duration=5 Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:33:15Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_ACTIVE old=BGP_FSM_IDLE reason=idle-hold-timer-expired subsys=basic
time="2024-11-08T19:33:20Z" level=debug msg="try to connect" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:33:20Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_OPENSENT old=BGP_FSM_ACTIVE reason=new-connection subsys=basic
time="2024-11-08T19:33:20.378997735Z" level=info msg="Can't find configuration for a new passive connection" Key=172.16.100.3 Topic=Peer asn=65001 component=gobgp.BgpServerInstance subsys=bgp-control-plane
time="2024-11-08T19:33:20Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_IDLE old=BGP_FSM_OPENSENT reason=read-failed subsys=basic
time="2024-11-08T19:33:25Z" level=debug msg="IdleHoldTimer expired" Duration=5 Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:33:25Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_ACTIVE old=BGP_FSM_IDLE reason=idle-hold-timer-expired subsys=basic
time="2024-11-08T19:33:31Z" level=debug msg="try to connect" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:33:31.38280504Z" level=info msg="Can't find configuration for a new passive connection" Key=172.16.100.3 Topic=Peer asn=65001 component=gobgp.BgpServerInstance subsys=bgp-control-plane
time="2024-11-08T19:33:31Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_OPENSENT old=BGP_FSM_ACTIVE reason=new-connection subsys=basic
time="2024-11-08T19:33:31Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_IDLE old=BGP_FSM_OPENSENT reason=read-failed subsys=basic
time="2024-11-08T19:33:36Z" level=debug msg="IdleHoldTimer expired" Duration=5 Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:33:36Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_ACTIVE old=BGP_FSM_IDLE reason=idle-hold-timer-expired subsys=basic
time="2024-11-08T19:33:44Z" level=debug msg="try to connect" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:33:44Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_OPENSENT old=BGP_FSM_ACTIVE reason=new-connection subsys=basic
time="2024-11-08T19:33:44.391627158Z" level=info msg="Can't find configuration for a new passive connection" Key=172.16.100.3 Topic=Peer asn=65001 component=gobgp.BgpServerInstance subsys=bgp-control-plane
time="2024-11-08T19:33:44Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_IDLE old=BGP_FSM_OPENSENT reason=read-failed subsys=basic
time="2024-11-08T19:33:49Z" level=debug msg="IdleHoldTimer expired" Duration=5 Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:33:49Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_ACTIVE old=BGP_FSM_IDLE reason=idle-hold-timer-expired subsys=basic
time="2024-11-08T19:33:55Z" level=debug msg="try to connect" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:33:55Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_OPENSENT old=BGP_FSM_ACTIVE reason=new-connection subsys=basic
time="2024-11-08T19:33:55.394139551Z" level=info msg="Can't find configuration for a new passive connection" Key=172.16.100.3 Topic=Peer asn=65001 component=gobgp.BgpServerInstance subsys=bgp-control-plane
time="2024-11-08T19:33:55Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_IDLE old=BGP_FSM_OPENSENT reason=read-failed subsys=basic
time="2024-11-08T19:34:00Z" level=debug msg="IdleHoldTimer expired" Duration=5 Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP subsys=basic
time="2024-11-08T19:34:00Z" level=debug msg="state changed" Key=172.16.100.1 Topic=Peer asn=65012 component=tests.BGP new=BGP_FSM_ACTIVE old=BGP_FSM_IDLE reason=idle-hold-timer-expired subsys=basic
    neighbor_test.go:153: 
        	Error Trace:	/host/pkg/bgpv1/test/neighbor_test.go:153
        	Error:      	Received unexpected error:
        	            	did not receive expected peering state ["ESTABLISHED"]: context deadline exceeded
        	Test:       	Test_NeighborAddDel/add_two_neighbors
        	Messages:   	add two neighbors

--- FAIL: Test_NeighborAddDel/delete_both_neighbors (0.00s)

    neighbor_test.go:153: 
        	Error Trace:	/host/pkg/bgpv1/test/neighbor_test.go:153
        	Error:      	Received unexpected error:
        	            	did not receive expected peering state ["IDLE" "ACTIVE"]: context deadline exceeded
        	Test:       	Test_NeighborAddDel/delete_both_neighbors
        	Messages:   	delete both neighbors

--- FAIL: Test_NeighborAddDel/update_both_neighbors (0.00s)

    neighbor_test.go:153: 
        	Error Trace:	/host/pkg/bgpv1/test/neighbor_test.go:153
        	Error:      	Received unexpected error:
        	            	did not receive expected peering state ["ESTABLISHED"]: context deadline exceeded
        	Test:       	Test_NeighborAddDel/update_both_neighbors
        	Messages:   	update both neighbors

Metadata

Metadata

Labels

area/CIContinuous Integration testing issue or flakearea/bgpImpacts the Border Gateway Protocol feature.ci/flakeThis is a known failure that occurs in the tree. Please investigate me!

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions