search

antrea-io / antrea

Kubernetes networking based on Open vSwitch
https://antrea.io
Apache License 2.0
1.67k stars 370 forks source link

TestGoBGPLifecycle failed occasionally #6501

Open tnqn opened 4 months ago

tnqn commented 4 months ago

Describe the bug

See https://github.com/antrea-io/antrea/actions/runs/9754329776/job/26921085868

=== RUN   TestGoBGPLifecycle
    gobgp_test.go:65: Starting all BGP servers
    gobgp_test.go:69: Started all BGP servers
    gobgp_test.go:108: Adding BGP peers for BGP server1
I0702 03:08:49.328791   11716 logs.go:48] "Add a peer configuration" Key="127.0.0.1" Topic="Peer"
I0702 03:08:49.328915   11716 logs.go:48] "Add a peer configuration" Key="::1" Topic="Peer"
    gobgp_test.go:111: Added BGP peers for BGP server1
    gobgp_test.go:113: Adding BGP peers for BGP server2
I0702 03:08:49.329028   11716 logs.go:48] "Add a peer configuration" Key="127.0.0.1" Topic="Peer"
    gobgp_test.go:115: Added BGP peers for BGP server2
    gobgp_test.go:117: Adding BGP peers for BGP server3
I0702 03:08:49.329170   11716 logs.go:48] "Add a peer configuration" Key="::1" Topic="Peer"
    gobgp_test.go:119: Added BGP peers for BGP server3
    gobgp_test.go:136: Getting peers of BGP server1 and verifying them
