search

kytos-ng / kytos-end-to-end-tests

Kytos End-to-End Tests
0 stars 10 forks source link

test_020_create_evc_inter_switch -> `was not deployed. No available path was found.` #173

Closed viniarck closed 1 year ago

viniarck commented 1 year ago

On October 16th, test_020_create_evc_inter_switch failed, since no path was found it didn't get deployed:

------------------------------- start/stop times -------------------------------
tests/test_e2e_10_mef_eline.py::TestE2EMefEline::test_020_create_evc_inter_switch: 2022-10-16,04:31:45.462340 - 2022-10-16,04:31:55.792864
=========================== short test summary info ============================
FAILED tests/test_e2e_10_mef_eline.py::TestE2EMefEline::test_020_create_evc_inter_switch
= 1 failed, 171 passed, 2 skipped, 18 xfailed, 8 xpassed, 758 warnings in 10683.08s (2:58:03) =
>       assert len(flows_s1.split('\r\n ')) == BASIC_FLOWS + 3, flows_s1
E       AssertionError:  cookie=0x0, duration=18.912s, table=0, n_packets=0, n_bytes=0, priority=50000,dl_src=ee:ee:ee:ee:ee:02 actions=CONTROLLER:65535
E          cookie=0x0, duration=18.897s, table=0, n_packets=0, n_bytes=0, priority=50000,dl_src=ee:ee:ee:ee:ee:03 actions=CONTROLLER:65535
E          cookie=0xab00000000000001, duration=21.832s, table=0, n_packets=14, n_bytes=588, priority=1000,dl_vlan=3799,dl_type=0x88cc actions=CONTROLLER:65535
E         
E       assert 3 == (3 + 3)
E        +  where 3 = len([' cookie=0x0, duration=18.912s, table=0, n_packets=0, n_bytes=0, priority=50000,dl_src=ee:ee:ee:ee:ee:02 actions=CONT...n=21.832s, table=0, n_packets=14, n_bytes=588, priority=1000,dl_vlan=3799,dl_type=0x88cc actions=CONTROLLER:65535\r\n'])
E        +    where [' cookie=0x0, duration=18.912s, table=0, n_packets=0, n_bytes=0, priority=50000,dl_src=ee:ee:ee:ee:ee:02 actions=CONT...n=21.832s, table=0, n_packets=14, n_bytes=588, priority=1000,dl_vlan=3799,dl_type=0x88cc actions=CONTROLLER:65535\r\n'] = <built-in method split of str object at 0x7f7cd7fe93d0>('\r\n ')
E        +      where <built-in method split of str object at 0x7f7cd7fe93d0> = ' cookie=0x0, duration=18.912s, table=0, n_packets=0, n_bytes=0, priority=50000,dl_src=ee:ee:ee:ee:ee:02 actions=CONTR...on=21.832s, table=0, n_packets=14, n_bytes=588, priority=1000,dl_vlan=3799,dl_type=0x88cc actions=CONTROLLER:65535\r\n'.split
tests/test_e2e_10_mef_eline.py:178: AssertionError

It's unexpected since looking at the debug event logs pathfinder got the topology updated accordingly:

Oct 16 04:31:27 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:27,970 (MainThread) kytos.core.controller:DEBUG controller:557:  looking for listeners for kytos/topology.topology_loaded
Oct 16 04:31:27 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:27,970 (MainThread) kytos.core.controller:DEBUG controller:566:  Calling listeners for kytos/topology.topology_loaded
Oct 16 04:31:27 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:27,972 (thread_pool_app_0) kytos.napps.kytos/pathfinder:DEBUG main:237:  Topology graph updated.
Oct 16 04:31:27 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:27,973 (MainThread) kytos.core.buffers:DEBUG buffers:92:  [buffer: app] Removed: kytos/topology.loaded

