search

kytos-ng / mef_eline

Kytos NApp to create and manage point-to-point L2 circuits
https://kytos-ng.github.io/api/mef_eline.html
MIT License
0 stars 9 forks source link

pre-mature deployment of EVCs resulted in a redeploy, and overlapping flows that triggered consistency check #376

Closed viniarck closed 1 year ago

viniarck commented 1 year ago

I'm using this topology (ring INT, with an EVPL between s1-eth1 and s3-eth1):

from mininet.topo import Topo

class MyTopo(Topo):
    "Simple topology example."

    def build(self):
        "Create custom topo."

        # Add hosts and switches
        h11 = self.addHost("h11")
        h12 = self.addHost("h12")
        h2 = self.addHost("h2")
        h3 = self.addHost("h3")

        s1 = self.addSwitch("s1")
        s2 = self.addSwitch("s2")
        s3 = self.addSwitch("s3")

        self.addLink(s1, h11)
        self.addLink(s1, h12)
        self.addLink(s2, h2)
        self.addLink(s3, h3)

        self.addLink(s1, s2)
        self.addLink(s2, s3)
        self.addLink(s1, s3)

        self.addLink(s1, s1, port1=5, port2=6)
        self.addLink(s1, s1, port1=7, port2=8)
        self.addLink(s3, s3, port1=5, port2=6)

topos = {"mytopo": (lambda: MyTopo())}
2023-09-27 15:35:09,621 - WARNING [kytos.napps.kytos/of_lldp] (thread_pool_app_8) LLDP loop detected on switch: 00:00:00:00:00:00:00:01, interfaces: ['s1-eth7', 's1-eth8'], port_numbers:
 [7, 8]
2023-09-27 15:35:09,629 - WARNING [kytos.napps.kytos/of_lldp] (thread_pool_app_0) LLDP loop detected on switch: 00:00:00:00:00:00:00:01, interfaces: ['s1-eth5', 's1-eth6'], port_numbers:
 [5, 6]
2023-09-27 15:35:09,640 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39078 - "POST /api/kytos/topology/v3/interfaces/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01%3A7/metadata HTTP/1.1" 201
2023-09-27 15:35:09,641 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39084 - "POST /api/kytos/topology/v3/interfaces/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01%3A5/metadata HTTP/1.1" 201
2023-09-27 15:35:10,862 - INFO [kytos.napps.kytos/mef_eline] (thread_pool_app_2) Event handle_link_up Link(Interface('s1-eth5', 5, Switch('00:00:00:00:00:00:00:01')), Interface('s1-eth6'
, 6, Switch('00:00:00:00:00:00:00:01')), 3bdc34e8e0ca38d7c24724d07c8282cc2c5f123cfed602f5b2eb3594c9606476)
2023-09-27 15:35:10,867 - INFO [kytos.napps.kytos/mef_eline] (thread_pool_app_0) Event handle_link_up Link(Interface('s1-eth8', 8, Switch('00:00:00:00:00:00:00:01')), Interface('s1-eth7'
, 7, Switch('00:00:00:00:00:00:00:01')), 20070c87457fc5197d74eb6354365560dd7b2b19ac414ad48c8dc2597236a6c4)
2023-09-27 15:35:10,873 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39088 - "GET /api/kytos/topology/v3/links HTTP/1.1" 200
2023-09-27 15:35:10,881 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:03, command: delete, force: True,  flows[0, 1]:
 [{'cookie': 12285342164225298764, 'cookie_mask': 18446744073709551615}]
2023-09-27 15:35:10,899 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39094 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A03 HTTP/1.1" 202
2023-09-27 15:35:10,904 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: delete, force: True,  flows[0, 1]:
 [{'cookie': 12285342164225298764, 'cookie_mask': 18446744073709551615}]