W0702 03:08:49.355965   11716 interface_configuration_linux.go:327] Failed to send gratuitous ARP #2: no such device or address
I0702 03:08:56.329568   11716 logs.go:48] "Peer Up" Key="::1" State="BGP_FSM_OPENCONFIRM" Topic="Peer"
I0702 03:08:56.329584   11716 logs.go:48] "Peer Up" Key="::1" State="BGP_FSM_OPENCONFIRM" Topic="Peer"
I0702 03:08:57.330204   11716 logs.go:44] "Closed an accepted connection" Key="127.0.0.1" State="BGP_FSM_OPENSENT" Topic="Peer"
I0702 03:08:57.330214   11716 logs.go:44] "Closed an accepted connection" Key="127.0.0.1" State="BGP_FSM_OPENSENT" Topic="Peer"
I0702 03:09:08.331918   11716 logs.go:44] "Closed an accepted connection" Key="127.0.0.1" State="BGP_FSM_OPENSENT" Topic="Peer"
I0702 03:09:08.331950   11716 logs.go:44] "Closed an accepted connection" Key="127.0.0.1" State="BGP_FSM_OPENSENT" Topic="Peer"
    gobgp_test.go:137: 
            Error Trace:    /usr/src/antrea.io/antrea/test/integration/agent/gobgp_test.go:140
                                        /usr/local/go/src/runtime/asm_amd64.s:1650
            Error:          Not equal: 
                            expected: sets.Set[string]{"127.0.0.1-62179":sets.Empty{}, "::1-63179":sets.Empty{}}
                            actual  : sets.Set[string]{"::1-63179":sets.Empty{}}

                            Diff:
                            --- Expected
                            +++ Actual
                            @@ -1,4 +1,2 @@
                            -(sets.Set[string]) (len=2) {
                            - (string) (len=15) "127.0.0.1-62179": (sets.Empty) {
                            - },
                            +(sets.Set[string]) (len=1) {
                              (string) (len=9) "::1-63179": (sets.Empty) {
    gobgp_test.go:137: 
            Error Trace:    /usr/src/antrea.io/antrea/test/integration/agent/gobgp_test.go:137
            Error:          Condition never satisfied
            Test:           TestGoBGPLifecycle
    gobgp_test.go:142: Got peers of BGP server1 and verified them
    gobgp_test.go:144: Getting peers of BGP server2 and verifying them
hongliangl commented 4 months ago

Will resolve it.

github-actions[bot] commented 1 month ago

This issue is stale because it has been open 90 days with no activity. Remove stale label or comment, or this will be closed in 90 days

antoninbas commented 3 weeks ago

@hongliangl any progress on this?

hongliangl commented 3 weeks ago

@hongliangl any progress on this?

@antoninbas I have done some investigations and found that the way I use gobgp in the test might be wrong and too tricky. In current test, I started multiple BGP processes with different ports on 127.0.0.1 and let them to establish BGP sessions to each other, and it can work for a local BGP process to establish session to another BGP process. However, it may get failed occasionally. Maybe we could delete or skip the test for a workaround.

antoninbas commented 2 weeks ago

I saw your post in https://github.com/osrg/gobgp/issues/2262, and it is unfortunate that we didn't get more guidance. In our case though, we don't try to add multiple peers with the same remote address to one BGP server. I was also not able to reproduce locally.

I wonder if the issue is not because we "mix" IPv4 and IPv6 in server1?

I feel like rather than removing the test, we could just make it simpler: 2 BGP servers, peering with each other, using IPv4 only. Maybe it will be enough to get the test stable? We can probably still exchange IPv6 routes in the test if we want to, even if the BGP session uses IPv4?

Or, if you want to figure what's going on, you could also try to enable debug logging for gobgp. Although it will get tricky if you cannot reproduce the issue locally.

hongliangl commented 1 week ago

I wonder if the issue is not because we "mix" IPv4 and IPv6 in server1? I feel like rather than removing the test, we could just make it simpler: 2 BGP servers, peering with each other, using IPv4 only. Maybe it will be enough to get the test stable? We can probably still exchange IPv6 routes in the test if we want to, even if the BGP session uses IPv4?

I have simplified the test as above in #6807

Or, if you want to figure what's going on, you could also try to enable debug logging for gobgp. Although it will get tricky if you cannot reproduce the issue locally.

Done in #6807

antoninbas commented 5 days ago

@hongliangl I have seen the job fail again after #6807. Here are the logs. Maybe the extra debug logs can help with the troubleshooting?

TestGoBGPLifecycle logs ``` 2024-11-20T18:04:39.9374707Z === RUN TestGoBGPLifecycle 2024-11-20T18:04:39.9375114Z gobgp_test.go:61: Starting all BGP servers 2024-11-20T18:04:39.9375552Z gobgp_test.go:64: Started all BGP servers 2024-11-20T18:04:39.9376283Z gobgp_test.go:85: Adding BGP peers for BGP server1 2024-11-20T18:04:39.9376922Z I1120 18:03:25.184734 13607 logs.go:48] "Add a peer configuration" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9377589Z gobgp_test.go:87: Added BGP peers for BGP server1 2024-11-20T18:04:39.9378091Z gobgp_test.go:89: Adding BGP peers for BGP server2 2024-11-20T18:04:39.9378708Z I1120 18:03:25.184873 13607 logs.go:48] "Add a peer configuration" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9379505Z I1120 18:03:25.184891 13607 logs.go:52] "IdleHoldTimer expired" Duration=0 Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9380361Z gobgp_test.go:91: Added BGP peers for BGP server2 2024-11-20T18:04:39.9380950Z gobgp_test.go:108: Getting peers of BGP server1 and verifying them 2024-11-20T18:04:39.9382021Z I1120 18:03:25.184931 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_ACTIVE" old="BGP_FSM_IDLE" reason="idle-hold-timer-expired" 2024-11-20T18:04:39.9383048Z I1120 18:03:25.184967 13607 logs.go:52] "IdleHoldTimer expired" Duration=0 Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9384195Z I1120 18:03:25.185010 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_ACTIVE" old="BGP_FSM_IDLE" reason="idle-hold-timer-expired" 2024-11-20T18:04:39.9385318Z W1120 18:03:25.193623 13607 interface_configuration_linux.go:327] Failed to send gratuitous ARP #2: no such device or address 2024-11-20T18:04:39.9386327Z W1120 18:03:25.225673 13607 interface_configuration_linux.go:327] Failed to send gratuitous ARP #2: no such device or address 2024-11-20T18:04:39.9387276Z I1120 18:03:33.185499 13607 logs.go:52] "Accepted a new passive connection" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9388419Z I1120 18:03:33.185535 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_OPENSENT" old="BGP_FSM_ACTIVE" reason="new-connection" 2024-11-20T18:04:39.9389703Z I1120 18:03:33.185498 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_OPENSENT" old="BGP_FSM_ACTIVE" reason="new-connection" 2024-11-20T18:04:39.9390709Z I1120 18:03:33.185573 13607 logs.go:52] "Accepted a new passive connection" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9391636Z I1120 18:03:33.185674 13607 logs.go:44] "Closed an accepted connection" Key="127.0.0.1" State="BGP_FSM_OPENSENT" Topic="Peer" 2024-11-20T18:04:39.9392629Z I1120 18:03:33.185676 13607 logs.go:44] "Closed an accepted connection" Key="127.0.0.1" State="BGP_FSM_OPENSENT" Topic="Peer" 2024-11-20T18:04:39.9393815Z I1120 18:03:33.185719 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_IDLE" old="BGP_FSM_OPENSENT" reason="read-failed" 2024-11-20T18:04:39.9395043Z I1120 18:03:33.185749 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_IDLE" old="BGP_FSM_OPENSENT" reason="read-failed" 2024-11-20T18:04:39.9396024Z I1120 18:03:38.185972 13607 logs.go:52] "IdleHoldTimer expired" Duration=5 Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9396847Z I1120 18:03:38.186037 13607 logs.go:52] "IdleHoldTimer expired" Duration=5 Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9397990Z I1120 18:03:38.186075 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_ACTIVE" old="BGP_FSM_IDLE" reason="idle-hold-timer-expired" 2024-11-20T18:04:39.9399453Z I1120 18:03:38.186086 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_ACTIVE" old="BGP_FSM_IDLE" reason="idle-hold-timer-expired" 2024-11-20T18:04:39.9400486Z I1120 18:03:45.186796 13607 logs.go:52] "Accepted a new passive connection" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9401634Z I1120 18:03:45.186797 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_OPENSENT" old="BGP_FSM_ACTIVE" reason="new-connection" 2024-11-20T18:04:39.9402915Z I1120 18:03:45.186834 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_OPENSENT" old="BGP_FSM_ACTIVE" reason="new-connection" 2024-11-20T18:04:39.9403910Z I1120 18:03:45.186872 13607 logs.go:52] "Accepted a new passive connection" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9404833Z I1120 18:03:45.186972 13607 logs.go:44] "Closed an accepted connection" Key="127.0.0.1" State="BGP_FSM_OPENSENT" Topic="Peer" 2024-11-20T18:04:39.9405826Z I1120 18:03:45.186972 13607 logs.go:44] "Closed an accepted connection" Key="127.0.0.1" State="BGP_FSM_OPENSENT" Topic="Peer" 2024-11-20T18:04:39.9407000Z I1120 18:03:45.187013 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_IDLE" old="BGP_FSM_OPENSENT" reason="read-failed" 2024-11-20T18:04:39.9408532Z I1120 18:03:45.187028 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_IDLE" old="BGP_FSM_OPENSENT" reason="read-failed" 2024-11-20T18:04:39.9409532Z I1120 18:03:50.187264 13607 logs.go:52] "IdleHoldTimer expired" Duration=5 Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9410369Z I1120 18:03:50.187283 13607 logs.go:52] "IdleHoldTimer expired" Duration=5 Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9411511Z I1120 18:03:50.187308 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_ACTIVE" old="BGP_FSM_IDLE" reason="idle-hold-timer-expired" 2024-11-20T18:04:39.9412849Z I1120 18:03:50.187309 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_ACTIVE" old="BGP_FSM_IDLE" reason="idle-hold-timer-expired" 2024-11-20T18:04:39.9413753Z gobgp_test.go:109: 2024-11-20T18:04:39.9414407Z Error Trace: /usr/src/antrea.io/antrea/test/integration/agent/gobgp_test.go:112 2024-11-20T18:04:39.9415241Z /usr/local/go/src/runtime/asm_amd64.s:1700 2024-11-20T18:04:39.9415683Z Error: Not equal: 2024-11-20T18:04:39.9416683Z expected: sets.Set[string]{"127.0.0.1-62179":sets.Empty{}} 2024-11-20T18:04:39.9417314Z actual : sets.Set[string]{} 2024-11-20T18:04:39.9417714Z 2024-11-20T18:04:39.9418040Z Diff: 2024-11-20T18:04:39.9418450Z --- Expected 2024-11-20T18:04:39.9418856Z +++ Actual 2024-11-20T18:04:39.9419291Z @@ -1,4 +1,2 @@ 2024-11-20T18:04:39.9419849Z -(sets.Set[string]) (len=1) { 2024-11-20T18:04:39.9420590Z - (string) (len=15) "127.0.0.1-62179": (sets.Empty) { 2024-11-20T18:04:39.9421109Z - } 2024-11-20T18:04:39.9421526Z +(sets.Set[string]) { 2024-11-20T18:04:39.9421904Z } 2024-11-20T18:04:39.9422205Z gobgp_test.go:109: 2024-11-20T18:04:39.9422844Z Error Trace: /usr/src/antrea.io/antrea/test/integration/agent/gobgp_test.go:109 2024-11-20T18:04:39.9423481Z Error: Condition never satisfied 2024-11-20T18:04:39.9423915Z Test: TestGoBGPLifecycle 2024-11-20T18:04:39.9424420Z gobgp_test.go:114: Got peers of BGP server1 and verified them 2024-11-20T18:04:39.9425043Z gobgp_test.go:116: Getting peers of BGP server2 and verifying them 2024-11-20T18:04:39.9425766Z I1120 18:03:55.188030 13607 logs.go:52] "Accepted a new passive connection" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9426748Z I1120 18:03:55.188058 13607 logs.go:52] "stop connect loop" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9427826Z I1120 18:03:55.188075 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_OPENSENT" old="BGP_FSM_ACTIVE" reason="new-connection" 2024-11-20T18:04:39.9429125Z I1120 18:03:55.188031 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_OPENSENT" old="BGP_FSM_ACTIVE" reason="new-connection" 2024-11-20T18:04:39.9430438Z I1120 18:03:55.188267 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_OPENCONFIRM" old="BGP_FSM_OPENSENT" reason="open-msg-received" 2024-11-20T18:04:39.9431789Z I1120 18:03:55.188285 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_OPENCONFIRM" old="BGP_FSM_OPENSENT" reason="open-msg-received" 2024-11-20T18:04:39.9432830Z I1120 18:03:55.188322 13607 logs.go:48] "Peer Up" Key="127.0.0.1" State="BGP_FSM_OPENCONFIRM" Topic="Peer" 2024-11-20T18:04:39.9434026Z I1120 18:03:55.188336 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_ESTABLISHED" old="BGP_FSM_OPENCONFIRM" reason="open-msg-negotiated" 2024-11-20T18:04:39.9435081Z I1120 18:03:55.188347 13607 logs.go:48] "Peer Up" Key="127.0.0.1" State="BGP_FSM_OPENCONFIRM" Topic="Peer" 2024-11-20T18:04:39.9436414Z I1120 18:03:55.188372 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_ESTABLISHED" old="BGP_FSM_OPENCONFIRM" reason="open-msg-negotiated" 2024-11-20T18:04:39.9437610Z I1120 18:03:55.188531 13607 logs.go:52] "EOR received" AddressFamily="ipv4-unicast" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9438596Z I1120 18:03:55.188534 13607 logs.go:52] "EOR received" AddressFamily="ipv4-unicast" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9439371Z gobgp_test.go:122: Got peers of BGP server2 and verified them 2024-11-20T18:04:39.9439941Z gobgp_test.go:135: Advertising routes on BGP server1 2024-11-20T18:04:39.9440557Z I1120 18:03:56.186763 13607 logs.go:52] "create Destination" Nlri="1.1.0.0/24" Topic="Table" 2024-11-20T18:04:39.9441282Z I1120 18:03:56.186834 13607 logs.go:52] "create Destination" Nlri="1.2.0.0/24" Topic="Table" 2024-11-20T18:04:39.9442005Z I1120 18:03:56.186884 13607 logs.go:52] "create Destination" Nlri="1.3.0.0/24" Topic="Table" 2024-11-20T18:04:39.9442643Z gobgp_test.go:137: Advertised routes on BGP server1 2024-11-20T18:04:39.9443157Z gobgp_test.go:139: Advertising routes on BGP server2 2024-11-20T18:04:39.9443750Z I1120 18:03:56.186975 13607 logs.go:52] "create Destination" Nlri="1.1.0.0/24" Topic="Table" 2024-11-20T18:04:39.9444464Z I1120 18:03:56.186989 13607 logs.go:52] "create Destination" Nlri="1.1.0.0/24" Topic="Table" 2024-11-20T18:04:39.9445179Z I1120 18:03:56.187020 13607 logs.go:52] "create Destination" Nlri="2.1.0.0/24" Topic="Table" 2024-11-20T18:04:39.9445885Z I1120 18:03:56.187047 13607 logs.go:52] "create Destination" Nlri="1.2.0.0/24" Topic="Table" 2024-11-20T18:04:39.9446600Z I1120 18:03:56.187062 13607 logs.go:52] "create Destination" Nlri="1.2.0.0/24" Topic="Table" 2024-11-20T18:04:39.9447296Z I1120 18:03:56.187078 13607 logs.go:52] "create Destination" Nlri="1.3.0.0/24" Topic="Table" 2024-11-20T18:04:39.9448087Z I1120 18:03:56.187091 13607 logs.go:52] "create Destination" Nlri="1.3.0.0/24" Topic="Table" 2024-11-20T18:04:39.9448797Z I1120 18:03:56.187118 13607 logs.go:52] "create Destination" Nlri="2.2.0.0/24" Topic="Table" 2024-11-20T18:04:39.9449514Z I1120 18:03:56.187186 13607 logs.go:52] "create Destination" Nlri="2.3.0.0/24" Topic="Table" 2024-11-20T18:04:39.9450227Z I1120 18:03:56.187189 13607 logs.go:52] "create Destination" Nlri="2.1.0.0/24" Topic="Table" 2024-11-20T18:04:39.9450936Z I1120 18:03:56.187208 13607 logs.go:52] "create Destination" Nlri="2.1.0.0/24" Topic="Table" 2024-11-20T18:04:39.9451564Z gobgp_test.go:141: Advertised routes on BGP server2 2024-11-20T18:04:39.9452194Z gobgp_test.go:151: Getting received routes of BGP server1 and verifying them 2024-11-20T18:04:39.9453032Z I1120 18:03:56.187269 13607 logs.go:52] "create Destination" Nlri="2.2.0.0/24" Topic="Table" 2024-11-20T18:04:39.9453750Z I1120 18:03:56.187282 13607 logs.go:52] "create Destination" Nlri="2.2.0.0/24" Topic="Table" 2024-11-20T18:04:39.9454464Z I1120 18:03:56.187292 13607 logs.go:52] "create Destination" Nlri="2.3.0.0/24" Topic="Table" 2024-11-20T18:04:39.9455168Z I1120 18:03:56.187312 13607 logs.go:52] "create Destination" Nlri="2.3.0.0/24" Topic="Table" 2024-11-20T18:04:39.9456094Z gobgp_test.go:157: Got received routes of BGP server1 and verified them 2024-11-20T18:04:39.9456814Z gobgp_test.go:159: Getting received routes of BGP server2 and verifying them 2024-11-20T18:04:39.9457513Z gobgp_test.go:165: Got received routes of BGP server2 and verified them 2024-11-20T18:04:39.9458109Z gobgp_test.go:182: Withdrawing routes on BGP server1 2024-11-20T18:04:39.9458651Z gobgp_test.go:184: Withdrew routes on BGP server1 2024-11-20T18:04:39.9459165Z gobgp_test.go:186: Withdrawing routes on BGP server2 2024-11-20T18:04:39.9459667Z gobgp_test.go:188: Withdrew routes on BGP server2 2024-11-20T18:04:39.9460278Z gobgp_test.go:190: Getting received routes of BGP server1 and verifying them 2024-11-20T18:04:39.9460985Z gobgp_test.go:197: Getting received routes of BGP server2 and verifying them 2024-11-20T18:04:39.9461832Z gobgp_test.go:203: Got received routes of BGP server2 and verified them 2024-11-20T18:04:39.9462424Z gobgp_test.go:214: Updating peers of BGP server1 2024-11-20T18:04:39.9463058Z I1120 18:04:00.189417 13607 logs.go:48] "Delete a peer configuration" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9463839Z I1120 18:04:00.189476 13607 logs.go:48] "Add a peer configuration" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9464469Z gobgp_test.go:216: Updated peers of server1 2024-11-20T18:04:39.9465028Z gobgp_test.go:218: Getting peers of BGP server1 and verifying them 2024-11-20T18:04:39.9465825Z I1120 18:04:00.189570 13607 logs.go:48] "Peer Down" Key="127.0.0.1" Reason="dying" State="BGP_FSM_ESTABLISHED" Topic="Peer" 2024-11-20T18:04:39.9466729Z I1120 18:04:00.189619 13607 logs.go:52] "IdleHoldTimer expired" Duration=0 Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9467615Z I1120 18:04:00.189606 13607 logs.go:44] "received notification" Code=6 Data="" Key="127.0.0.1" Subcode=6 Topic="Peer" 2024-11-20T18:04:39.9468518Z I1120 18:04:00.189653 13607 logs.go:52] "freed fsm.h" Key="127.0.0.1" State="BGP_FSM_ESTABLISHED" Topic="Peer" 2024-11-20T18:04:39.9469712Z I1120 18:04:00.189684 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_ACTIVE" old="BGP_FSM_IDLE" reason="idle-hold-timer-expired" 2024-11-20T18:04:39.9471253Z I1120 18:04:00.189725 13607 logs.go:48] "Peer Down" Key="127.0.0.1" Reason="notification-received code 6(cease) subcode 6(other configuration change)" State="BGP_FSM_ESTABLISHED" Topic="Peer" 2024-11-20T18:04:39.9473002Z I1120 18:04:00.189752 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_IDLE" old="BGP_FSM_ESTABLISHED" reason="notification-received code 6(cease) subcode 6(other configuration change)" 2024-11-20T18:04:39.9474231Z I1120 18:04:05.189948 13607 logs.go:52] "IdleHoldTimer expired" Duration=5 Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9475386Z I1120 18:04:05.189997 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_ACTIVE" old="BGP_FSM_IDLE" reason="idle-hold-timer-expired" 2024-11-20T18:04:39.9476413Z I1120 18:04:07.190223 13607 logs.go:52] "Accepted a new passive connection" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9477537Z I1120 18:04:07.190223 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_OPENSENT" old="BGP_FSM_ACTIVE" reason="new-connection" 2024-11-20T18:04:39.9478467Z I1120 18:04:07.190262 13607 logs.go:52] "stop connect loop" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9479528Z I1120 18:04:07.190282 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_OPENSENT" old="BGP_FSM_ACTIVE" reason="new-connection" 2024-11-20T18:04:39.9480998Z I1120 18:04:07.190423 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_OPENCONFIRM" old="BGP_FSM_OPENSENT" reason="open-msg-received" 2024-11-20T18:04:39.9482346Z I1120 18:04:07.190423 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_OPENCONFIRM" old="BGP_FSM_OPENSENT" reason="open-msg-received" 2024-11-20T18:04:39.9483380Z I1120 18:04:07.190499 13607 logs.go:48] "Peer Up" Key="127.0.0.1" State="BGP_FSM_OPENCONFIRM" Topic="Peer" 2024-11-20T18:04:39.9484581Z I1120 18:04:07.190527 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_ESTABLISHED" old="BGP_FSM_OPENCONFIRM" reason="open-msg-negotiated" 2024-11-20T18:04:39.9485639Z I1120 18:04:07.190502 13607 logs.go:48] "Peer Up" Key="127.0.0.1" State="BGP_FSM_OPENCONFIRM" Topic="Peer" 2024-11-20T18:04:39.9486827Z I1120 18:04:07.190592 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_ESTABLISHED" old="BGP_FSM_OPENCONFIRM" reason="open-msg-negotiated" 2024-11-20T18:04:39.9487829Z I1120 18:04:07.190732 13607 logs.go:52] "create Destination" Nlri="2.1.0.0/24" Topic="Table" 2024-11-20T18:04:39.9488553Z I1120 18:04:07.190754 13607 logs.go:52] "create Destination" Nlri="2.2.0.0/24" Topic="Table" 2024-11-20T18:04:39.9489386Z I1120 18:04:07.190769 13607 logs.go:52] "create Destination" Nlri="2.1.0.0/24" Topic="Table" 2024-11-20T18:04:39.9490104Z I1120 18:04:07.190782 13607 logs.go:52] "create Destination" Nlri="1.2.0.0/24" Topic="Table" 2024-11-20T18:04:39.9490804Z I1120 18:04:07.190793 13607 logs.go:52] "create Destination" Nlri="2.2.0.0/24" Topic="Table" 2024-11-20T18:04:39.9491524Z I1120 18:04:07.190797 13607 logs.go:52] "create Destination" Nlri="1.1.0.0/24" Topic="Table" 2024-11-20T18:04:39.9492238Z I1120 18:04:07.190814 13607 logs.go:52] "create Destination" Nlri="1.2.0.0/24" Topic="Table" 2024-11-20T18:04:39.9493146Z I1120 18:04:07.190824 13607 logs.go:52] "EOR received" AddressFamily="ipv4-unicast" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9493963Z I1120 18:04:07.190834 13607 logs.go:52] "create Destination" Nlri="1.1.0.0/24" Topic="Table" 2024-11-20T18:04:39.9494859Z I1120 18:04:07.190854 13607 logs.go:52] "EOR received" AddressFamily="ipv4-unicast" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9495668Z gobgp_test.go:224: Got peers of BGP server1 and verified them 2024-11-20T18:04:39.9496513Z gobgp_test.go:226: Deleting peers of BGP server1 2024-11-20T18:04:39.9497154Z I1120 18:04:08.190057 13607 logs.go:48] "Delete a peer configuration" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9497824Z gobgp_test.go:228: Deleted peers of BGP server1 2024-11-20T18:04:39.9498404Z gobgp_test.go:230: Getting peers of BGP server1 and verifying them 2024-11-20T18:04:39.9499216Z I1120 18:04:08.190171 13607 logs.go:44] "received notification" Code=6 Data="" Key="127.0.0.1" Subcode=3 Topic="Peer" 2024-11-20T18:04:39.9500175Z I1120 18:04:08.190204 13607 logs.go:48] "Peer Down" Key="127.0.0.1" Reason="dying" State="BGP_FSM_ESTABLISHED" Topic="Peer" 2024-11-20T18:04:39.9501106Z I1120 18:04:08.190237 13607 logs.go:52] "freed fsm.h" Key="127.0.0.1" State="BGP_FSM_ESTABLISHED" Topic="Peer" 2024-11-20T18:04:39.9502440Z I1120 18:04:08.190262 13607 logs.go:48] "Peer Down" Key="127.0.0.1" Reason="notification-received code 6(cease) subcode 3(peer deconfigured)" State="BGP_FSM_ESTABLISHED" Topic="Peer" 2024-11-20T18:04:39.9504112Z I1120 18:04:08.190298 13607 logs.go:52] "state changed" Key="127.0.0.1" Topic="Peer" new="BGP_FSM_IDLE" old="BGP_FSM_ESTABLISHED" reason="notification-received code 6(cease) subcode 3(peer deconfigured)" 2024-11-20T18:04:39.9505220Z gobgp_test.go:236: Got peers of BGP server1 and verified them 2024-11-20T18:04:39.9505746Z gobgp_test.go:238: Stopping all BGP servers 2024-11-20T18:04:39.9506349Z I1120 18:04:09.190443 13607 logs.go:48] "Delete a peer configuration" Key="127.0.0.1" Topic="Peer" 2024-11-20T18:04:39.9507320Z I1120 18:04:09.190521 13607 logs.go:52] "freed fsm.h" Key="127.0.0.1" State="BGP_FSM_IDLE" Topic="Peer" 2024-11-20T18:04:39.9507978Z gobgp_test.go:241: Stopped all BGP servers 2024-11-20T18:04:39.9508406Z --- FAIL: TestGoBGPLifecycle (44.01s) ```