Oct 16 04:31:45 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:45,606 (Thread-103) kytos.napps.kytos/flow_manager:INFO main:583:  Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: delete, force: True, flows_dict: {'flows': [{'cookie': 12302533030856836679, 'cookie_mask': 18446744073709551615}], 'force': True}
Oct 16 04:31:45 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:45,623 (Thread-103) werkzeug:INFO _internal:225:  127.0.0.1 - - [16/Oct/2022 04:31:45] "#033[35m#033[1mPOST /api/kytos/flow_manager/v2/delete/00:00:00:00:00:00:00:01 HTTP/1.1#033[0m" 202 -
Oct 16 04:31:45 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:45,657 (Thread-104) kytos.napps.kytos/flow_manager:INFO main:583:  Send FlowMod from request dpid: 00:00:00:00:00:00:00:02, command: delete, force: True, flows_dict: {'flows': [{'cookie': 12302533030856836679, 'cookie_mask': 18446744073709551615}], 'force': True}
Oct 16 04:31:45 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:45,674 (Thread-104) werkzeug:INFO _internal:225:  127.0.0.1 - - [16/Oct/2022 04:31:45] "#033[35m#033[1mPOST /api/kytos/flow_manager/v2/delete/00:00:00:00:00:00:00:02 HTTP/1.1#033[0m" 202 -
Oct 16 04:31:45 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:45,731 (Thread-105) werkzeug:INFO _internal:225:  127.0.0.1 - - [16/Oct/2022 04:31:45] "POST /api/kytos/pathfinder/v2/ HTTP/1.1" 200 -
Oct 16 04:31:45 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:45,735 (Thread-100) kytos.napps.kytos/mef_eline:WARNING evc:611:  EVC(bb609c25bb4647, my evc1) was not deployed. No available path was found.
Oct 16 04:31:45 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:45,742 (Thread-100) werkzeug:INFO _internal:225:  127.0.0.1 - - [16/Oct/2022 04:31:45] "#033[35m#033[1mPOST /api/kytos/mef_eline/v2/evc/ HTTP/1.1#033[0m" 201 -
Oct 16 04:31:47 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:47,960 (Thread-109) werkzeug:INFO _internal:225:  127.0.0.1 - - [16/Oct/2022 04:31:47] "PUT /api/amlight/sdntrace_cp/trace HTTP/1.1" 200 -
Oct 16 04:31:47 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:47,977 (Thread-110) werkzeug:INFO _internal:225:  127.0.0.1 - - [16/Oct/2022 04:31:47] "PUT /api/amlight/sdntrace_cp/trace HTTP/1.1" 200 -
Oct 16 04:31:47 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:47,979 (mef_eline) kytos.napps.kytos/mef_eline:INFO main:100:  EVC(bb609c25bb4647, my evc1) enabled but inactive - activating
Oct 16 04:31:56 runner-rmtk68xb-project-107-concurrent-0 2022-10-16 04:31:56,029 (MainThread) kytos.core.controller:INFO kytosd:114:  Stopping Kytos controller...

I haven't found any other cause on topology that might have led to this yet.

On another test case, there was a similar behavior where the EVC didn't get deployed as highlighted on this comment https://github.com/amlight/kytos-end-to-end-tests/issues/160#issuecomment-1278151550, consistency check didn't get triggered pre-maturely with a short interval this time.

viniarck commented 1 year ago

On yesterday's nightly execution, same error but in a different test test_120_patch_queue_id:

------------------------------- start/stop times -------------------------------
tests/test_e2e_10_mef_eline.py::TestE2EMefEline::test_120_patch_queue_id: 2022-10-18,04:49:24.183312 - 2022-10-18,04:49:34.604396
=========================== short test summary info ============================
FAILED tests/test_e2e_10_mef_eline.py::TestE2EMefEline::test_120_patch_queue_id
= 1 failed, 171 passed, 2 skipped, 18 xfailed, 8 xpassed, 758 warnings in 10641.94s (2:57:21) =

Oct 18 04:49:24 runner-rmtk68xb-project-107-concurrent-0 2022-10-18 04:49:24,479 (Thread-108) werkzeug:INFO _internal:225:  127.0.0.1 - - [18/Oct/2022 04:49:24] "POST /api/kytos/pathfinder/v2/ HTTP/1.1" 200 -
Oct 18 04:49:24 runner-rmtk68xb-project-107-concurrent-0 2022-10-18 04:49:24,492 (Thread-103) werkzeug:INFO _internal:225:  127.0.0.1 - - [18/Oct/2022 04:49:24] "#033[35m#033[1mPOST /api/kytos/mef_eline/v2/evc/ HTTP/1.1#033[0m" 201 -
Oct 18 04:49:24 runner-rmtk68xb-project-107-concurrent-0 2022-10-18 04:49:24,489 (Thread-103) kytos.napps.kytos/mef_eline:WARNING evc:659:  EVC(a9903606afaf42, Vlan_100) was not deployed. No available path was found.
viniarck commented 1 year ago

Over the past 3 days this issue hasn't occurred, https://github.com/kytos-ng/pathfinder/pull/35 fixed it from the evidence that we have so far.

I'll go ahead and close the issue.