Invalid trace from uni_a -- issue when uni_a is the last switch on the topology ordered list

[italovalcy]

How to reproduce:

1. Get kytos running with latest docker version (amlight/kytos) and Mininet with linear topology tmux new-sess -d -s mn mn --topo linear,3 --controller=remote,ip=127.0.0.1
2. enable all switches, interfaces and links
3. create an EVC with UNI A being the last switch in the ordered list of switch's dpid

   vlan=101; curl -H 'Content-type: application/json' -X POST http://127.0.0.1:8181/api/kytos/mef_eline/v2/evc/ -d '{"name": "evc-vlan-'$vlan'", "dynamic_backup_path": true,  "uni_z": {"tag": {"value": '$vlan', "tag_type": 1}, "interface_id": "00:00:00:00:00:00:00:01:1"}, "uni_a": {"tag": {"value": '$vlan', "tag_type": 1}, "interface_id": "00:00:00:00:00:00:00:03:1"}}'

4. restart Kytos

Expected behavior: Kytos should smoothly activate the EVC again, i.e., all traces should be valid.

Actual behavior:

Sep 15 18:56:27 6a7f9ddec698 uvicorn.access:INFO httptools_impl:506:  127.0.0.1:41232 - "GET /api/kytos/flow_manager/v2/stored_flows/?state=installed HTTP/1.1" 200
Sep 15 18:56:27 6a7f9ddec698 uvicorn.access:INFO httptools_impl:506:  127.0.0.1:41228 - "PUT /api/amlight/sdntrace_cp/v1/traces HTTP/1.1" 200
Sep 15 18:56:27 6a7f9ddec698 kytos.napps.kytos/mef_eline:WARNING evc:1250:  Invalid trace from uni_a: [{'dpid': '00:00:00:00:00:00:00:03', 'port': 1, 'time': '2023-09-15 18:56:27.411135', 'type': 'starting', 'vlan': 101}, {'dpid': '00:00:00:00:00:00:00:02', 'port': 3, 'time': '2023-09-15 18:56:27.411195', 'type': 'intermediary', 'vlan': 1}, {'dpid': '00:00:00:00:00:00:00:01', 'port': 2, 'time': '2023-09-15 18:56:27.411224', 'type': 'last', 'vlan': 1, 'out': {'port': 1, 'vlan': 101}}]

PS: you may eventually need to repeat the step 4 a few times, depending on the case of mef_eline loading the EVCs before the link_up events (in order to see the issue, the EVCs have to be loaded after the link up events, leaving the activation of the EVC for the consistency routine)

Adding the following debug information helps understand the issue:

diff --git a/models/evc.py b/models/evc.py
index 335187d..6879890 100644
--- a/models/evc.py
+++ b/models/evc.py
@@ -1247,6 +1247,7 @@ class EVCDeploy(EVCBase):
                                         metadata_vlan,
                                         trace2
                                     ) is False:
