search

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

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

False positive on `test_delete_circuit_id` (low consistency interval & overload) #181

Closed viniarck closed 1 year ago

viniarck commented 1 year ago

For the record, on Nov 7th nightly execution test_delete_circuit_id resulted in a false positive, the consistency check reinstalled flows that were deleted likely because of an overload, deletion FlowMod was sent, kytos/of_core.flow_stats.received events were received, so this is to highlight existing problems that a low interval of the consistency check can bring, it would take longer to converge until the system is responsive:

------------------------------- start/stop times -------------------------------
tests/test_e2e_12_mef_eline.py::TestE2EMefEline::test_delete_circuit_id: 2022-11-07,09:04:23.782889 - 2022-11-07,09:04:34.041078
=========================== short test summary info ============================
FAILED tests/test_e2e_12_mef_eline.py::TestE2EMefEline::test_delete_circuit_id
= 1 failed, 179 passed, 2 skipped, 18 xfailed, 8 xpassed, 793 warnings in 10787.70s (2:59:47) =

        # Verify that the flow is not in the flow table
        s1 = self.net.net.get('s1')
        flows_s1 = s1.dpctl('dump-flows')
        # Each switch had BASIC_FLOWS flows + 02 for the EVC (ingress + egress)
        # at this point the flow number should be reduced to BASIC_FLOWS
