search

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

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

wrong return on switches is_connected #121

Open italovalcy opened 2 years ago

italovalcy commented 2 years ago

One of the end-to-end tests failed today with the following error:

=================================== FAILURES ===================================
91__________________ TestE2EMefEline.test_155_patch_evc_active ___________________
92self = <tests.test_e2e_13_mef_eline.TestE2EMefEline object at 0x7f14c6710e80>
93    def test_155_patch_evc_active(self):
94        api_url = KYTOS_API + '/mef_eline/v2/evc/'
95        evc1 = self.create_evc(100)
96    
97        payload = {
98            "active": False,
99        }
100    
101        # It sets a new circuit's creation_time
102        response = requests.patch(api_url + evc1, data=json.dumps(payload),
103                                  headers={'Content-type': 'application/json'})
104        assert response.status_code == 400, response.text
105    
106        # It verifies EVC's data
107        response = requests.get(api_url + evc1)
108        data = response.json()
109>       assert data['active'] is True
110E       assert False is True
111tests/test_e2e_13_mef_eline.py:941: AssertionError
112
...
------------------------------- start/stop times -------------------------------
147tests/test_e2e_13_mef_eline.py::TestE2EMefEline::test_155_patch_evc_active: 2022-02-14,06:17:25.439752 - 2022-02-14,06:17:26.088959
148

Looking at the logs for this specific execution test (around 2022-02-14 06:17:25), and filtering for specific events, we can see something interesting:

Feb 14 06:17:16 runner-rmtk68xb-project-107-concurrent-0 2022-02-14 06:17:16,423 (MainThread) kytos.core.controller:INFO controller:268:  Starting Kytos - Kytos Controller
Feb 14 06:17:22 runner-rmtk68xb-project-107-concurrent-0 2022-02-14 06:17:22,227 (ThreadPoolExecutor-0_3) kytos.napps.kytos/of_core:INFO main:177:  Connection ('127.0.0.1', 41978), Switch 00:00:00:00:00:00:00:01: OPENFLOW HANDSHAKE COMPLETE
Feb 14 06:17:22 runner-rmtk68xb-project-107-concurrent-0 2022-02-14 06:17:22,256 (ThreadPoolExecutor-0_2) kytos.napps.kytos/of_core:INFO main:177:  Connection ('127.0.0.1', 41980), Switch 00:00:00:00:00:00:00:03: OPENFLOW HANDSHAKE COMPLETE
Feb 14 06:17:22 runner-rmtk68xb-project-107-concurrent-0 2022-02-14 06:17:22,283 (ThreadPoolExecutor-0_0) kytos.napps.kytos/of_core:INFO main:177:  Connection ('127.0.0.1', 41982), Switch 00:00:00:00:00:00:00:02: OPENFLOW HANDSHAKE COMPLETE
Feb 14 06:17:25 runner-rmtk68xb-project-107-concurrent-0 2022-02-14 06:17:25,833 (Thread-21) werkzeug:INFO _internal:113:  127.0.0.1 - - [14/Feb/2022 06:17:25] "#033[37mPOST /api/kytos/mef_eline/v2/evc/ HTTP/1.1#033[0m" 201 -
Feb 14 06:17:25 runner-rmtk68xb-project-107-concurrent-0 2022-02-14 06:17:25,928 (Thread-28) werkzeug:INFO _internal:113:  127.0.0.1 - - [14/Feb/2022 06:17:25] "#033[31m#033[1mPATCH /api/kytos/mef_eline/v2/evc/eb0b290238a548 HTTP/1.1#033[0m" 400 -

What surprises me about the above log messages is: the switches finished the connection at 06:17:22 (OPENFLOW HANDSHAKE COMPLETE) and the EVC creation was finished 3 seconds later. This behavior is incoherent with the testing definition, especially the setup_method, which should restart Kytos, wait until the switches connect, and then wait additional 10 seconds: https://github.com/amlight/kytos-end-to-end-tests/blob/master/tests/test_e2e_13_mef_eline.py#L29-L31

