search

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

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

test_001_create_delete_create_with_constraints -> pathfinder updating graph error #179

Closed viniarck closed 1 year ago

viniarck commented 1 year ago

This test test_001_create_delete_create_with_constraints failed on yesterday's nightly execution, it seems related to be of the cause of the No available path was found. issue that was also reported recently: 

tests/test_e2e_15_mef_eline.py::TestE2EMefEline::test_001_create_delete_create_with_constraints: 2022-10-28,06:02:59.477496 - 2022-10-28,06:03:10.186329

Oct 28 06:03:00 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:03:00,156 (Thread-111) werkzeug:INFO _internal:225:  127.0.0.1 - - [28/Oct/2022 06:03:00] "POST /api/kytos/pathfinder/v2/ HTTP/1.1" 200 -
Oct 28 06:03:00 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:03:00,158 (Thread-106) kytos.napps.kytos/mef_eline:WARNING evc:659:  EVC(17c1ec574dde46, Vlan_100) was not deployed. No available path was found.

Looking into the logs about a few seconds before pytest register the beginning of the test, kytos/topology.updated had been sent, and the graph updated, and POST /api/kytos/topology/v3/links/78282c4d5b579265f04ebadc4405ca1b49628eb1d684bb45e5d0607fa8b713d0/metadata HTTP/1.1 returned 201. So, from topology's perspective the link does exist and had been published, however, pathfinder end up crashing with a key error since it didn't find it, there might be a race condition, I'll keep investigating.

Oct 28 06:02:51 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:51,197 (thread_pool_app_5) kytos.napps.kytos/mef_eline:DEBUG main:634:  Event handle_link_up kytos/topology.link_up
Oct 28 06:02:51 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:51,199 (thread_pool_app_5) kytos.napps.kytos/mef_eline:DEBUG main:634:  Event handle_link_up kytos/topology.link_up
Oct 28 06:02:51 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:51,199 (thread_pool_app_5) kytos.napps.kytos/mef_eline:DEBUG main:634:  Event handle_link_up kytos/topology.link_up
Oct 28 06:02:51 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:51,199 (thread_pool_app_5) kytos.napps.kytos/pathfinder:DEBUG main:237:  Topology graph updated.
Oct 28 06:02:51 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:51,206 (thread_pool_app_1) kytos.napps.kytos/pathfinder:DEBUG main:237:  Topology graph updated.
Oct 28 06:02:51 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:51,217 (MainThread) kytos.core.controller:DEBUG controller:571:  Calling listeners for kytos/topology.updated
Oct 28 06:02:51 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:51,218 (MainThread) kytos.core.buffers:DEBUG buffers:92:  [buffer: app] Removed: kytos/topology.updated
Oct 28 06:02:51 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:51,218 (MainThread) kytos.core.controller:DEBUG controller:562:  looking for listeners for kytos/topology.updated
Oct 28 06:02:51 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:51,218 (MainThread) kytos.core.controller:DEBUG controller:571:  Calling listeners for kytos/topology.updated
Oct 28 06:02:51 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:51,218 (MainThread) kytos.core.controller:DEBUG controller:571:  Calling listeners for kytos/topology.updated
Oct 28 06:02:51 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:51,224 (thread_pool_app_7) kytos.napps.kytos/pathfinder:DEBUG main:237:  Topology graph updated.

Oct 28 06:02:59 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:59,535 (Thread-103) werkzeug:INFO _internal:225:  127.0.0.1 - - [28/Oct/2022 06:02:59] "#033[35m#033[1mPOST /api/kytos/topology/v3/links/78282c4d5b579265f04ebadc4405ca1b49628eb1d684bb45e5d0607fa8b713d0/metadata HTTP/1.1#033[0m" 201 -
Oct 28 06:02:59 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:59,537 (MainThread) kytos.core.controller:DEBUG controller:625:  Connection ('127.0.0.1', 44702): OUT OFP, version: 4, type: Type.OFPT_MULTIPART_REQUEST, xid: 1628728354 - 0412001861146c220004000000000000ffffffff00000000
Oct 28 06:02:59 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:59,538 (MainThread) kytos.core.controller:DEBUG controller:562:  looking for listeners for kytos/of_core.v0x04.messages.out.ofpt_multipart_request
Oct 28 06:02:59 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:59,546 (MainThread) kytos.core.atcp_server:DEBUG atcp_server:163:  New data from 127.0.0.1:44702 (744 bytes)
Oct 28 06:02:59 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:59,550 (MainThread) kytos.core.buffers:DEBUG buffers:63:  [buffer: raw] Added: kytos/core.openflow.raw.in
Oct 28 06:02:59 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:59,551 (MainThread) kytos.core.buffers:DEBUG buffers:92:  [buffer: app] Removed: kytos/topology.links.metadata.added
Oct 28 06:02:59 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:59,552 (MainThread) kytos.core.controller:DEBUG controller:562:  looking for listeners for kytos/topology.links.metadata.added
Oct 28 06:02:59 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:59,552 (MainThread) kytos.core.controller:DEBUG controller:571:  Calling listeners for kytos/topology.links.metadata.added
Oct 28 06:02:59 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:59,553 (MainThread) kytos.core.buffers:DEBUG buffers:92:  [buffer: raw] Removed: kytos/core.openflow.raw.in
Oct 28 06:02:59 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:59,553 (MainThread) kytos.core.controller:DEBUG controller:562:  looking for listeners for kytos/core.openflow.raw.in
Oct 28 06:02:59 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:59,553 (MainThread) kytos.core.controller:DEBUG controller:571:  Calling listeners for kytos/core.openflow.raw.in
Oct 28 06:02:59 runner-rmtk68xb-project-107-concurrent-0 2022-10-28 06:02:59,560 (thread_pool_app_0) kytos.core.helpers:ERROR helpers:130:  listen_to handler: <function Main.on_links_metadata_changed at 0x7fe3b4260790>, args: (<Main(pathfinder, stopped 140615425591040)>, KytosEvent('kytos/topology.links.metadata.added', {'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'))), 'metadata': {'last_status_is_active': True, 'link_name': 's1-eth3-s2-eth2', 'ownership': 'red'}}, 0)) traceback: Traceback (most recent call last):,   File "/usr/local/lib/python3.9/dist-packages/kytos/core/helpers.py", line 126, in handler_context,     result = handler(*args),   File "//var/lib/kytos/napps/kytos/pathfinder/main.py", line 244, in on_links_metadata_changed,     self.graph.update_link_metadata(link),   File "//var/lib/kytos/napps/../napps/kytos/pathfinder/graph.py", line 82, in update_link_metadata,     self.graph[endpoint_a][endpoint_b][key] = value,   File "/usr/local/lib/python3.9/dist-packages/networkx/classes/coreviews.py", line 54, in __getitem__,     return self._atlas[key], KeyError: '00:00:00:00:00:00:00:02:2',
viniarck commented 1 year ago

This hasn't happened more recently over the past week, I'll go ahead and close it, the related fixes worked.