2023-09-27 15:35:10,919 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39108 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01 HTTP/1.1" 202
2023-09-27 15:35:10,951 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39114 - "POST /api/kytos/pathfinder/v3/ HTTP/1.1" 200
2023-09-27 15:35:10,952 - WARNING [kytos.napps.kytos/mef_eline] (thread_pool_app_2) EVC(7e4d9b9ac7114c, evpl) was not deployed. No available path was found.
2023-09-27 15:35:10,954 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:03, command: delete, force: True,  flows[0, 1]:
 [{'cookie': 12285342164225298764, 'cookie_mask': 18446744073709551615}]
2023-09-27 15:35:10,956 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39124 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A03 HTTP/1.1" 202
2023-09-27 15:35:10,959 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: delete, force: True,  flows[0, 1]:
 [{'cookie': 12285342164225298764, 'cookie_mask': 18446744073709551615}]
2023-09-27 15:35:10,961 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39128 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01 HTTP/1.1" 202
2023-09-27 15:35:10,969 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39140 - "POST /api/kytos/pathfinder/v3/ HTTP/1.1" 200
2023-09-27 15:35:10,969 - WARNING [kytos.napps.kytos/mef_eline] (thread_pool_app_0) EVC(7e4d9b9ac7114c, evpl) was not deployed. No available path was found.
2023-09-27 15:35:11,417 - INFO [kytos.core.atcp_server] (MainThread) New connection from 127.0.0.1:58736
2023-09-27 15:35:11,418 - INFO [kytos.core.atcp_server] (MainThread) New connection from 127.0.0.1:58750
2023-09-27 15:35:08,309 - INFO [kytos.core.atcp_server] (MainThread) New connection from 127.0.0.1:60534
2023-09-27 15:35:08,814 - INFO [kytos.napps.kytos/of_core] (thread_pool_sb_0) Connection ('127.0.0.1', 60534), Switch 00:00:00:00:00:00:00:01: OPENFLOW HANDSHAKE COMPLETE
2023-09-27 15:35:08,865 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: add, force: True,  flows[0, 2]: [{
'match': {'dl_src': 'ee:ee:ee:ee:ee:03'}, 'priority': 50000, 'actions': [{'action_type': 'output', 'port': 4294967293}], 'cookie': 12393906174523604993, 'table_id': 0, 'owner': 'coloring
', 'table_group': 'base'}, {'match': {'dl_src': 'ee:ee:ee:ee:ee:02'}, 'priority': 50000, 'actions': [{'action_type': 'output', 'port': 4294967293}], 'cookie': 12393906174523604993, 'tabl
e_id': 0, 'owner': 'coloring', 'table_group': 'base'}]
2023-09-27 15:35:08,867 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: add, force: False,  flows[0, 1]: [
{'actions': [{'action_type': 'output', 'port': 4294967293}], 'table_id': 0, 'owner': 'of_lldp', 'table_group': 'base', 'priority': 50000, 'cookie': 12321848580485677057, 'match': {'dl_ty
pe': 35020, 'dl_vlan': 3799}}]
2023-09-27 15:35:08,873 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39058 - "POST /api/kytos/flow_manager/v2/flows/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01 HTTP/1.1" 202
2023-09-27 15:35:08,878 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39068 - "POST /api/kytos/flow_manager/v2/flows/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01 HTTP/1.1" 202
2023-09-27 15:35:09,621 - WARNING [kytos.napps.kytos/of_lldp] (thread_pool_app_8) LLDP loop detected on switch: 00:00:00:00:00:00:00:01, interfaces: ['s1-eth7', 's1-eth8'], port_numbers:
 [7, 8]
2023-09-27 15:35:09,629 - WARNING [kytos.napps.kytos/of_lldp] (thread_pool_app_0) LLDP loop detected on switch: 00:00:00:00:00:00:00:01, interfaces: ['s1-eth5', 's1-eth6'], port_numbers:
 [5, 6]
2023-09-27 15:35:09,640 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39078 - "POST /api/kytos/topology/v3/interfaces/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01%3A7/metadata HTTP/1.1" 201
2023-09-27 15:35:09,641 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39084 - "POST /api/kytos/topology/v3/interfaces/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01%3A5/metadata HTTP/1.1" 201
2023-09-27 15:35:10,862 - INFO [kytos.napps.kytos/mef_eline] (thread_pool_app_2) Event handle_link_up Link(Interface('s1-eth5', 5, Switch('00:00:00:00:00:00:00:01')), Interface('s1-eth6'
, 6, Switch('00:00:00:00:00:00:00:01')), 3bdc34e8e0ca38d7c24724d07c8282cc2c5f123cfed602f5b2eb3594c9606476)
2023-09-27 15:35:10,867 - INFO [kytos.napps.kytos/mef_eline] (thread_pool_app_0) Event handle_link_up Link(Interface('s1-eth8', 8, Switch('00:00:00:00:00:00:00:01')), Interface('s1-eth7'
, 7, Switch('00:00:00:00:00:00:00:01')), 20070c87457fc5197d74eb6354365560dd7b2b19ac414ad48c8dc2597236a6c4)
2023-09-27 15:35:10,873 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39088 - "GET /api/kytos/topology/v3/links HTTP/1.1" 200
2023-09-27 15:35:10,881 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:03, command: delete, force: True,  flows[0, 1]:
 [{'cookie': 12285342164225298764, 'cookie_mask': 18446744073709551615}]
2023-09-27 15:35:10,899 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39094 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A03 HTTP/1.1" 202
2023-09-27 15:35:10,904 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: delete, force: True,  flows[0, 1]:
 [{'cookie': 12285342164225298764, 'cookie_mask': 18446744073709551615}]
2023-09-27 15:35:10,919 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39108 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01 HTTP/1.1" 202
2023-09-27 15:35:10,951 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39114 - "POST /api/kytos/pathfinder/v3/ HTTP/1.1" 200
2023-09-27 15:35:10,952 - WARNING [kytos.napps.kytos/mef_eline] (thread_pool_app_2) EVC(7e4d9b9ac7114c, evpl) was not deployed. No available path was found.
2023-09-27 15:35:10,954 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:03, command: delete, force: True,  flows[0, 1]:
 [{'cookie': 12285342164225298764, 'cookie_mask': 18446744073709551615}]
2023-09-27 15:35:10,956 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39124 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A03 HTTP/1.1" 202
2023-09-27 15:35:10,959 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: delete, force: True,  flows[0, 1]:
 [{'cookie': 12285342164225298764, 'cookie_mask': 18446744073709551615}]
2023-09-27 15:35:10,961 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39128 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01 HTTP/1.1" 202
2023-09-27 15:35:10,969 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39140 - "POST /api/kytos/pathfinder/v3/ HTTP/1.1" 200
2023-09-27 15:35:10,969 - WARNING [kytos.napps.kytos/mef_eline] (thread_pool_app_0) EVC(7e4d9b9ac7114c, evpl) was not deployed. No available path was found.
2023-09-27 15:35:11,417 - INFO [kytos.core.atcp_server] (MainThread) New connection from 127.0.0.1:58736
2023-09-27 15:35:11,418 - INFO [kytos.core.atcp_server] (MainThread) New connection from 127.0.0.1:58750
2023-09-27 15:35:11,475 - INFO [kytos.napps.kytos/of_core] (thread_pool_sb_2) Connection ('127.0.0.1', 58736), Switch 00:00:00:00:00:00:00:03: OPENFLOW HANDSHAKE COMPLETE
2023-09-27 15:35:11,479 - INFO [kytos.napps.kytos/of_core] (thread_pool_sb_4) Connection ('127.0.0.1', 58750), Switch 00:00:00:00:00:00:00:02: OPENFLOW HANDSHAKE COMPLETE
2023-09-27 15:35:11,530 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:03, command: add, force: False,  flows[0, 1]: [
{'actions': [{'action_type': 'output', 'port': 4294967293}], 'table_id': 0, 'owner': 'of_lldp', 'table_group': 'base', 'priority': 50000, 'cookie': 12321848580485677059, 'match': {'dl_ty
pe': 35020, 'dl_vlan': 3799}}]
2023-09-27 15:35:11,533 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:02, command: add, force: False,  flows[0, 1]: [
{'actions': [{'action_type': 'output', 'port': 4294967293}], 'table_id': 0, 'owner': 'of_lldp', 'table_group': 'base', 'priority': 50000, 'cookie': 12321848580485677058, 'match': {'dl_ty
pe': 35020, 'dl_vlan': 3799}}]
2023-09-27 15:35:11,535 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:02, command: add, force: True,  flows[0, 2]: [{
'match': {'dl_src': 'ee:ee:ee:ee:ee:01'}, 'priority': 50000, 'actions': [{'action_type': 'output', 'port': 4294967293}], 'cookie': 12393906174523604994, 'table_id': 0, 'owner': 'coloring
', 'table_group': 'base'}, {'match': {'dl_src': 'ee:ee:ee:ee:ee:03'}, 'priority': 50000, 'actions': [{'action_type': 'output', 'port': 4294967293}], 'cookie': 12393906174523604994, 'tabl
e_id': 0, 'owner': 'coloring', 'table_group': 'base'}]
2023-09-27 15:35:11,547 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39172 - "POST /api/kytos/flow_manager/v2/flows/00%3A00%3A00%3A00%3A00%3A00%3A00%3A02 HTTP/1.1" 202
2023-09-27 15:35:11,548 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39144 - "POST /api/kytos/flow_manager/v2/flows/00%3A00%3A00%3A00%3A00%3A00%3A00%3A03 HTTP/1.1" 202
2023-09-27 15:35:11,548 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39156 - "POST /api/kytos/flow_manager/v2/flows/00%3A00%3A00%3A00%3A00%3A00%3A00%3A02 HTTP/1.1" 202
2023-09-27 15:35:11,555 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:03, command: add, force: True,  flows[0, 2]: [{
'match': {'dl_src': 'ee:ee:ee:ee:ee:01'}, 'priority': 50000, 'actions': [{'action_type': 'output', 'port': 4294967293}], 'cookie': 12393906174523604995, 'table_id': 0, 'owner': 'coloring
', 'table_group': 'base'}, {'match': {'dl_src': 'ee:ee:ee:ee:ee:02'}, 'priority': 50000, 'actions': [{'action_type': 'output', 'port': 4294967293}], 'cookie': 12393906174523604995, 'tabl
e_id': 0, 'owner': 'coloring', 'table_group': 'base'}]
2023-09-27 15:35:11,562 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39176 - "POST /api/kytos/flow_manager/v2/flows/00%3A00%3A00%3A00%3A00%3A00%3A00%3A03 HTTP/1.1" 202
2023-09-27 15:35:12,651 - WARNING [kytos.napps.kytos/of_lldp] (thread_pool_app_11) LLDP loop detected on switch: 00:00:00:00:00:00:00:03, interfaces: ['s3-eth5', 's3-eth6'], port_numbers
: [5, 6]
2023-09-27 15:35:12,663 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39192 - "POST /api/kytos/topology/v3/interfaces/00%3A00%3A00%3A00%3A00%3A00%3A00%3A03%3A5/metadata HTTP/1.1" 201
2023-09-27 15:35:13,522 - INFO [kytos.napps.kytos/mef_eline] (thread_pool_app_5) Event handle_link_up Link(Interface('s3-eth6', 6, Switch('00:00:00:00:00:00:00:03')), Interface('s3-eth5'
, 5, Switch('00:00:00:00:00:00:00:03')), c0fe8cb39c5d91a28891d8c81403391fda144e77ac812c22043ce3bb373f6cd2)
2023-09-27 15:35:13,524 - INFO [kytos.napps.kytos/mef_eline] (thread_pool_app_10) Event handle_link_up Link(Interface('s3-eth3', 3, Switch('00:00:00:00:00:00:00:03')), Interface('s1-eth4
', 4, Switch('00:00:00:00:00:00:00:01')), c8b55359990f89a5849813dc348d30e9e1f991bad1dcb7f82112bd35429d9b07)
2023-09-27 15:35:13,526 - INFO [kytos.napps.kytos/flow_manager] (thread_pool_sb_2) Consistency check: alien flow on switch 00:00:00:00:00:00:00:03
2023-09-27 15:35:13,528 - INFO [kytos.napps.kytos/flow_manager] (thread_pool_sb_2) Flow forwarded to switch 00:00:00:00:00:00:00:03 to be deleted. Flow: {'flows': [{'switch': '00:00:00:0
0:00:00:00:03', 'table_id': 0, 'match': {'in_port': 1, 'dl_vlan': 102}, 'priority': 20000, 'idle_timeout': 0, 'hard_timeout': 0, 'cookie': 12285342164225298764, 'id': '06ea2378d6c6019665
b935968d5b9464', 'stats': {'byte_count': 0, 'duration_sec': 101, 'duration_nsec': 3000000, 'packet_count': 0}, 'cookie_mask': 0, 'instructions': [{'instruction_type': 'apply_actions', 'a
ctions': [{'vlan_id': 101, 'action_type': 'set_vlan'}, {'action_type': 'push_vlan', 'tag_type': 's'}, {'vlan_id': 1, 'action_type': 'set_vlan'}, {'port': 3, 'action_type': 'output'}]}]}]
}
2023-09-27 15:35:13,529 - INFO [kytos.napps.kytos/flow_manager] (thread_pool_sb_2) Consistency check: alien flow on switch 00:00:00:00:00:00:00:03
2023-09-27 15:35:13,530 - INFO [kytos.napps.kytos/flow_manager] (thread_pool_sb_2) Flow forwarded to switch 00:00:00:00:00:00:00:03 to be deleted. Flow: {'flows': [{'switch': '00:00:00:0
0:00:00:00:03', 'table_id': 0, 'match': {'in_port': 3, 'dl_vlan': 1}, 'priority': 20000, 'idle_timeout': 0, 'hard_timeout': 0, 'cookie': 12285342164225298764, 'id': '5b187691da7a746536d8
d4787ced65d3', 'stats': {'byte_count': 0, 'duration_sec': 101, 'duration_nsec': 2000000, 'packet_count': 0}, 'cookie_mask': 0, 'instructions': [{'instruction_type': 'apply_actions', 'act
ions': [{'action_type': 'pop_vlan'}, {'port': 1, 'action_type': 'output'}]}]}]}
2023-09-27 15:35:13,530 - INFO [kytos.napps.kytos/flow_manager] (thread_pool_sb_2) Consistency check: alien flow on switch 00:00:00:00:00:00:00:03
2023-09-27 15:35:13,531 - INFO [kytos.napps.kytos/flow_manager] (thread_pool_sb_2) Flow forwarded to switch 00:00:00:00:00:00:00:03 to be deleted. Flow: {'flows': [{'switch': '00:00:00:0
0:00:00:00:03', 'table_id': 0, 'match': {'in_port': 2, 'dl_vlan': 1}, 'priority': 20000, 'idle_timeout': 0, 'hard_timeout': 0, 'cookie': 12285342164225298764, 'id': '1f21bd3be6168ca4f06a
930ca42f546e', 'stats': {'byte_count': 0, 'duration_sec': 100, 'duration_nsec': 880000000, 'packet_count': 0}, 'cookie_mask': 0, 'instructions': [{'instruction_type': 'apply_actions', 'a
ctions': [{'action_type': 'pop_vlan'}, {'port': 1, 'action_type': 'output'}]}]}]}
2023-09-27 15:35:13,537 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:03, command: delete, force: True,  flows[0, 1]:
 [{'cookie': 12285342164225298764, 'cookie_mask': 18446744073709551615}]
2023-09-27 15:35:13,541 - INFO [kytos.napps.kytos/mef_eline] (thread_pool_app_12) Event handle_link_up Link(Interface('s2-eth2', 2, Switch('00:00:00:00:00:00:00:02')), Interface('s1-eth3
', 3, Switch('00:00:00:00:00:00:00:01')), 78282c4d5b579265f04ebadc4405ca1b49628eb1d684bb45e5d0607fa8b713d0)
2023-09-27 15:35:13,542 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39202 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A03 HTTP/1.1" 202
2023-09-27 15:35:13,546 - INFO [kytos.napps.kytos/mef_eline] (thread_pool_app_7) Event handle_link_up Link(Interface('s2-eth3', 3, Switch('00:00:00:00:00:00:00:02')), Interface('s3-eth2'
, 2, Switch('00:00:00:00:00:00:00:03')), 4d42dc0852278accac7d9df15418f6d921db160b13d674029a87cef1b5f67f30)
2023-09-27 15:35:13,548 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: delete, force: True,  flows[0, 1]:
 [{'cookie': 12285342164225298764, 'cookie_mask': 18446744073709551615}]
2023-09-27 15:35:13,549 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39214 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01 HTTP/1.1" 202
2023-09-27 15:35:13,563 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39228 - "POST /api/kytos/pathfinder/v3/ HTTP/1.1" 200
2023-09-27 15:35:13,584 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: add, force: False,  flows[0, 2]: [
{'match': {'in_port': 1, 'dl_vlan': 101}, 'cookie': 12285342164225298764, 'actions': [{'action_type': 'set_vlan', 'vlan_id': 102}, {'action_type': 'push_vlan', 'tag_type': 's'}, {'action
_type': 'set_vlan', 'vlan_id': 2}, {'action_type': 'output', 'port': 4}], 'owner': 'mef_eline', 'table_group': 'evpl', 'table_id': 0, 'priority': 20000}, {'match': {'in_port': 4, 'dl_vla
n': 2}, 'cookie': 12285342164225298764, 'actions': [{'action_type': 'pop_vlan'}, {'action_type': 'output', 'port': 1}], 'owner': 'mef_eline', 'table_group': 'evpl', 'table_id': 0, 'prior
ity': 20000}]
2023-09-27 15:35:13,592 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39238 - "POST /api/kytos/flow_manager/v2/flows/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01 HTTP/1.1" 202
2023-09-27 15:35:13,599 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:03, command: add, force: False,  flows[0, 2]: [
{'match': {'in_port': 1, 'dl_vlan': 102}, 'cookie': 12285342164225298764, 'actions': [{'action_type': 'set_vlan', 'vlan_id': 101}, {'action_type': 'push_vlan', 'tag_type': 's'}, {'action
_type': 'set_vlan', 'vlan_id': 2}, {'action_type': 'output', 'port': 3}], 'owner': 'mef_eline', 'table_group': 'evpl', 'table_id': 0, 'priority': 20000}, {'match': {'in_port': 3, 'dl_vla
n': 2}, 'cookie': 12285342164225298764, 'actions': [{'action_type': 'pop_vlan'}, {'action_type': 'output', 'port': 1}], 'owner': 'mef_eline', 'table_group': 'evpl', 'table_id': 0, 'prior
ity': 20000}]
2023-09-27 15:35:13,607 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39250 - "POST /api/kytos/flow_manager/v2/flows/00%3A00%3A00%3A00%3A00%3A00%3A00%3A03 HTTP/1.1" 202
2023-09-27 15:35:13,613 - INFO [kytos.napps.kytos/mef_eline] (thread_pool_app_5) EVC(7e4d9b9ac7114c, evpl) was deployed.
2023-09-27 15:35:13,619 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39256 - "GET /api/kytos/topology/v3/links HTTP/1.1" 200
2023-09-27 15:35:13,622 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39258 - "GET /api/kytos/topology/v3/links HTTP/1.1" 200
2023-09-27 15:35:13,624 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39266 - "GET /api/kytos/topology/v3/links HTTP/1.1" 200
2023-09-27 15:35:13,627 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:02, command: delete, force: True,  flows[0, 2]:
 [{'cookie': 12285342164225298764, 'match': {'in_port': 2, 'dl_vlan': 1}, 'cookie_mask': 18446744073709551615}, {'cookie': 12285342164225298764, 'match': {'in_port': 3, 'dl_vlan': 1}, 'c
ookie_mask': 18446744073709551615}]
2023-09-27 15:35:13,634 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39268 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A02 HTTP/1.1" 202
2023-09-27 15:35:13,641 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: delete, force: True,  flows[0, 1]:
 [{'cookie': 12285342164225298764, 'match': {'in_port': 3, 'dl_vlan': 1}, 'cookie_mask': 18446744073709551615}]
2023-09-27 15:35:13,643 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39280 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01 HTTP/1.1" 202
2023-09-27 15:35:13,647 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:03, command: delete, force: True,  flows[0, 1]:
 [{'cookie': 12285342164225298764, 'match': {'in_port': 2, 'dl_vlan': 1}, 'cookie_mask': 18446744073709551615}]
2023-09-27 15:35:13,649 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39284 - "POST /api/kytos/flow_manager/v2/delete/00%3A00%3A00%3A00%3A00%3A00%3A00%3A03 HTTP/1.1" 202
2023-09-27 15:35:13,674 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39298 - "POST /api/kytos/pathfinder/v3/ HTTP/1.1" 200
2023-09-27 15:35:13,697 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:02, command: add, force: False,  flows[0, 2]: [
{'match': {'in_port': 2, 'dl_vlan': 2}, 'cookie': 12285342164225298764, 'actions': [{'action_type': 'set_vlan', 'vlan_id': 2}, {'action_type': 'output', 'port': 3}], 'owner': 'mef_eline'
, 'table_group': 'evpl', 'table_id': 0, 'priority': 20000}, {'match': {'in_port': 3, 'dl_vlan': 2}, 'cookie': 12285342164225298764, 'actions': [{'action_type': 'set_vlan', 'vlan_id': 2},
 {'action_type': 'output', 'port': 2}], 'owner': 'mef_eline', 'table_group': 'evpl', 'table_id': 0, 'priority': 20000}]
2023-09-27 15:35:13,724 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39310 - "POST /api/kytos/flow_manager/v2/flows/00%3A00%3A00%3A00%3A00%3A00%3A00%3A02 HTTP/1.1" 202
2023-09-27 15:35:13,744 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:01, command: add, force: False,  flows[0, 1]: [
{'match': {'in_port': 3, 'dl_vlan': 2}, 'cookie': 12285342164225298764, 'actions': [{'action_type': 'pop_vlan'}, {'action_type': 'output', 'port': 1}], 'owner': 'mef_eline', 'table_group
': 'evpl', 'table_id': 0, 'priority': 20000}]
2023-09-27 15:35:13,748 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39316 - "POST /api/kytos/flow_manager/v2/flows/00%3A00%3A00%3A00%3A00%3A00%3A00%3A01 HTTP/1.1" 202
2023-09-27 15:35:13,754 - INFO [kytos.napps.kytos/flow_manager] (AnyIO worker thread) Send FlowMod from request dpid: 00:00:00:00:00:00:00:03, command: add, force: False,  flows[0, 1]: [
{'match': {'in_port': 2, 'dl_vlan': 2}, 'cookie': 12285342164225298764, 'actions': [{'action_type': 'pop_vlan'}, {'action_type': 'output', 'port': 1}], 'owner': 'mef_eline', 'table_group
': 'evpl', 'table_id': 0, 'priority': 20000}]
2023-09-27 15:35:13,758 - INFO [uvicorn.access] (MainThread) 127.0.0.1:39328 - "POST /api/kytos/flow_manager/v2/flows/00%3A00%3A00%3A00%3A00%3A00%3A00%3A03 HTTP/1.1" 202
2023-09-27 15:35:13,763 - INFO [kytos.napps.kytos/mef_eline] (thread_pool_app_11) Failover path for EVC(7e4d9b9ac7114c, evpl) was deployed.
kytos $>                                                                                                                                                                                  

kytos $> 2023-09-27 15:36:07,547 - INFO [uvicorn.access] (MainThread) 127.0.0.1:52848 - "GET /api/kytos/flow_manager/v2/stored_flows/?state=installed HTTP/1.1" 200                       
2023-09-27 15:36:07,550 - INFO [uvicorn.access] (MainThread) 127.0.0.1:52844 - "PUT /api/amlight/sdntrace_cp/v1/traces HTTP/1.1" 200
2023-09-27 15:36:07,552 - INFO [kytos.napps.kytos/mef_eline] (mef_eline) EVC(4aaf37eff66d4d, evpl) enabled but inactive - activating

It might be related to https://github.com/kytos-ng/mef_eline/issues/218, but since the scenario wasn't resulting in a traceback and it became easier to reproduce I went ahead and reported this one too.

How to reproduce:

mn --controller=remote,ip=127.0.0.1,port=6653 --switch=ovsk,protocols=OpenFlow13 --custom custom_topos/ring_int.py --topo mytopo

{
    "name": "evpl",
    "service_level": 6,
    "dynamic_backup_path": true,
    "uni_a": {
        "interface_id": "00:00:00:00:00:00:00:01:1",
        "tag": {
            "tag_type": 1,
            "value": 101
        }
    },
    "uni_z": {
        "interface_id": "00:00:00:00:00:00:00:03:1",
        "tag": {
            "tag_type": 1,
            "value": 102
        }
    },
    "primary_constraints": {
        "mandatory_metrics": {
            "ownership": "blue"
        }
    },
    "secondary_constraints": {
        "mandatory_metrics": {
            "ownership": "blue"
        }
    }
}
{
  "name": "intra_evpl",
  "service_level": 6,
  "dynamic_backup_path": true,
  "uni_a": {
    "interface_id": "00:00:00:00:00:00:00:01:1",
    "tag": {
      "tag_type": 1,
      "value": 200
    }
  },
  "uni_z": {
    "interface_id": "00:00:00:00:00:00:00:01:2",
    "tag": {
      "tag_type": 1,
      "value": 200
    }
  }
}

We'll need to reassess when it's safe to start handling a link up, and whether or not if consistency check itself will be responsible for the final activation and or reploy.

viniarck commented 1 year ago

Initially assigning it to @Alopalao to assess and work on it, since I've hit this issue when reviewing https://github.com/kytos-ng/mef_eline/pull/371#pullrequestreview-1646864908, but cc'ing also @Ktmi and @italovalcy for you guys to collaborate on it since it has some overlap with handling link up and consistency check responsibilities that are being assessed/refined in other issues https://github.com/kytos-ng/mef_eline/issues/218#issuecomment-1718153743. Thanks, guys.

viniarck commented 1 year ago

I'll go ahead and close this, since it's been discussed that mef_eline should keep reacting to link_up|link_down, due to https://github.com/kytos-ng/mef_eline/pull/383 now it's keeping track of the activation state so this problem has been minimized. If this discussion comes back a new requirement will be mapped accordingly.