The only possible explanation is: after kytos was stopped, the switches, remained connected for a few seconds (they didn't detect the connection down) and right after starting kytos, the self.net.wait_switches_connect call returned a wrong return.

Ideally, we should also reset the switch's connections after killing Kytos. Maybe PR #120 will help on this issue, since we will do some waiting time there, but I think it is worthy finding a solution to this behavior.

italovalcy commented 2 years ago

I'm investigating other executions and the one below seems to be also related to this problem. The failure:

=================================== FAILURES ===================================
91_ TestE2EMaintenance.test_045_patch_mw_on_switch_should_fail_wrong_payload_on_dates _
92self = <tests.test_e2e_15_maintenance.TestE2EMaintenance object at 0x7f80d54149d0>
93    def test_045_patch_mw_on_switch_should_fail_wrong_payload_on_dates(self):
94        """
95        400 response calling
96            /api/kytos/maintenance/{mw_id} on PATCH
97        """
98    
99>       self.restart_and_create_circuit()
100tests/test_e2e_15_maintenance.py:391: 
101_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
102tests/test_e2e_15_maintenance.py:64: in restart_and_create_circuit
103    self.create_circuit(100)
104_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
105vlan_id = 100
106    @staticmethod
107    def create_circuit(vlan_id):
108        payload = {
109            "name": "my evc1",
110            "enabled": True,
111            "dynamic_backup_path": True,
112            "uni_a": {
113                "interface_id": "00:00:00:00:00:00:00:01:1",
114                "tag": {
115                    "tag_type": 1,
116                    "value": vlan_id
117                }
118            },
119            "uni_z": {
120                "interface_id": "00:00:00:00:00:00:00:03:1",
121                "tag": {
122                    "tag_type": 1,
123                    "value": vlan_id
124                }
125            },
126            "primary_path": [
127                {"endpoint_a": {"id": "00:00:00:00:00:00:00:01:3"},
128                 "endpoint_b": {"id": "00:00:00:00:00:00:00:02:2"}},
129                {"endpoint_a": {"id": "00:00:00:00:00:00:00:02:3"},
130                 "endpoint_b": {"id": "00:00:00:00:00:00:00:03:2"}}
131            ],
132        }
133        api_url = KYTOS_API + '/mef_eline/v2/evc/'
134        response = requests.post(api_url, json=payload)
135>       assert response.status_code == 201, response.text
136E       AssertionError: {"code":400,"description":"primary_path is not valid: Link 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'))) is not available.","name":"Bad Request"}
137E         
138E       assert 400 == 201
139E        +  where 400 = <Response [400]>.status_code
140tests/test_e2e_15_maintenance.py:58: AssertionError
141
...
------------------------------- start/stop times -------------------------------
[176](https://gitlab.ampath.net/kytos/kytos-end-to-end-tester/-/jobs/21269#L176)tests/test_e2e_15_maintenance.py::TestE2EMaintenance::test_045_patch_mw_on_switch_should_fail_wrong_payload_on_dates: 2022-02-09,06:36:06.861196 - 2022-02-09,06:36:23.193179
[177](https://gitlab.ampath.net/kytos/kytos-end-to-end-tester/-/jobs/21269#L177)

Looking for the log messages for this execution:

# egrep "HANDSHAKE|POST.*evc|Starting Kyto" log2
Feb  9 06:36:13 runner-rmtk68xb-project-107-concurrent-0 2022-02-09 06:36:13,611 (MainThread) kytos.core.controller:INFO controller:268:  Starting Kytos - Kytos Controller
Feb  9 06:36:19 runner-rmtk68xb-project-107-concurrent-0 2022-02-09 06:36:19,541 (ThreadPoolExecutor-0_2) kytos.napps.kytos/of_core:INFO main:177:  Connection ('127.0.0.1', 60966), Switch 00:00:00:00:00:00:00:03: OPENFLOW HANDSHAKE COMPLETE
Feb  9 06:36:19 runner-rmtk68xb-project-107-concurrent-0 2022-02-09 06:36:19,538 (ThreadPoolExecutor-0_3) kytos.napps.kytos/of_core:INFO main:177:  Connection ('127.0.0.1', 60964), Switch 00:00:00:00:00:00:00:01: OPENFLOW HANDSHAKE COMPLETE
Feb  9 06:36:19 runner-rmtk68xb-project-107-concurrent-0 2022-02-09 06:36:19,552 (ThreadPoolExecutor-0_1) kytos.napps.kytos/of_core:INFO main:177:  Connection ('127.0.0.1', 60968), Switch 00:00:00:00:00:00:00:02: OPENFLOW HANDSHAKE COMPLETE
Feb  9 06:36:23 runner-rmtk68xb-project-107-concurrent-0 2022-02-09 06:36:23,183 (Thread-21) werkzeug:INFO _internal:113:  127.0.0.1 - - [09/Feb/2022 06:36:23] "#033[31m#033[1mPOST /api/kytos/mef_eline/v2/evc/ HTTP/1.1#033[0m" 400 -

Once again, pay attention that the controller was started 06:36:13, the switches finished the connection setup at 06:36:19, but the POST to create an EVC was executed 06:36:23 (10 seconds after the controller starts, not 10 seconds after the switches connect).

italovalcy commented 2 years ago

Another case, from tests executed Feb 11st, 2022: two failures.

Failure 1:

____________ TestE2EMaintenance.test_075_delete_future_mw_on_switch ____________
92self = <tests.test_e2e_15_maintenance.TestE2EMaintenance object at 0x7f78da9a6820>
93    def test_075_delete_future_mw_on_switch(self):
94        """Tests the maintenance window removing process on a scheduled MW
95        Test:
96            /api/kytos/maintenance/ on POST and
97            /api/kytos/maintenance/{mw_id} on DELETE
98        """
99    
100>       self.restart_and_create_circuit()
101tests/test_e2e_15_maintenance.py:749: 
102_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
103tests/test_e2e_15_maintenance.py:64: in restart_and_create_circuit
104    self.create_circuit(100)
105_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
106vlan_id = 100
107    @staticmethod
108    def create_circuit(vlan_id):
109        payload = {
110            "name": "my evc1",
111            "enabled": True,
112            "dynamic_backup_path": True,
113            "uni_a": {
114                "interface_id": "00:00:00:00:00:00:00:01:1",
115                "tag": {
116                    "tag_type": 1,
117                    "value": vlan_id
118                }
119            },
120            "uni_z": {
121                "interface_id": "00:00:00:00:00:00:00:03:1",
122                "tag": {
123                    "tag_type": 1,
124                    "value": vlan_id
125                }
126            },
127            "primary_path": [
128                {"endpoint_a": {"id": "00:00:00:00:00:00:00:01:3"},
129                 "endpoint_b": {"id": "00:00:00:00:00:00:00:02:2"}},
130                {"endpoint_a": {"id": "00:00:00:00:00:00:00:02:3"},
131                 "endpoint_b": {"id": "00:00:00:00:00:00:00:03:2"}}
132            ],
133        }
134        api_url = KYTOS_API + '/mef_eline/v2/evc/'
135        response = requests.post(api_url, json=payload)
136>       assert response.status_code == 201, response.text
137E       AssertionError: {"code":400,"description":"primary_path is not valid: Link 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'))) is not available.","name":"Bad Request"}
138E         
139E       assert 400 == 201
140E        +  where 400 = <Response [400]>.status_code
141tests/test_e2e_15_maintenance.py:58: AssertionError
142
...
------------------------------- start/stop times -------------------------------
221tests/test_e2e_15_maintenance.py::TestE2EMaintenance::test_075_delete_future_mw_on_switch: 2022-02-11,06:40:47.526309 - 2022-02-11,06:41:03.823734

From log messages:

# egrep "HANDSHAKE|POST.*evc|Starting Kyto" log3
Feb 11 06:40:54 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 06:40:54,616 (MainThread) kytos.core.controller:INFO controller:268:  Starting Kytos - Kytos Controller
Feb 11 06:41:00 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 06:41:00,328 (ThreadPoolExecutor-0_2) kytos.napps.kytos/of_core:INFO main:177:  Connection ('127.0.0.1', 43152), Switch 00:00:00:00:00:00:00:01: OPENFLOW HANDSHAKE COMPLETE
Feb 11 06:41:00 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 06:41:00,336 (ThreadPoolExecutor-0_1) kytos.napps.kytos/of_core:INFO main:177:  Connection ('127.0.0.1', 43154), Switch 00:00:00:00:00:00:00:03: OPENFLOW HANDSHAKE COMPLETE
Feb 11 06:41:00 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 06:41:00,363 (ThreadPoolExecutor-0_3) kytos.napps.kytos/of_core:INFO main:177:  Connection ('127.0.0.1', 43156), Switch 00:00:00:00:00:00:00:02: OPENFLOW HANDSHAKE COMPLETE
Feb 11 06:41:03 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 06:41:03,820 (Thread-21) werkzeug:INFO _internal:113:  127.0.0.1 - - [11/Feb/2022 06:41:03] "#033[31m#033[1mPOST /api/kytos/mef_eline/v2/evc/ HTTP/1.1#033[0m" 400 -

Again, the EVC creation happened 10 seconds after Kytos startup, rather than 10 sec after the switches connect.

Failure 2:

_________________ TestE2EFlowManager.test_050_add_action_flow __________________
145self = <tests.test_e2e_20_flow_manager.TestE2EFlowManager object at 0x7f78da91cdc0>
146    def test_050_add_action_flow(self):
147>       self.add_action_flow()
148tests/test_e2e_20_flow_manager.py:438: 
149_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
150self = <tests.test_e2e_20_flow_manager.TestE2EFlowManager object at 0x7f78da91cdc0>
151restart_kytos = False
152    def add_action_flow(self, restart_kytos=False):
153    
154        payload = {
155            "flows": [
156                {
157                    "priority": 10,
158                    "idle_timeout": 360,
159                    "hard_timeout": 1200,
160                    "match": {
161                        "in_port": 1
162                    },
163                    "actions": [
164                        {"action_type": "output", "port": 2}
165                    ]
166                }
167            ]
168        }
169    
170        api_url = KYTOS_API + '/flow_manager/v2/flows/00:00:00:00:00:00:00:01'
171        requests.post(api_url, data=json.dumps(payload),
172                      headers={'Content-type': 'application/json'})
173    
174        # wait for the flow to be installed
175        time.sleep(10)
176    
177        # Verify the flow
178        s1 = self.net.net.get('s1')
179        flows_s1 = s1.dpctl('dump-flows')
180>       assert len(flows_s1.split('\r\n ')) == 2
181E       AssertionError: assert 1 == 2
182E        +  where 1 = len([' cookie=0xab00000000000001, duration=5.471s, table=0, n_packets=2, n_bytes=84, priority=1000,dl_vlan=3799,dl_type=0x88cc actions=CONTROLLER:65535\r\n'])
183E        +    where [' cookie=0xab00000000000001, duration=5.471s, table=0, n_packets=2, n_bytes=84, priority=1000,dl_vlan=3799,dl_type=0x88cc actions=CONTROLLER:65535\r\n'] = <built-in method split of str object at 0x7f78da9a4850>('\r\n ')
184E        +      where <built-in method split of str object at 0x7f78da9a4850> = ' cookie=0xab00000000000001, duration=5.471s, table=0, n_packets=2, n_bytes=84, priority=1000,dl_vlan=3799,dl_type=0x88cc actions=CONTROLLER:65535\r\n'.split
185tests/test_e2e_20_flow_manager.py:420: AssertionError
186
...
222tests/test_e2e_20_flow_manager.py::TestE2EFlowManager::test_050_add_action_flow: 2022-02-11,07:01:37.179378 - 2022-02-11,07:01:47.211812

From the log messages:

# egrep "HANDSHAKE|POST.*flow_manager.*00:01|Send FlowMod|Starting Kyto" log4
Feb 11 07:01:28 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 07:01:28,561 (MainThread) kytos.core.controller:INFO controller:268:  Starting Kytos - Kytos Controller
Feb 11 07:01:37 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 07:01:37,189 (Thread-12) kytos.napps.kytos/flow_manager:INFO main:737:  Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: add, force: False, flows_dict: {'flows': [{'priority': 10, 'idle_timeout': 360, 'hard_timeout': 1200, 'match': {'in_port': 1}, 'actions': [{'action_type': 'output', 'port': 2}]}]}
Feb 11 07:01:37 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 07:01:37,191 (Thread-12) werkzeug:INFO _internal:113:  127.0.0.1 - - [11/Feb/2022 07:01:37] "#033[33mPOST /api/kytos/flow_manager/v2/flows/00:00:00:00:00:00:00:01 HTTP/1.1#033[0m" 404 -
Feb 11 07:01:41 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 07:01:41,531 (ThreadPoolExecutor-0_4) kytos.napps.kytos/of_core:INFO main:177:  Connection ('127.0.0.1', 44344), Switch 00:00:00:00:00:00:00:01: OPENFLOW HANDSHAKE COMPLETE
Feb 11 07:01:41 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 07:01:41,537 (ThreadPoolExecutor-0_0) kytos.napps.kytos/of_core:INFO main:177:  Connection ('127.0.0.1', 44346), Switch 00:00:00:00:00:00:00:03: OPENFLOW HANDSHAKE COMPLETE
Feb 11 07:01:41 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 07:01:41,542 (ThreadPoolExecutor-0_1) kytos.napps.kytos/of_core:INFO main:177:  Connection ('127.0.0.1', 44348), Switch 00:00:00:00:00:00:00:02: OPENFLOW HANDSHAKE COMPLETE
Feb 11 07:01:41 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 07:01:41,605 (Thread-14) kytos.napps.kytos/flow_manager:INFO main:737:  Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: add, force: False, flows_dict: {'flows': [{'priority': 1000, 'table_id': 0, 'cookie': 12321848580485677057, 'match': {'dl_type': 35020, 'dl_vlan': 3799}, 'actions': [{'action_type': 'output', 'port': 4294967293}]}]}
Feb 11 07:01:41 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 07:01:41,610 (Thread-15) kytos.napps.kytos/flow_manager:INFO main:737:  Send FlowMod from request dpid: 00:00:00:00:00:00:00:03, command: add, force: False, flows_dict: {'flows': [{'priority': 1000, 'table_id': 0, 'cookie': 12321848580485677059, 'match': {'dl_type': 35020, 'dl_vlan': 3799}, 'actions': [{'action_type': 'output', 'port': 4294967293}]}]}
Feb 11 07:01:41 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 07:01:41,625 (Thread-14) werkzeug:INFO _internal:113:  127.0.0.1 - - [11/Feb/2022 07:01:41] "#033[37mPOST /api/kytos/flow_manager/v2/flows/00:00:00:00:00:00:00:01 HTTP/1.1#033[0m" 202 -
Feb 11 07:01:41 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 07:01:41,639 (ThreadPoolExecutor-0_4) urllib3.connectionpool:DEBUG connectionpool:452:  http://localhost:8181 "POST /api/kytos/flow_manager/v2/flows/00:00:00:00:00:00:00:01 HTTP/1.1" 202 37
Feb 11 07:01:41 runner-rmtk68xb-project-107-concurrent-0 2022-02-11 07:01:41,666 (Thread-18) kytos.napps.kytos/flow_manager:INFO main:737:  Send FlowMod from request dpid: 00:00:00:00:00:00:00:02, command: add, force: False, flows_dict: {'flows': [{'priority': 1000, 'table_id': 0, 'cookie': 12321848580485677058, 'match': {'dl_type': 35020, 'dl_vlan': 3799}, 'actions': [{'action_type': 'output', 'port': 4294967293}]}]}

We can again observe that the FlowMod was sent even before the switches get connected (the flow_manager API even returned error 404, but our test is not taking that into consideration).