>       assert len(flows_s1.split('\r\n ')) == BASIC_FLOWS, flows_s1
E       AssertionError:  cookie=0x0, duration=21.688s, table=0, n_packets=0, n_bytes=0, priority=50000,dl_src=ee:ee:ee:ee:ee:03 actions=CONTROLLER:65535
E          cookie=0x0, duration=21.676s, table=0, n_packets=0, n_bytes=0, priority=50000,dl_src=ee:ee:ee:ee:ee:02 actions=CONTROLLER:65535
E          cookie=0xaab71dbfcb308941, duration=1.482s, table=0, n_packets=0, n_bytes=0, in_port="s1-eth1" actions=output:"s1-eth2"
E          cookie=0xaab71dbfcb308941, duration=1.447s, table=0, n_packets=0, n_bytes=0, in_port="s1-eth2" actions=output:"s1-eth1"
E          cookie=0xab00000000000001, duration=24.702s, table=0, n_packets=14, n_bytes=588, priority=1000,dl_vlan=3799,dl_type=0x88cc actions=CONTROLLER:65535
E         
E       assert 5 == 3
E        +  where 5 = len([' cookie=0x0, duration=21.688s, table=0, n_packets=0, n_bytes=0, priority=50000,dl_src=ee:ee:ee:ee:ee:03 actions=CONT...n=24.702s, 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=21.688s, table=0, n_packets=0, n_bytes=0, priority=50000,dl_src=ee:ee:ee:ee:ee:03 actions=CONT...n=24.702s, 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 0x7f99cc009fe0>('\r\n ')
E        +      where <built-in method split of str object at 0x7f99cc009fe0> = ' cookie=0x0, duration=21.688s, table=0, n_packets=0, n_bytes=0, priority=50000,dl_src=ee:ee:ee:ee:ee:03 actions=CONTR...on=24.702s, 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_12_mef_eline.py:389: AssertionError

Nov  7 09:04:29 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:29,659 (MainThread) kytos.core.buffers:DEBUG buffers:92:  [buffer: app] Removed: kytos/of_core.flow_stats.received
Nov  7 09:04:29 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:29,659 (MainThread) kytos.core.controller:DEBUG controller:562:  looking for listeners for kytos/of_core.flow_stats.received
Nov  7 09:04:29 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:29,659 (MainThread) kytos.core.controller:DEBUG controller:571:  Calling listeners for kytos/of_core.flow_stats.received

Nov  7 09:04:23 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:23,710 (Thread-104) kytos.napps.kytos/mef_eline:INFO evc:672:  EVC(b71dbfcb308941, my evc1) was deployed.
Nov  7 09:04:23 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:23,716 (Thread-104) werkzeug:INFO _internal:225:  127.0.0.1 - - [07/Nov/2022 09:04:23] "#033[35m#033[1mPOST /api/kytos/mef_eline/v2/evc/ HTTP/1.1#033[0m" 201 -
Nov  7 09:04:23 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:23,774 (Thread-110) werkzeug:INFO _internal:225:  127.0.0.1 - - [07/Nov/2022 09:04:23] "GET /api/kytos/mef_eline/v2/evc/b71dbfcb308941 HTTP/1.1" 200 -
Nov  7 09:04:23 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:23,813 (Thread-111) kytos.napps.kytos/mef_eline:INFO main:324:  Removing EVC(b71dbfcb308941, my evc1)
Nov  7 09:04:23 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:23,844 (Thread-112) kytos.napps.kytos/flow_manager:INFO main:585:  Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: delete, force: True, flows_dict: {'flows': [{'cookie': 12301333616770713921, 'cookie_mask': 18446744073709551615}], 'force': True}
Nov  7 09:04:23 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:23,909 (Thread-112) werkzeug:INFO _internal:225:  127.0.0.1 - - [07/Nov/2022 09:04:23] "#033[35m#033[1mPOST /api/kytos/flow_manager/v2/delete/00:00:00:00:00:00:00:01 HTTP/1.1#033[0m" 202 -
Nov  7 09:04:23 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:23,961 (Thread-111) kytos.napps.kytos/mef_eline:INFO main:333:  EVC removed. EVC(b71dbfcb308941, my evc1)
Nov  7 09:04:23 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:23,964 (Thread-111) werkzeug:INFO _internal:225:  127.0.0.1 - - [07/Nov/2022 09:04:23] "DELETE /api/kytos/mef_eline/v2/evc/b71dbfcb308941 HTTP/1.1" 200 -
Nov  7 09:04:32 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:32,542 (thread_pool_sb_3) kytos.napps.kytos/flow_manager:INFO main:361:  Consistency check: missing flow on switch 00:00:00:00:00:00:00:01.
Nov  7 09:04:32 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:32,553 (thread_pool_sb_3) kytos.napps.kytos/flow_manager:INFO main:365:  Flow forwarded to switch 00:00:00:00:00:00:00:01 to be installed. Flow: {'flows': [{'cookie': 12301333616770713921, 'match': {'in_port': 1}, 'actions': [{'action_type': 'output', 'port': 2}], 'table_id': 0, 'priority': 32768, 'idle_timeout': 0, 'hard_timeout': 0}]}
Nov  7 09:04:32 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:32,553 (thread_pool_sb_3) kytos.napps.kytos/flow_manager:INFO main:361:  Consistency check: missing flow on switch 00:00:00:00:00:00:00:01.
Nov  7 09:04:32 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:32,567 (thread_pool_sb_3) kytos.napps.kytos/flow_manager:INFO main:365:  Flow forwarded to switch 00:00:00:00:00:00:00:01 to be installed. Flow: {'flows': [{'cookie': 12301333616770713921, 'match': {'in_port': 2}, 'actions': [{'action_type': 'output', 'port': 1}], 'table_id': 0, 'priority': 32768, 'idle_timeout': 0, 'hard_timeout': 0}]}
Nov  7 09:04:33 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:33,998 (Thread-122) werkzeug:INFO _internal:225:  127.0.0.1 - - [07/Nov/2022 09:04:33] "GET /api/kytos/mef_eline/v2/evc/ HTTP/1.1" 200 -
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,088 (MainThread) kytos.napps.kytos/of_core:INFO main:600:  Modified Interface('s1-eth1', 1, Switch('00:00:00:00:00:00:00:01')) 00:00:00:00:00:00:00:01:1
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,206 (MainThread) kytos.napps.kytos/of_core:INFO main:600:  Modified Interface('s1-eth2', 2, Switch('00:00:00:00:00:00:00:01')) 00:00:00:00:00:00:00:01:2
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,306 (MainThread) kytos.napps.kytos/of_core:INFO main:600:  Modified Interface('s1-eth3', 3, Switch('00:00:00:00:00:00:00:01')) 00:00:00:00:00:00:00:01:3
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,420 (MainThread) kytos.napps.kytos/of_core:INFO main:600:  Modified Interface('s2-eth2', 2, Switch('00:00:00:00:00:00:00:02')) 00:00:00:00:00:00:00:02:2
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,549 (thread_pool_app_5) kytos.napps.kytos/mef_eline:INFO main:648:  Event handle_link_down Link(Interface('s1-eth3', 3, Switch('00:00:00:00:00:00:00:01')), Interface('s2-eth2', 2, Switch('00:00:00:00:00:00:00:02')))
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,665 (MainThread) kytos.napps.kytos/of_core:INFO main:600:  Modified Interface('s2-eth1', 1, Switch('00:00:00:00:00:00:00:02')) 00:00:00:00:00:00:00:02:1
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,699 (MainThread) kytos.napps.kytos/of_core:INFO main:600:  Modified Interface('s2-eth3', 3, Switch('00:00:00:00:00:00:00:02')) 00:00:00:00:00:00:00:02:3
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,742 (MainThread) kytos.napps.kytos/of_core:INFO main:600:  Modified Interface('s3-eth2', 2, Switch('00:00:00:00:00:00:00:03')) 00:00:00:00:00:00:00:03:2
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,772 (thread_pool_app_4) kytos.napps.kytos/mef_eline:INFO main:648:  Event handle_link_down Link(Interface('s1-eth3', 3, Switch('00:00:00:00:00:00:00:01')), Interface('s2-eth2', 2, Switch('00:00:00:00:00:00:00:02')))
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,824 (thread_pool_app_0) kytos.napps.kytos/mef_eline:INFO main:648:  Event handle_link_down Link(Interface('s3-eth2', 2, Switch('00:00:00:00:00:00:00:03')), Interface('s2-eth3', 3, Switch('00:00:00:00:00:00:00:02')))
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,856 (thread_pool_app_4) kytos.napps.kytos/mef_eline:INFO main:648:  Event handle_link_down Link(Interface('s3-eth2', 2, Switch('00:00:00:00:00:00:00:03')), Interface('s2-eth3', 3, Switch('00:00:00:00:00:00:00:02')))
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,865 (MainThread) kytos.napps.kytos/of_core:INFO main:600:  Modified Interface('s3-eth1', 1, Switch('00:00:00:00:00:00:00:03')) 00:00:00:00:00:00:00:03:1
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,969 (thread_pool_app_3) kytos.napps.kytos/mef_eline:INFO main:648:  Event handle_link_down Link(Interface('s1-eth4', 4, Switch('00:00:00:00:00:00:00:01')), Interface('s3-eth3', 3, Switch('00:00:00:00:00:00:00:03')))
Nov  7 09:04:34 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:34,984 (thread_pool_app_5) kytos.napps.kytos/mef_eline:INFO main:648:  Event handle_link_down Link(Interface('s1-eth4', 4, Switch('00:00:00:00:00:00:00:01')), Interface('s3-eth3', 3, Switch('00:00:00:00:00:00:00:03')))
Nov  7 09:04:35 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:35,040 (MainThread) kytos.core.atcp_server:INFO atcp_server:182:  Connection lost with client 127.0.0.1:33652. Reason: Request closed by client
Nov  7 09:04:35 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:35,044 (MainThread) kytos.core.atcp_server:INFO atcp_server:182:  Connection lost with client 127.0.0.1:33654. Reason: Request closed by client
Nov  7 09:04:35 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:35,052 (MainThread) kytos.core.atcp_server:INFO atcp_server:182:  Connection lost with client 127.0.0.1:33656. Reason: Request closed by client
Nov  7 09:04:38 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:38,442 (MainThread) kytos.core.atcp_server:INFO atcp_server:131:  New connection from 127.0.0.1:33688
Nov  7 09:04:40 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:40,923 (MainThread) kytos.core.atcp_server:INFO atcp_server:131:  New connection from 127.0.0.1:33690
Nov  7 09:04:40 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:40,923 (MainThread) kytos.core.atcp_server:INFO atcp_server:131:  New connection from 127.0.0.1:33692
Nov  7 09:04:40 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:40,935 (MainThread) kytos.core.atcp_server:INFO atcp_server:131:  New connection from 127.0.0.1:33694
Nov  7 09:04:40 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:40,953 (MainThread) kytos.core.controller:INFO kytosd:114:  Stopping Kytos controller...
Nov  7 09:04:40 runner-rmtk68xb-project-107-concurrent-0 2022-11-07 09:04:40,953 (MainThread) kytos.core.controller:INFO controller:479:  Stopping Kytos
viniarck commented 1 year ago

PR #178 should help out to mitigate this type of false positive.

viniarck commented 1 year ago

I'll go ahead and close this. With all of the fixes that have landed no recent failures have happened.