+                log.warning(f"Invalid trace from uni_a: link.endpoint_a={link.endpoint_a} metadata_vlan={metadata_vlan} trace2={trace2}")
                 log.warning(f"Invalid trace from uni_a: {trace_a}")
                 return False
             if compare_endpoint_trace(

The log now becomes:

Sep 15 19:29:27 6a7f9ddec698 kytos.napps.kytos/mef_eline:WARNING evc:1250:  Invalid trace from uni_a: link.endpoint_a=Interface('s2-eth3', 3, Switch('00:00:00:00:00:00:00:02')) metadata_vlan=8 trace2={'dpid': '00:00:00:00:00:00:00:03', 'port': 2, 'time': '2023-09-15 19:29:27.553224', 'type': 'last', 'vlan': 8, 'out': {'port': 1, 'vlan': 101}}
Sep 15 19:29:27 6a7f9ddec698 kytos.napps.kytos/mef_eline:WARNING evc:1251:  Invalid trace from uni_a: [{'dpid': '00:00:00:00:00:00:00:03', 'port': 1, 'time': '2023-09-15 19:29:27.553015', 'type': 'starting', 'vlan': 101}, {'dpid': '00:00:00:00:00:00:00:02', 'port': 3, 'time': '2023-09-15 19:29:27.553104', 'type': 'intermediary', 'vlan': 8}, {'dpid': '00:00:00:00:00:00:00:01', 'port': 2, 'time': '2023-09-15 19:29:27.553150', 'type': 'last', 'vlan': 8, 'out': {'port': 1, 'vlan': 101}}]

Here is the EVC data:

# curl http://127.0.0.1:8181/api/kytos/mef_eline/v2/evc/
{"4a7e03f20ddb42":{"active":false,"archived":false,"backup_path":[],"bandwidth":0,"circuit_scheduler":[],"current_path":[{"id":"4d42dc0852278accac7d9df15418f6d921db160b13d674029a87cef1b5f67f30","endpoint_a":{"id":"00:00:00:00:00:00:00:02:3","name":"s2-eth3","port_number":3,"mac":"c6:64:21:17:33:ad","switch":"00:00:00:00:00:00:00:02","type":"interface","nni":true,"uni":false,"speed":1250000000.0,"metadata":{},"lldp":true,"active":false,"enabled":true,"status":"DOWN","status_reason":["deactivated"],"link":"4d42dc0852278accac7d9df15418f6d921db160b13d674029a87cef1b5f67f30"},"endpoint_b":{"id":"00:00:00:00:00:00:00:03:2","name":"s3-eth2","port_number":2,"mac":"62:6c:53:60:b8:bf","switch":"00:00:00:00:00:00:00:03","type":"interface","nni":true,"uni":false,"speed":1250000000.0,"metadata":{},"lldp":true,"active":false,"enabled":true,"status":"DOWN","status_reason":["deactivated"],"link":"4d42dc0852278accac7d9df15418f6d921db160b13d674029a87cef1b5f67f30"},"metadata":{"s_vlan":{"tag_type":1,"value":8}},"active":false,"enabled":false,"status":"DISABLED","status_reason":["deactivated","disabled"]},{"id":"cf0f4071be426b3f745027f5d22bc61f8312ae86293c9b28e7e66015607a9260","endpoint_a":{"id":"00:00:00:00:00:00:00:01:2","name":"s1-eth2","port_number":2,"mac":"b2:e1:26:b8:ea:42","switch":"00:00:00:00:00:00:00:01","type":"interface","nni":true,"uni":false,"speed":1250000000.0,"metadata":{},"lldp":true,"active":false,"enabled":true,"status":"DOWN","status_reason":["deactivated"],"link":"cf0f4071be426b3f745027f5d22bc61f8312ae86293c9b28e7e66015607a9260"},"endpoint_b":{"id":"00:00:00:00:00:00:00:02:2","name":"s2-eth2","port_number":2,"mac":"1a:e5:27:62:22:10","switch":"00:00:00:00:00:00:00:02","type":"interface","nni":true,"uni":false,"speed":1250000000.0,"metadata":{},"lldp":true,"active":false,"enabled":true,"status":"DOWN","status_reason":["deactivated"],"link":"cf0f4071be426b3f745027f5d22bc61f8312ae86293c9b28e7e66015607a9260"},"metadata":{"s_vlan":{"tag_type":1,"value":8}},"active":false,"enabled":false,"status":"DISABLED","status_reason":["deactivated","disabled"]}],"dynamic_backup_path":true,"enabled":true,"failover_path":[],"id":"4a7e03f20ddb42","metadata":{},"name":"evc-vlan-101","primary_path":[],"service_level":0,"uni_a":{"tag":{"tag_type":1,"value":101},"interface_id":"00:00:00:00:00:00:00:03:1"},"uni_z":{"tag":{"tag_type":1,"value":101},"interface_id":"00:00:00:00:00:00:00:01:1"},"sb_priority":null,"execution_rounds":0,"owner":null,"queue_id":-1,"primary_constraints":{},"secondary_constraints":{},"primary_links":[],"backup_links":[],"start_date":"2023-09-15T18:53:32","creation_time":"2023-09-15T18:53:32","request_time":"2023-09-15T18:53:32","end_date":null,"flow_removed_at":"2023-09-15T19:25:46","updated_at":"2023-09-15T19:28:27"}}

And the stored flows:

# curl "http://127.0.0.1:8181/api/kytos/flow_manager/v2/stored_flows/?state=installed"
{"00:00:00:00:00:00:00:01":[{"flow":{"owner":"coloring","cookie":12393906174523604993,"match":{"dl_src":"ee:ee:ee:ee:ee:02"},"actions":[{"action_type":"output","port":4294967293}],"table_id":0,"table_group":"base","priority":50000,"idle_timeout":0,"hard_timeout":0},"flow_id":"1def4287eab3ab24897296657de64520","id":"914c314cfe8591090073a14bec4e659f","inserted_at":"2023-09-15T18:52:42.025000","state":"installed","switch":"00:00:00:00:00:00:00:01","updated_at":"2023-09-15T19:28:36.326000"},{"flow":{"owner":"of_lldp","cookie":12321848580485677057,"match":{"dl_type":35020,"dl_vlan":3799},"actions":[{"action_type":"output","port":4294967293}],"table_id":0,"table_group":"base","priority":50000,"idle_timeout":0,"hard_timeout":0},"flow_id":"2ee616117c8ce044e9f8f1f4f8e266ad","id":"b33f354ca83bfc990537e1d8d0c964e4","inserted_at":"2023-09-15T18:52:41.558000","state":"installed","switch":"00:00:00:00:00:00:00:01","updated_at":"2023-09-15T19:28:36.327000"},{"flow":{"owner":"mef_eline","cookie":12270758690135333698,"match":{"in_port":1,"dl_vlan":101},"actions":[{"action_type":"set_vlan","vlan_id":101},{"action_type":"push_vlan","tag_type":"s"},{"action_type":"set_vlan","vlan_id":8},{"action_type":"output","port":2}],"table_id":0,"table_group":"evpl","priority":20000,"idle_timeout":0,"hard_timeout":0},"flow_id":"65393385aaa6df94c92927ab22d2fb2b","id":"c86b59bcd70ee091a04947e93e670377","inserted_at":"2023-09-15T18:53:32.908000","state":"installed","switch":"00:00:00:00:00:00:00:01","updated_at":"2023-09-15T19:25:46.893000"},{"flow":{"owner":"mef_eline","cookie":12270758690135333698,"match":{"in_port":2,"dl_vlan":8},"actions":[{"action_type":"pop_vlan"},{"action_type":"output","port":1}],"table_id":0,"table_group":"evpl","priority":20000,"idle_timeout":0,"hard_timeout":0},"flow_id":"ee5b52b68bd63dcefa9c0eb42f1beb29","id":"f08c70f8246563bf4a93855dae710eff","inserted_at":"2023-09-15T19:25:46.868000","state":"installed","switch":"00:00:00:00:00:00:00:01","updated_at":"2023-09-15T19:25:46.893000"}],"00:00:00:00:00:00:00:02":[{"flow":{"owner":"of_lldp","cookie":12321848580485677058,"match":{"dl_type":35020,"dl_vlan":3799},"actions":[{"action_type":"output","port":4294967293}],"table_id":0,"table_group":"base","priority":50000,"idle_timeout":0,"hard_timeout":0},"flow_id":"355c284b2260fe897f3fb912e23e5b5d","id":"666b779f61fb741c943be13013dbe210","inserted_at":"2023-09-15T18:52:41.569000","state":"installed","switch":"00:00:00:00:00:00:00:02","updated_at":"2023-09-15T19:28:36.334000"},{"flow":{"owner":"coloring","cookie":12393906174523604994,"match":{"dl_src":"ee:ee:ee:ee:ee:03"},"actions":[{"action_type":"output","port":4294967293}],"table_id":0,"table_group":"base","priority":50000,"idle_timeout":0,"hard_timeout":0},"flow_id":"c8a22029a15f4669f35ffe2d24f05539","id":"0c72c8ba69a06905ee3c83ac6082efd7","inserted_at":"2023-09-15T18:52:42.029000","state":"installed","switch":"00:00:00:00:00:00:00:02","updated_at":"2023-09-15T19:28:36.364000"},{"flow":{"owner":"coloring","cookie":12393906174523604994,"match":{"dl_src":"ee:ee:ee:ee:ee:01"},"actions":[{"action_type":"output","port":4294967293}],"table_id":0,"table_group":"base","priority":50000,"idle_timeout":0,"hard_timeout":0},"flow_id":"68f45f0c241bb50ecce17dae4250bf27","id":"d36602f48f45949ee3197e542cca3e7e","inserted_at":"2023-09-15T18:52:42.062000","state":"installed","switch":"00:00:00:00:00:00:00:02","updated_at":"2023-09-15T19:28:36.364000"},{"flow":{"owner":"mef_eline","cookie":12270758690135333698,"match":{"in_port":3,"dl_vlan":8},"actions":[{"action_type":"set_vlan","vlan_id":8},{"action_type":"output","port":2}],"table_id":0,"table_group":"evpl","priority":20000,"idle_timeout":0,"hard_timeout":0},"flow_id":"d0374e0491fd6436843c40893d2f76d1","id":"adf4ced8d08896aaeaabf2e1dc92804c","inserted_at":"2023-09-15T19:25:46.727000","state":"installed","switch":"00:00:00:00:00:00:00:02","updated_at":"2023-09-15T19:25:46.792000"},{"flow":{"owner":"mef_eline","cookie":12270758690135333698,"match":{"in_port":2,"dl_vlan":8},"actions":[{"action_type":"set_vlan","vlan_id":8},{"action_type":"output","port":3}],"table_id":0,"table_group":"evpl","priority":20000,"idle_timeout":0,"hard_timeout":0},"flow_id":"bd65f70d00bd3beeb93ab40a4c3aa086","id":"82e91897febf39a7b86c120800e90beb","inserted_at":"2023-09-15T19:25:46.727000","state":"installed","switch":"00:00:00:00:00:00:00:02","updated_at":"2023-09-15T19:25:46.792000"}],"00:00:00:00:00:00:00:03":[{"flow":{"owner":"of_lldp","cookie":12321848580485677059,"match":{"dl_type":35020,"dl_vlan":3799},"actions":[{"action_type":"output","port":4294967293}],"table_id":0,"table_group":"base","priority":50000,"idle_timeout":0,"hard_timeout":0},"flow_id":"d7954dbf011826f4bc0e2e3ab0c90f1c","id":"4d4697b07ceccc1e1d616e9690beaabd","inserted_at":"2023-09-15T18:52:41.563000","state":"installed","switch":"00:00:00:00:00:00:00:03","updated_at":"2023-09-15T19:28:36.335000"},{"flow":{"owner":"coloring","cookie":12393906174523604995,"match":{"dl_src":"ee:ee:ee:ee:ee:02"},"actions":[{"action_type":"output","port":4294967293}],"table_id":0,"table_group":"base","priority":50000,"idle_timeout":0,"hard_timeout":0},"flow_id":"3cadb140ad2138141f50dc5d3794c84b","id":"c69ee7566ada1922d511d184ad35e516","inserted_at":"2023-09-15T18:52:42.068000","state":"installed","switch":"00:00:00:00:00:00:00:03","updated_at":"2023-09-15T19:28:36.384000"},{"flow":{"owner":"mef_eline","cookie":12270758690135333698,"match":{"in_port":1,"dl_vlan":101},"actions":[{"action_type":"set_vlan","vlan_id":101},{"action_type":"push_vlan","tag_type":"s"},{"action_type":"set_vlan","vlan_id":8},{"action_type":"output","port":2}],"table_id":0,"table_group":"evpl","priority":20000,"idle_timeout":0,"hard_timeout":0},"flow_id":"c11957fac5c529215069c82d92e924a0","id":"a7a96bccbec6216fbbcf374bb74303be","inserted_at":"2023-09-15T18:53:32.858000","state":"installed","switch":"00:00:00:00:00:00:00:03","updated_at":"2023-09-15T19:25:46.856000"},{"flow":{"owner":"mef_eline","cookie":12270758690135333698,"match":{"in_port":2,"dl_vlan":8},"actions":[{"action_type":"pop_vlan"},{"action_type":"output","port":1}],"table_id":0,"table_group":"evpl","priority":20000,"idle_timeout":0,"hard_timeout":0},"flow_id":"143dacb69b8a1d124299d5dfa05e23d3","id":"52ab46472173feaefb612e8706bf49ce","inserted_at":"2023-09-15T19:25:46.827000","state":"installed","switch":"00:00:00:00:00:00:00:03","updated_at":"2023-09-15T19:25:46.856000"}]}

[viniarck]

@italovalcy thanks for catching and reporting this.

@gretelliz I've assigned this to you. I've initially set the priority as priority_medium and scheduled for 2023.2, @italovalcy feel free to update the priority accordingly if needed.

[viniarck]

@gretelliz when you're back, check out this issue that has been left behind. The workaround seems simpler, but sdntrace_cp should be reliable to also handle this case when comparing the trace result.

[italovalcy]

Hi team

The most updated version of Kytos does not run sdntrace on the startup anymore (sdntrace was helping to see if the flows were still there to re-activate the EVC -- now that EVCs are activated by default sdntrace wont run anymore)

Anyway, to reproduce the issue now the approach would be:

1. start Kytos with the console (kytosd -f) -- I usually do this by leveraging tmux.

Then, after following the guidelines presented on this issue, you can connect to Kytos console and run the following test:

kytos $> a = EVCDeploy.check_list_traces(controller.napps[('kytos', 'mef_eline')].circuits.values())
2023-11-13 19:51:58,562 - INFO [uvicorn.access] (MainThread) 127.0.0.1:57420 - "GET /api/kytos/flow_manager/v2/stored_flows/?state=installed HTTP/1.1" 200
2023-11-13 19:51:58,566 - INFO [uvicorn.access] (MainThread) 127.0.0.1:57406 - "PUT /api/amlight/sdntrace_cp/v1/traces HTTP/1.1" 200

kytos $> 2023-11-13 19:51:58,568 - WARNING [kytos.napps.kytos/mef_eline] (ThreadPoolExecutor-1_0) Invalid trace from uni_a: [{'dpid': '00:00:00:00:00:00:00:03', 'port': 1, 'time': '2023-11-13 19:51:58.565206', 'type': 'starting', 'vlan': 999}, {'dpid': '00:00:00:00:00:00:00:02', 'port': 3, 'time': '2023-11-13 19:51:58.565262', 'type': 'intermediary', 'vlan': 3}, {'dpid': '00:00:00:00:00:00:00:01', 'port': 2, 'time': '2023-11-13 19:51:58.565320', 'type': 'last', 'vlan': 3, 'out': {'port': 1, 'vlan': 999}}]
kytos $> a
Out[18]: {'23f4ff3f61ab42': True, '82ff02a96a4d44': False}