On 8/12/24 18:33, Ilya Maximets wrote:
> On 8/12/24 18:24, Vladislav Odintsov wrote:
>> Hi,
>>
>> I've faced with a behavior of OVS/OVN (I couldn't understand which part
>> to blame) loosing openflow connection if I change mac address of an
>> added to br-int logical port, which is claimed as a normal VIF port by
>> ovn-controller. There is a simple reproducer script:
>>
>> ovn-nbctl ls-add test
>> ovn-nbctl lsp-add test test1
>> ip li add test1 type dummy
>> ovs-vsctl add-port br-int test1
>> ip li set test1 add 00:00:00:00:00:01
>>
>> When the last line is executed in ovn-controller.log I see openflow is
>> re-connected:
>>
>> 2024-08-12T15:42:02.493Z|03705|rconn(ovn_pinctrl0)|INFO|unix:/run/openvswitch/br-int.mgmt:
>>
>> connection closed by peer
>> 2024-08-12T15:42:02.494Z|00222|rconn|INFO|unix:/run/openvswitch/br-int.mgmt:
>> connection closed by peer
>> 2024-08-12T15:42:02.494Z|00223|rconn|INFO|unix:/run/openvswitch/br-int.mgmt:
>> connection closed by peer
>> 2024-08-12T15:42:03.495Z|00224|rconn|INFO|unix:/run/openvswitch/br-int.mgmt:
>> connecting...
>> 2024-08-12T15:42:03.495Z|00225|rconn|INFO|unix:/run/openvswitch/br-int.mgmt:
>> connecting...
>> 2024-08-12T15:42:03.495Z|03706|rconn(ovn_pinctrl0)|INFO|unix:/run/openvswitch/br-int.mgmt:
>>
>> connecting...
>> 2024-08-12T15:42:03.495Z|00226|rconn|INFO|unix:/run/openvswitch/br-int.mgmt:
>> connected
>>
>> In ovs-vswitchd with enabled DBG logs there is:
>>
>> 2024-08-12T16:01:08.694Z|3796712|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 18 (NETLINK_ROUTE<->NETLINK_ROUTE) at lib/netlink-socket.c:1409 (0%
>> CPU usage)
>> 2024-08-12T16:01:08.695Z|3796713|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 16 (NETLINK_ROUTE<->NETLINK_ROUTE) at lib/netlink-socket.c:1409 (0%
>> CPU usage)
>> 2024-08-12T16:01:08.695Z|3796714|netlink_socket|DBG|Dropped 505 log
>> messages in last 1 seconds (most recently, 0 seconds ago) due to
>> excessive rate
>> 2024-08-12T16:01:08.695Z|3796715|netlink_socket|DBG|nl_sock_recv__
>> (Success): nl(len:1360, type=16(family-defined), flags=0, seq=0, pid=0
>> 2024-08-12T16:01:08.695Z|3796716|dpif|DBG|Dropped 15 log messages in
>> last 0 seconds (most recently, 0 seconds ago) due to excessive rate
>> 2024-08-12T16:01:08.695Z|3796717|dpif|DBG|system@ovs-system: device
>> internet is on port 1
>> 2024-08-12T16:01:08.695Z|3796718|dpif|DBG|system@ovs-system: device
>> br-ext is on port 2
>> 2024-08-12T16:01:08.695Z|3796719|jsonrpc|DBG|unix:/var/run/openvswitch/db.sock:
>>
>> send request, method="transact",
>> params=["Open_vSwitch",{"where":[["_uuid","==",["uuid","acae6b73-de5f-46e4-a3d9-7874efd43cb4"]]],"row":{"mac_in_use":"00:00:00:00:00:02"},"op":"update","table":"Interface"},{"lock":"ovs_vswitchd","op":"assert"}],
>>
>> id=4284801
>> 2024-08-12T16:01:08.699Z|3796720|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 37 (FIFO pipe:[103980657]) at vswitchd/bridge.c:421 (0% CPU usage)
>> 2024-08-12T16:01:08.699Z|3796721|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 17 (<->/var/run/openvswitch/db.sock) at lib/stream-fd.c:157 (0% CPU
>> usage)
>> 2024-08-12T16:01:08.699Z|00690|poll_loop(urcu5)|DBG|wakeup due to
>> [POLLIN] on fd 56 (FIFO pipe:[103975681]) at lib/ovs-rcu.c:363
>> 2024-08-12T16:01:08.699Z|3796722|jsonrpc|DBG|unix:/var/run/openvswitch/db.sock:
>>
>> received notification, method="update3",
>> params=[["monid","Open_vSwitch"],"00000000-0000-0000-0000-000000000000",{"Interface":{"acae6b73-de5f-46e4-a3d9-7874efd43cb4":{"modify":{"mac_in_use":"00:00:00:00:00:02"}}}}]
>> 2024-08-12T16:01:08.699Z|3796723|jsonrpc|DBG|unix:/var/run/openvswitch/db.sock:
>>
>> received reply, result=[{"count":1},{}], id=4284801
>> 2024-08-12T16:01:08.699Z|3796724|vconn|DBG|unix#121: sent (Success):
>> OFPT_PORT_STATUS (OF1.5) (xid=0x0): MOD: 15(test1): addr:00:00:00:00:00:02
>> config: PORT_DOWN
>> state: LINK_DOWN
>> speed: 0 Mbps now, 0 Mbps max
>> 2024-08-12T16:01:08.699Z|3796725|bridge|INFO|bridge br-int: using
>> datapath ID 0000000000000002
>> 2024-08-12T16:01:08.699Z|3796726|rconn|INFO|br-int<->unix#121: disconnecting
>> 2024-08-12T16:01:08.699Z|3796727|rconn|DBG|br-int<->unix#121: entering
>> DISCONNECTED
>> 2024-08-12T16:01:08.699Z|3796728|rconn|INFO|br-int<->unix#122: disconnecting
>> 2024-08-12T16:01:08.699Z|3796729|rconn|DBG|br-int<->unix#122: entering
>> DISCONNECTED
>> 2024-08-12T16:01:08.699Z|3796730|rconn|INFO|br-int<->unix#123: disconnecting
>> 2024-08-12T16:01:08.699Z|3796731|rconn|DBG|br-int<->unix#123: entering
>> DISCONNECTED
>> 2024-08-12T16:01:08.699Z|3796732|jsonrpc|DBG|unix:/var/run/openvswitch/db.sock:
>>
>> send request, method="transact",
>> params=["Open_vSwitch",{"where":[["_uuid","==",["uuid","5c37aa7c-9394-4068-8a4d-ab23705036d7"]]],"row":{"datapath_id":"0000000000000002"},"op":"update","table":"Bridge"},{"lock":"ovs_vswitchd","op":"assert"}],
>>
>> id=4284802
>> 2024-08-12T16:01:08.701Z|3796733|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 37 (FIFO pipe:[103980657]) at vswitchd/bridge.c:421 (0% CPU usage)
>> 2024-08-12T16:01:08.701Z|3796734|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 17 (<->/var/run/openvswitch/db.sock) at lib/stream-fd.c:157 (0% CPU
>> usage)
>> 2024-08-12T16:01:08.701Z|00691|poll_loop(urcu5)|DBG|wakeup due to
>> [POLLIN] on fd 56 (FIFO pipe:[103975681]) at lib/ovs-rcu.c:236
>> 2024-08-12T16:01:08.701Z|3796735|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 16 (NETLINK_ROUTE<->NETLINK_ROUTE) at lib/netlink-socket.c:1409 (0%
>> CPU usage)
>> 2024-08-12T16:01:08.701Z|3796736|jsonrpc|DBG|unix:/var/run/openvswitch/db.sock:
>>
>> received notification, method="update3",
>> params=[["monid","Open_vSwitch"],"00000000-0000-0000-0000-000000000000",{"Bridge":{"5c37aa7c-9394-4068-8a4d-ab23705036d7":{"modify":{"datapath_id":"0000000000000002"}}}}]
>> 2024-08-12T16:01:08.701Z|3796737|jsonrpc|DBG|unix:/var/run/openvswitch/db.sock:
>>
>> received reply, result=[{"count":1},{}], id=4284802
>> 2024-08-12T16:01:08.701Z|3796738|ovsdb_cs|DBG|unix:/var/run/openvswitch/db.sock:
>>
>> received unexpected reply message:
>> {"error":null,"id":4284802,"result":[{"count":1},{}]}
>> 2024-08-12T16:01:08.702Z|3796739|jsonrpc|DBG|unix:/var/run/openvswitch/db.sock:
>>
>> send request, method="transact",
>> params=["Open_vSwitch",{"where":[["_uuid","==",["uuid","c0210d7f-8482-44e5-8fcb-49df616d3f97"]]],"row":{"mac_in_use":"00:00:00:00:00:02"},"op":"update","table":"Interface"},{"lock":"ovs_vswitchd","op":"assert"}],
>>
>> id=4284803
>> 2024-08-12T16:01:08.703Z|3796740|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 17 (<->/var/run/openvswitch/db.sock) at lib/stream-fd.c:157 (0% CPU
>> usage)
>> 2024-08-12T16:01:08.703Z|3796741|jsonrpc|DBG|unix:/var/run/openvswitch/db.sock:
>>
>> received notification, method="update3",
>> params=[["monid","Open_vSwitch"],"00000000-0000-0000-0000-000000000000",{"Interface":{"c0210d7f-8482-44e5-8fcb-49df616d3f97":{"modify":{"mac_in_use":"00:00:00:00:00:02"}}}}]
>> 2024-08-12T16:01:08.703Z|3796742|jsonrpc|DBG|unix:/var/run/openvswitch/db.sock:
>>
>> received reply, result=[{"count":1},{}], id=4284803
>>
>>
>> Then OVN re-instansiates OF connection. With OVN 22.09.1 this looks like
>> this:
>>
>>
>> 2024-08-12T16:03:52.189Z|00709|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 55 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:274 (0%
>> CPU usage)
>> 2024-08-12T16:03:52.189Z|00710|rconn|DBG|br-int<->unix#4: entering
>> CONNECTING
>> 2024-08-12T16:03:52.189Z|00711|poll_loop|DBG|wakeup due to [POLLOUT] on
>> fd 63 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:153 (0%
>> CPU usage)
>> 2024-08-12T16:03:52.189Z|00712|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 55 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:274 (0%
>> CPU usage)
>> 2024-08-12T16:03:52.189Z|00713|vconn|DBG|unix#4: sent (Success):
>> OFPT_HELLO (OF1.5) (xid=0x4):
>> version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2024-08-12T16:03:52.189Z|00714|vconn|DBG|unix#4: received: OFPT_HELLO
>> (OF1.5) (xid=0x14):
>> version bitmap: 0x06
>> 2024-08-12T16:03:52.189Z|00715|vconn|DBG|unix#4: negotiated OpenFlow
>> version 0x06 (we support version 0x06 and earlier, peer supports version
>> 0x06)
>> 2024-08-12T16:03:52.189Z|00716|rconn|DBG|br-int<->unix#4: connected
>> 2024-08-12T16:03:52.189Z|00717|rconn|DBG|br-int<->unix#4: entering ACTIVE
>> 2024-08-12T16:03:52.189Z|00718|rconn|DBG|br-int<->unix#5: entering
>> CONNECTING
>> 2024-08-12T16:03:52.189Z|00719|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 63 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:157 (0%
>> CPU usage)
>> 2024-08-12T16:03:52.189Z|00720|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 55 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:274 (0%
>> CPU usage)
>> 2024-08-12T16:03:52.189Z|00721|poll_loop|DBG|wakeup due to [POLLOUT] on
>> fd 64 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:153 (0%
>> CPU usage)
>> 2024-08-12T16:03:52.189Z|00722|vconn|DBG|unix#4: received:
>> OFPT_GET_CONFIG_REQUEST (OF1.5) (xid=0x17):
>> 2024-08-12T16:03:52.189Z|00723|vconn|DBG|unix#4: sent (Success):
>> OFPT_GET_CONFIG_REPLY (OF1.5) (xid=0x17): frags=normal miss_send_len=0
>> 2024-08-12T16:03:52.189Z|00724|vconn|DBG|unix#4: received:
>> NXT_SET_PACKET_IN_FORMAT (OF1.5) (xid=0x18): format=nxt_packet_in2
>> 2024-08-12T16:03:52.189Z|00725|vconn|DBG|unix#4: received:
>> OFPT_SET_CONFIG (OF1.5) (xid=0x19): frags=normal miss_send_len=65535
>> 2024-08-12T16:03:52.189Z|00726|vconn|DBG|unix#5: sent (Success):
>> OFPT_HELLO (OF1.5) (xid=0x5):
>> version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2024-08-12T16:03:52.189Z|00727|vconn|DBG|unix#5: received: OFPT_HELLO
>> (OF1.5) (xid=0x15):
>> version bitmap: 0x06
>> 2024-08-12T16:03:52.189Z|00728|vconn|DBG|unix#5: negotiated OpenFlow
>> version 0x06 (we support version 0x06 and earlier, peer supports version
>> 0x06)
>> 2024-08-12T16:03:52.189Z|00729|rconn|DBG|br-int<->unix#5: connected
>> 2024-08-12T16:03:52.189Z|00730|rconn|DBG|br-int<->unix#5: entering ACTIVE
>> 2024-08-12T16:03:52.189Z|00731|rconn|DBG|br-int<->unix#6: entering
>> CONNECTING
>> 2024-08-12T16:03:52.189Z|00732|poll_loop|DBG|wakeup due to [POLLOUT] on
>> fd 65 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:153 (0%
>> CPU usage)
>> 2024-08-12T16:03:52.189Z|00733|vconn|DBG|unix#6: sent (Success):
>> OFPT_HELLO (OF1.5) (xid=0x6):
>> version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2024-08-12T16:03:52.189Z|00734|vconn|DBG|unix#6: received: OFPT_HELLO
>> (OF1.5) (xid=0x16):
>> version bitmap: 0x06
>> 2024-08-12T16:03:52.189Z|00735|vconn|DBG|unix#6: negotiated OpenFlow
>> version 0x06 (we support version 0x06 and earlier, peer supports version
>> 0x06)
>> 2024-08-12T16:03:52.189Z|00736|rconn|DBG|br-int<->unix#6: connected
>> 2024-08-12T16:03:52.189Z|00737|rconn|DBG|br-int<->unix#6: entering ACTIVE
>> 2024-08-12T16:03:52.190Z|00738|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 65 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:157 (0%
>> CPU usage)
>> 2024-08-12T16:03:52.190Z|00739|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 64 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:157 (0%
>> CPU usage)
>> 2024-08-12T16:03:52.190Z|00740|vconn|DBG|unix#5: received:
>> OFPST_METER_FEATURES request (OF1.5) (xid=0x1a):
>> 2024-08-12T16:03:52.190Z|00741|vconn|DBG|unix#5: sent (Success):
>> OFPST_METER_FEATURES reply (OF1.5) (xid=0x1a):
>> max_meter:4294967295 max_bands:1 max_color:0
>> band_types: drop
>> capabilities: kbps pktps burst stats
>> 2024-08-12T16:03:52.190Z|00742|vconn|DBG|unix#6: received:
>> NXT_TLV_TABLE_REQUEST (OF1.5) (xid=0x1b):
>> 2024-08-12T16:03:52.190Z|00743|vconn|DBG|unix#6: sent (Success):
>> NXT_TLV_TABLE_REPLY (OF1.5) (xid=0x1b):
>> max option space=256 max fields=64
>> allocated option space=4
>>
>> mapping table:
>> class type length match field
>> ------ ---- ------ --------------
>> 0x102 0x80 4 tun_metadata0
>>
>> 2024-08-12T16:03:52.209Z|00744|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 64 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:157 (0%
>> CPU usage)
>> 2024-08-12T16:03:52.209Z|00745|vconn|DBG|unix#5: received:
>> OFPST_METER_FEATURES request (OF1.5) (xid=0x1c):
>> 2024-08-12T16:03:52.209Z|00746|vconn|DBG|unix#5: sent (Success):
>> OFPST_METER_FEATURES reply (OF1.5) (xid=0x1c):
>> max_meter:4294967295 max_bands:1 max_color:0
>> band_types: drop
>> capabilities: kbps pktps burst stats
>>
>>
>> But with OVN main there is an OpenFlow error:
>>
>>
>> 2024-08-12T16:08:29.607Z|01803|vconn|DBG|unix#10: sent (Success):
>> OFPT_HELLO (OF1.5) (xid=0xa):
>> version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2024-08-12T16:08:29.607Z|01804|vconn|DBG|unix#10: received: OFPT_HELLO
>> (OF1.5) (xid=0x20d4):
>> version bitmap: 0x06
>> 2024-08-12T16:08:29.607Z|01805|vconn|DBG|unix#10: negotiated OpenFlow
>> version 0x06 (we support version 0x06 and earlier, peer supports version
>> 0x06)
>> 2024-08-12T16:08:29.607Z|01806|rconn|DBG|br-int<->unix#10: connected
>> 2024-08-12T16:08:29.607Z|01807|rconn|DBG|br-int<->unix#10: entering ACTIVE
>> 2024-08-12T16:08:29.607Z|01808|vconn|DBG|unix#10: received:
>> OFPT_GET_CONFIG_REQUEST (OF1.5) (xid=0x20d7):
>> 2024-08-12T16:08:29.607Z|01809|vconn|DBG|unix#10: sent (Success):
>> OFPT_GET_CONFIG_REPLY (OF1.5) (xid=0x20d7): frags=normal miss_send_len=0
>> 2024-08-12T16:08:29.607Z|01810|vconn|DBG|unix#10: received:
>> NXT_SET_PACKET_IN_FORMAT (OF1.5) (xid=0x20d8): format=nxt_packet_in2
>> 2024-08-12T16:08:29.607Z|01811|vconn|DBG|unix#10: received:
>> OFPT_SET_CONFIG (OF1.5) (xid=0x20d9): frags=normal miss_send_len=65535
>> 2024-08-12T16:08:29.607Z|01812|rconn|DBG|br-int<->unix#11: entering
>> CONNECTING
>> 2024-08-12T16:08:29.607Z|01813|poll_loop|DBG|wakeup due to [POLLIN] on
>> fd 91 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:274 (0%
>> CPU usage)
>> 2024-08-12T16:08:29.607Z|01814|poll_loop|DBG|wakeup due to [POLLOUT] on
>> fd 104 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:153 (0%
>> CPU usage)
>> 2024-08-12T16:08:29.608Z|01815|vconn|DBG|unix#11: sent (Success):
>> OFPT_HELLO (OF1.5) (xid=0xb):
>> version bitmap: 0x01, 0x02, 0x03, 0x04, 0x05, 0x06
>> 2024-08-12T16:08:29.608Z|01816|vconn|DBG|unix#11: received: OFPT_HELLO
>> (OF1.5) (xid=0x20d5):
>> version bitmap: 0x06
>> 2024-08-12T16:08:29.608Z|01817|vconn|DBG|unix#11: negotiated OpenFlow
>> version 0x06 (we support version 0x06 and earlier, peer supports version
>> 0x06)
>> 2024-08-12T16:08:29.608Z|01818|rconn|DBG|br-int<->unix#11: connected
>> 2024-08-12T16:08:29.608Z|01819|rconn|DBG|br-int<->unix#11: entering ACTIVE
>> 2024-08-12T16:08:29.608Z|01820|rconn|DBG|br-int<->unix#12: entering
>> CONNECTING
>> 2024-08-12T16:08:29.608Z|01821|poll_loop|DBG|wakeup due to [POLLOUT] on
>> fd 105 (//var/run/openvswitch/br-int.mgmt<->) at lib/stream-fd.c:153 (0%
>> CPU usage)
>> 2024-08-12T16:08:29.608Z|01822|vconn|DBG|unix#11: received:
>> OFPST_METER_FEATURES request (OF1.5) (xid=0x20da):
>> 2024-08-12T16:08:29.608Z|01823|vconn|DBG|unix#11: sent (Success):
>> OFPST_METER_FEATURES reply (OF1.5) (xid=0x20da):
>> max_meter:4294967295 max_bands:1 max_color:0
>> band_types: drop
>> capabilities: kbps pktps burst stats
>> 2024-08-12T16:08:29.608Z|01824|vconn|DBG|unix#11: received:
>> OFPT_BARRIER_REQUEST (OF1.5) (xid=0x20db):
>> 2024-08-12T16:08:29.608Z|01825|vconn|DBG|unix#11: sent (Success):
>> OFPT_BARRIER_REPLY (OF1.5) (xid=0x20db):
>> 2024-08-12T16:08:29.608Z|01826|vconn|DBG|unix#11: received:
>> OFPST_GROUP_FEATURES request (OF1.5) (xid=0x20dc):
>> 2024-08-12T16:08:29.608Z|01827|vconn|DBG|unix#11: sent (Success):
>> OFPST_GROUP_FEATURES reply (OF1.5) (xid=0x20dc):
>> Group table:
>> Types: 0xf
>> Capabilities: 0x7
>> all group:
>> max_groups=0xffffff00
>> actions: output group set_field strip_vlan push_vlan mod_nw_ttl
>> dec_ttl set_mpls_ttl dec_mpls_ttl push_mpls pop_mpls set_queue
>> select group:
>> max_groups=0xffffff00
>> actions: output group set_field strip_vlan push_vlan mod_nw_ttl
>> dec_ttl set_mpls_ttl dec_mpls_ttl push_mpls pop_mpls set_queue
>> indirect group:
>> max_groups=0xffffff00
>> actions: output group set_field strip_vlan push_vlan mod_nw_ttl
>> dec_ttl set_mpls_ttl dec_mpls_ttl push_mpls pop_mpls set_queue
>> fast failover group:
>> max_groups=0xffffff00
>> actions: output group set_field strip_vlan push_vlan mod_nw_ttl
>> dec_ttl set_mpls_ttl dec_mpls_ttl push_mpls pop_mpls set_queue
>> 2024-08-12T16:08:29.608Z|01828|vconn|DBG|unix#11: received:
>> OFPT_BARRIER_REQUEST (OF1.5) (xid=0x20dd):
>> 2024-08-12T16:08:29.608Z|01829|vconn|DBG|unix#11: sent (Success):
>> OFPT_BARRIER_REPLY (OF1.5) (xid=0x20dd):
>> 2024-08-12T16:08:29.609Z|01830|vconn|DBG|unix#11: received:
>> OFPT_BUNDLE_CONTROL (OF1.5) (xid=0x20de):
>> bundle_id=0 type=OPEN_REQUEST flags=atomic ordered
>> 2024-08-12T16:08:29.609Z|01831|vconn|DBG|unix#11: sent (Success):
>> OFPT_BUNDLE_CONTROL (OF1.5) (xid=0x20de):
>> bundle_id=0 type=OPEN_REPLY flags=0
>> 2024-08-12T16:08:29.609Z|01832|ofp_actions|WARN|Dropped 3 log messages
>> in last 104 seconds (most recently, 104 seconds ago) due to excessive rate
>> 2024-08-12T16:08:29.609Z|01833|ofp_actions|WARN|unknown OpenFlow15
>> action for vendor 0x2320 and type 51
>> 2024-08-12T16:08:29.609Z|01834|ofp_actions|WARN|bad action at offset 0
>> (OFPBAC_BAD_VENDOR_TYPE):
>> 00000000 ff ff 00 28 00 00 23 20-00 33 ff ff 00 00 00 00
>> 00000010 00 01 00 04 00 1f 00 00-00 01 00 04 00 1f 00 00
>> 00000020 ff ff 00 00 00 00 00 00-
>> 2024-08-12T16:08:29.609Z|01835|vconn|DBG|unix#11: received:
>> OFPT_BUNDLE_ADD_MESSAGE (OF1.5) (xid=0x20df):
>> bundle_id=0 flags=atomic ordered
>> OFPT_FLOW_MOD (OF1.5) (xid=0x20df): ***decode error:
>> OFPBAC_BAD_VENDOR_TYPE***
>> 00000000 06 0e 00 68 00 00 20 df-00 00 00 00 00 00 00 00 |...h.. .........|
>> 00000010 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 |................|
>> 00000020 ff ff ff ff ff ff ff ff-ff ff ff ff 00 00 00 00 |................|
>> 00000030 00 01 00 04 00 00 00 00-00 04 00 30 00 00 00 00 |...........0....|
>> 00000040 ff ff 00 28 00 00 23 20-00 33 ff ff 00 00 00 00 |...(..# .3......|
>> 00000050 00 01 00 04 00 1f 00 00-00 01 00 04 00 1f 00 00 |................|
>> 00000060 ff ff 00 00 00 00 00 00- |........ |
>> 2024-08-12T16:08:29.609Z|01836|connmgr|INFO|br-int<->unix#11: sending
>> OFPBAC_BAD_VENDOR_TYPE error reply to OFPT_BUNDLE_ADD_MESSAGE message
>> 2024-08-12T16:08:29.609Z|01837|vconn|DBG|unix#11: sent (Success):
>> OFPT_ERROR (OF1.5) (xid=0x20df): OFPBAC_BAD_VENDOR_TYPE
>> OFPT_BUNDLE_ADD_MESSAGE (OF1.5) (xid=0x20df):
>> bundle_id=0 flags=atomic ordered
>> OFPT_FLOW_MOD (OF1.5) (xid=0x20df): ***decode error:
>> OFPBAC_BAD_VENDOR_TYPE***
>> 00000000 06 0e 00 68 00 00 20 df-00 00 00 00 00 00 00 00 |...h.. .........|
>> 00000010 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 |................|
>> 00000020 ff ff ff ff ff ff ff ff-ff ff ff ff 00 00 00 00 |................|
>> 00000030 00 01 00 04 00 00 00 00-00 04 00 30 00 00 00 00 |...........0....|
>> 00000040 ff ff 00 28 00 00 23 20-00 33 ff ff 00 00 00 00 |...(..# .3......|
>> 00000050 00 01 00 04 00 1f 00 00-00 01 00 04 00 1f 00 00 |................|
>> 00000060 ff ff 00 00 00 00 00 00- |........ |
>> 2024-08-12T16:08:29.609Z|01838|vconn|DBG|unix#11: received:
>> OFPT_BUNDLE_CONTROL (OF1.5) (xid=0x20e0):
>> bundle_id=0 type=DISCARD_REQUEST flags=atomic ordered
>> 2024-08-12T16:08:29.609Z|01839|vconn|DBG|unix#11: sent (Success):
>> OFPT_BUNDLE_CONTROL (OF1.5) (xid=0x20e0):
>> bundle_id=0 type=DISCARD_REPLY flags=0
>> 2024-08-12T16:08:29.609Z|01840|vconn|DBG|unix#11: received:
>> OFPT_BARRIER_REQUEST (OF1.5) (xid=0x20e1):
>> 2024-08-12T16:08:29.609Z|01841|vconn|DBG|unix#11: sent (Success):
>> OFPT_BARRIER_REPLY (OF1.5) (xid=0x20e1):
>>
>>
>> The behavior was tested against OVS 3.1.1 and 3.3.1. Results are the same.
>>
>> My questions are:
>>
>> 1. How to understand the reason for OF disconnect? I don't see any
>> specific error in OVS log.> 2. I see that OF Error in handling
>> OFPT_BUNDLE_ADD_MESSAGE is triggered
>> on each OF connection instantiation within ovn-controller. Is this a
>> real error (despite of this is a DBG loglevel)?
>
> I'd guess it's a feature discovery for the new SAMPLE4 action, i.e.
> sample action with registers as observation point/ids. This is only
> supported in upcoming OVS 3.4. So, you'll see these debug errors on
> earlier releases and that is expected.
>
> Do you see the same issue with OVS' branch-3.4 ?
>
> However, OVN should not disconnect on these errors. Might be a bug in
> the feature checking code in ovn-controller. I'd guess that controller
> disconnects after receiving any OF error. But it should not do that
> during feature support checks.
Or maybe I misunderstood. The disconnection happens before the feature
re-negotiation. Either way the OF errors in the log are likely expected
when using older OVS.
>
> Ales, could you take a look?
>
> Best regards, Ilya Maximets.
_______________________________________________
dev mailing list
[email protected]
https://mail.openvswitch.org/mailman/listinfo/ovs-dev
