The crash happens when "ovs-ofctl dump-flows" is envoked.

I performed some triage on the provided core dump, and found that this crash is triggered when ofpmp_postappend() encounters a flow with more than 65535 bytes worth of action. In this case, there is a flow with 80360 bytes worth of actions.


(gdb) f 8
#8  0x0000559e8eabb522 in handle_flow_stats_request
2073	    return ovsrcu_get(struct tun_table *, &ofproto->metadata_tab);
(gdb) p ((struct rule **)rules->collection->objs)[406076]->actions->ofpacts_len
$7 = 80360
(gdb) ovs_dump_ofpacts 0x559eb5a743b8 80360
(struct ofpact *) 0x559eb5a743b8: {type = OFPACT_SET_FIELD, raw = 255 '\377', len = 24}
(struct ofpact *) 0x559eb5a743d0: {type = OFPACT_RESUBMIT, raw = 38 '&', len = 16}
(struct ofpact *) 0x559eb5a743e0: {type = OFPACT_SET_FIELD, raw = 255 '\377', len = 24}
(struct ofpact *) 0x559eb5a743f8: {type = OFPACT_RESUBMIT, raw = 38 '&', len = 16}
(struct ofpact *) 0x559eb5a74408: {type = OFPACT_SET_FIELD, raw = 255 '\377', len = 24}
[...Over 4000 lines truncated]
(struct ofpact *) 0x559eb5a87d78: {type = OFPACT_SET_FIELD, raw = 255 '\377', len = 24}
(struct ofpact *) 0x559eb5a87d90: {type = OFPACT_RESUBMIT, raw = 38 '&', len = 16}


I attempted to reproduce this condition with ovs-ofctl; however, the ovs-ofctl utility would not allow me to produce an action larger than 65535 bytes:

# ovs-ofctl --bundle add-flows s1 large_flow.txt
Error OFPBMC_BAD_LEN for: (***only uses 56 bytes out of 65592***)
00000000  05 0e 00 38 00 00 00 06-00 00 00 00 00 00 00 00 |...8............|
00000010  00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 64 |...............d|
00000020  ff ff ff ff ff ff ff ff-ff ff ff ff 00 00 00 00 |................|


I'm not too familiar with OVN, but I see that it does modify flow structs directly. It may be adding structures that are invalid in OVS.

(gdb) ovs_dump_ovs_list replies 'struct ofpbuf' list_node dump
...
(struct ofpbuf *) 0x559eb8c4b2f0 =
  {base = 0x559ec1d8a080, data = 0x559ec1d8a080, size = 64376, allocated = 65640, header = 0x559ec1d8a080, msg = 0x559ec1d8a098, list_node = {prev = 0x559eb861d798, next = 0x559eb8a41dd8}, source = OFPBUF_MALLOC}

(struct ofpbuf *) 0x559eb8a41db0 =
  {base = 0x559ec1d9a0f0, data = 0x559ec1d9a0f0, size = 45352, allocated = 125808, header = 0x559ec1d9a0f0, msg = 0x559ec1d9a108, list_node = {prev = 0x559eb8c4b318, next = 0x559eb12d1a48}, source = OFPBUF_MALLOC}

(struct ofpbuf *) 0x559eb12d1a20 =
  {base = 0x559ec1db8c70, data = 0x559ec1db8c70, size = 80600, allocated = 80632, header = 0x559ec1db8c70, msg = 0x559ec1db8c88, list_node = {prev = 0x559eb8a41dd8, next = 0x7ffe18e8a0d0}, source = OFPBUF_MALLOC}

^^ Total 926 entries!!

(gdb) p start_ofs
$4 = 80456

(gdb) p *(struct ofp10_flow_stats *) (((struct ofpbuf *) 0x559eb12d1a20)->data + start_ofs)
$23 = {length = 36864, table_id = 37 '%', pad = 0 '\000', match = {wildcards = 1929445376, in_port = 26403, dl_src = {{ea = "\270\200\000d\000", be16 = {32952, 25600, 0}}}, dl_dst = {{ea = "\000\000\000\024\001t", be16 = {0, 5120, 29697}}}, dl_vlan = 29697, dl_vlan_pcp = 0 '\000', 
    pad1 = "", dl_type = 0, nw_tos = 200 '\310', nw_proto = 143 '\217', pad2 = "&K", nw_src = 0, nw_dst = 0, tp_src = 0, tp_dst = 0}, duration_sec = 0, duration_nsec = 69075200, priority = 0, idle_timeout = 768, hard_timeout = 128, pad2 = "\004\b\000\000\000", cookie = {
    hi = 2349137920, lo = 0}, packet_count = {hi = 402718719, lo = 539164672}, byte_count = {hi = 385877760, lo = 136315136}}

(gdb) p /x ((struct ofp10_flow_stats *) (((struct ofpbuf *) 0x559eb12d1a20)->data + start_ofs))->length
$26 = 0x9000

 0x0090 -> 144  ====  size = 80600 - start_ofs = 80456  => 144

(gdb) p /x ((struct ofp10_flow_stats *) (((struct ofpbuf *) 0x559eb12d1a20)->data))->length
$27 = 0x1101

 0x0111 -> 273


Question why is the last fragment of 80600 not broken up?

Looks like the previous length was rather large, as for the split we allocated 125808 bytes, and the previous size restored was 45352, so this might hint that the previous message was 125808 - 45352 = 80456 bytes :(

What was the previous request?!?
Data msg header (previous message):

(gdb) p *(struct ofp_header *) (((struct ofpbuf *) 0x559eb12d1a20)->data)
$33 = {version = 1 '\001', type = 17 '\021', length = 6144, xid = 67108864}

Version is 1 --> OFP10_VERSION = 0x01
Type is 17 --> #define OFPT10_STATS_REPLY 17

(gdb) p *(struct ofp10_stats_msg *) (((struct ofpbuf *) 0x559eb12d1a20)->data)
$34 = {header = {version = 1 '\001', type = 17 '\021', length = 6144, xid = 67108864}, type = 65535, flags = 0}

(gdb) p /x ((struct ofp10_stats_msg *) (((struct ofpbuf *) 0x559eb12d1a20)->data))->header.length
$36 = 0x1800

== 24 bytes

(gdb) p sizeof(struct ofp10_stats_msg)
$50 = 12

but type = OFPST_VENDOR 0xffff so:

(gdb) p sizeof(struct nicira10_stats_msg)
$51 = 24

(gdb) p *(struct nicira10_stats_msg *) (((struct ofpbuf *) 0x559eb12d1a20)->data)
$53 = {vsm = {osm = {header = {version = 1 '\001', type = 17 '\021', length = 6144, xid = 67108864}, type = 65535, flags = 0}, vendor = 539164672}, subtype = 0, pad = "\000\000\000"}

Next message is than at ->data + 24

0x559ec1db8c70+24 = 0x559ec1db8c88 ==== ->msg

(gdb) p *(struct ofp10_flow_stats *) (((struct ofpbuf *) 0x559eb12d1a20)->data + 24)
(gdb) p /x *(struct ofp10_flow_stats *) (((struct ofpbuf *) 0x559eb12d1a20)->msg)
$37 = {length = 12346, table_id = 37 '%', pad = 0 '\000', match = {wildcards = 1929445376, in_port = 26403, dl_src = {{ea = "\270\200\000d\000", be16 = {32952, 25600, 0}}}, dl_dst = {{ea = "\000\000\000\024\001t", be16 = {0, 5120, 29697}}}, dl_vlan = 29697, dl_vlan_pcp = 0 '\000', 
    pad1 = "", dl_type = 0, nw_tos = 69 'E', nw_proto = 199 '\307', pad2 = "<", nw_src = 0, nw_dst = 0, tp_src = 0, tp_dst = 0}, duration_sec = 0, duration_nsec = 69075200, priority = 0, idle_timeout = 128, hard_timeout = 128, pad2 = "\004\b\000\000\000", cookie = {hi = 16777216, 
    lo = 0}, packet_count = {hi = 402718719, lo = 539164672}, byte_count = {hi = 520095488, lo = 69075200}}

(gdb) p /x ((struct ofp10_flow_stats *) (((struct ofpbuf *) 0x559eb12d1a20)->data + 24))->length
$39 = 0x303a

3a30 => 14896

The below next entry looks odd!?

(gdb)  p *(struct ofp10_flow_stats *) (((struct ofpbuf *) 0x559eb12d1a20)->msg + 0x3a30)
$58 = {length = 65535, table_id = 0 '\000', pad = 16 '\020', match = {wildcards = 539164672, in_port = 3584, dl_src = {{ea = "\377\370'\000\000", be16 = {63743, 39, 0}}}, dl_dst = {{ea = "\377\377\000\030\000", be16 = {65535, 6144, 0}}}, dl_vlan = 8227, dl_vlan_pcp = 0 '\000', 
    pad1 = "\a", dl_type = 7936, nw_tos = 0 '\000', nw_proto = 1 '\001', pad2 = "\036\004", nw_src = 0, nw_dst = 2600730624, tp_src = 65535, tp_dst = 4096}, duration_sec = 539164672, duration_nsec = 4177464832, priority = 39, idle_timeout = 0, hard_timeout = 65535, 
  pad2 = "\000\030\000\000# ", cookie = {hi = 520095488, lo = 69075200}, packet_count = {hi = 0, lo = 2265055232}, byte_count = {hi = 268500991, lo = 539164672}}


0xffff + 3a30 == 0x13a2f -> 80431  + 24 for header = 80455 offset -> len at start 80456....

This looks almost like the correct size (-1 byte), but the content also looks corrupted.
I inspected a lot of code but could not find any clue on how this could happen.

But these are the things that keep me awake at night, and at 00:36 I had a perfect theory, and I could go to sleep :)

The total message size is indeed over 64K, and as the size is stored in uint16, it overflowed.

80456 - 24 (hdr) = 80432 => 0x13a30 => htons(0x13a30) = 0x303a


So what was the previous flow entry that added so many actions that it went over 64K?


(gdb) frame 8
#8  0x0000559e8eabb522 in handle_flow_stats_request (ofconn=ofconn@entry=0x559e9138e5b0, request=request@entry=0x559eb8162e50) at ../ofproto/ofproto-provider.h:2073
(gdb) p i__
$2 = 406077

So previous entry was 406076

(gdb) p (struct rule *)rules->collection.objs[i__ - 1]
$9 = (struct rule *) 0x559eb59d6ab0
(gdb) p *(struct rule *)rules->collection.objs[i__ - 1]
$10 = {ofproto = 0x559e907e0220, cr = {node = {prev = 0x559eb5a50238, next = {p = 0x559eb5a71148}}, priority = 100, cls_match = {p = 0x559ebe235990}, match = {{{flow = 0x559eb5a50b30, mask = 0x559eb5a50b50}, flows = {
          0x559eb5a50b30, 0x559eb5a50b50}}, tun_md = 0x0}}, table_id = 37 '%', state = RULE_INSERTED, mutex = {lock = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 2, __spins = 0, __elision = 0, __list = {
          __prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 16 times>, "\002", '\000' <repeats 22 times>, __align = 0}, where = 0x559e8ed54c5d "<unlocked>"}, ref_count = {count = 2}, flow_cookie = 17107597769310208, 
  cookie_node = {hash = 2280874424, d = 0x559ea11ca418, s = 0x559eb613ed28}, flags = (unknown: 0), hard_timeout = 0, idle_timeout = 0, importance = 0, removed_reason = 6 '\006', eviction_group = 0x0, evg_node = {idx = 0, 
    priority = 0}, actions = 0x559eb5a743b0, meter_list_node = {prev = 0x559eb59d6b80, next = 0x559eb59d6b80}, monitor_flags = (unknown: 0), add_seqno = 541882, modify_seqno = 541882, expirable = {prev = 0x559eb59d6ba8, 
    next = 0x559eb59d6ba8}, created = 2075283079, modified = 2075283079, match_tlv_bitmap = 0, ofpacts_tlv_bitmap = 0}


(gdb) p *((struct rule *)rules->collection.objs[i__ - 1])->actions
$12 = {has_meter = false, has_learn_with_delete = false, has_groups = false, ofpacts_len = 80360, ofpacts = 0x559eb5a743b8}


(gdb) ovs_dump_ofpacts 0x559eb5a743b8 80360
(struct ofpact *) 0x559eb5a743b8: {type = OFPACT_SET_FIELD, raw = 255 '\377', len = 24}
(struct ofpact *) 0x559eb5a743d0: {type = OFPACT_RESUBMIT, raw = 38 '&', len = 16}
(struct ofpact *) 0x559eb5a743e0: {type = OFPACT_SET_FIELD, raw = 255 '\377', len = 24}
...
...
(struct ofpact *) 0x559eb5a87d28: {type = OFPACT_SET_FIELD, raw = 255 '\377', len = 24}
(struct ofpact *) 0x559eb5a87d40: {type = OFPACT_RESUBMIT, raw = 38 '&', len = 16}
(struct ofpact *) 0x559eb5a87d50: {type = OFPACT_SET_FIELD, raw = 255 '\377', len = 24}
(struct ofpact *) 0x559eb5a87d68: {type = OFPACT_RESUBMIT, raw = 38 '&', len = 16}
(struct ofpact *) 0x559eb5a87d78: {type = OFPACT_SET_FIELD, raw = 255 '\377', len = 24}
(struct ofpact *) 0x559eb5a87d90: {type = OFPACT_RESUBMIT, raw = 38 '&', len = 16}

Total of 4019 entries...

(gdb) p *(struct ofpact_set_field*) 0x559eb5a87d78
$16 = {{{ofpact = {type = OFPACT_SET_FIELD, raw = 255 '\377', len = 24}, flow_has_vlan = false, field = 0x559e8f0c4e20 <mf_fields+6496>}, pad21 = "\006\377\030\000\000\000\000\000 N\f\217\236U\000"}, value = 0x559eb5a87d88}
(gdb) p * (struct mf_field *)0x559e8f0c4e20
$17 = {id = MFF_REG15, name = 0x559e8ed686e1 "reg15", extra_name = 0x0, n_bytes = 4, n_bits = 32, variable_len = false, maskable = MFM_FULLY, string = MFS_HEXADECIMAL, prereqs = MFP_NONE, writable = true, mapped = false, 
  usable_protocols_exact = (OFPUTIL_P_OF10_NXM | OFPUTIL_P_OF10_NXM_TID | OFPUTIL_P_OF12_OXM | OFPUTIL_P_OF13_OXM | OFPUTIL_P_OF14_OXM | OFPUTIL_P_OF15_OXM), 
  usable_protocols_cidr = (OFPUTIL_P_OF10_NXM | OFPUTIL_P_OF10_NXM_TID | OFPUTIL_P_OF12_OXM | OFPUTIL_P_OF13_OXM | OFPUTIL_P_OF14_OXM | OFPUTIL_P_OF15_OXM), 
  usable_protocols_bitwise = (OFPUTIL_P_OF10_NXM | OFPUTIL_P_OF10_NXM_TID | OFPUTIL_P_OF12_OXM | OFPUTIL_P_OF13_OXM | OFPUTIL_P_OF14_OXM | OFPUTIL_P_OF15_OXM), flow_be32ofs = -1}

(gdb) p *(struct ofpact_resubmit *) 0x559eb5a87d90
$18 = {{{ofpact = {type = OFPACT_RESUBMIT, raw = 38 '&', len = 16}, in_port = 65528, table_id = 38 '&', with_ct_orig = false}, pad34 = "&&\020\000\370\377\000\000&\000\000\000\000\000\000"}}

So we have so many actions that it overflows the 64K limit... 

A quick peek at the openflows spec does not show a solution, actually, it does not mention these limits at all.

It's very likely these flows are added by ovn-controller here, for the MC_FLOOD multicast group that handles BUM traffic:

https://github.com/ovn-org/ovn/blob/d659b6538b00bd72aeca1fc5dd3a3c337ac53f37/controller/physical.c#L1526

I'm guessing this is for the provider logical switch which has a lot of ports connected to it.

I've been trying to add 4k actions into a single flow rule, and from code/ovs-ofctl add-flow I'm not able to do this without overrunning the message length when creating the flow.

This makes me wonder how OVN is able to do so, or if OVN is sending such a message that could corrupt the flows?!?

Dumitru is there data we can take from the live setup, which could help us recreate the problem? Or do you see an easy way to let OVN create these many actions?

(In reply to Eelco Chaudron from comment #6)
> I've been trying to add 4k actions into a single flow rule, and from
> code/ovs-ofctl add-flow I'm not able to do this without overrunning the
> message length when creating the flow.
> 
> This makes me wonder how OVN is able to do so, or if OVN is sending such a
> message that could corrupt the flows?!?

ovn-controller uses bundles, maybe that's the difference?

> 
> Dumitru is there data we can take from the live setup, which could help us
> recreate the problem? Or do you see an easy way to let OVN create these many
> actions?

In any case, we can repr the crash in an OVN sandbox; from an OVN source directory, run:

$ make sandbox

$ ./ovn-setup.sh # This creates a very simple topology with a couple of switches.

$ # Add 1200 more ports to one of the switches and bind them to OVN
$ for i in $(seq 1 1200); do echo "Adding port $i"; p=lsp$i; ovs-vsctl add-port br-int $p -- set interface $p external_ids:iface-id=$p; ovn-nbctl lsp-add sw0 $p; done

$ # Try to dump OVS flows (table=38 has the large flows), this crashes ovs-vswitchd running in the sandbox.
$ ovs-ofctl dump-flows br-int table=38

So OVN is communicating with OVS using OpenFlow15, which as it turns out has a slightly optimized message format compared to OpenFlow10 which is used by default for the ovs-ofctl commands. So to avoid the crash for now, please use the  -O OpenFlow15 option when dumping the flows. For example:

  ovs-ofctl dump-flows -O OpenFlow15 br-int 

Note that I assumed if you add enough interfaces to OVN we will eventually also hit the 64K limit. But doing a quick test with 2000 interfaces it looks like we get two flow entries. So there must be some split logic, however, I did not investigate.

The next step from my side will be to come up with a patch to no longer crash OVS and just log a message and skip reporting the specific flow.

Did a quick test, and it looks like OVN is not splitting up the flows at all, but it will just fail adding the correct flows.
If you use the reproduced in #7, with the following:

 for i in $(seq 1 1365); do echo "Adding port $i"; p=lsp$i; ovs-vsctl add-port br-int $p -- set interface $p external_ids:iface-id=$p; ovn-nbctl lsp-add sw0 $p; done

The flow dumped will look like this, only a single resubmit:

ovs-ofctl dump-flows -O OpenFlow15  br-int table=38
...
 cookie=0x5bbbbfcb, duration=123.316s, table=38, n_packets=0, n_bytes=0, idle_age=123, priority=100,reg15=0x8000,metadata=0x1 actions=set_field:0x28d->reg13,set_field:0x287->reg15,resubmit(,39)
 cookie=0x667e983f, duration=123.316s, table=38, n_packets=0, n_bytes=0, idle_age=123, priority=100,reg15=0x8005,metadata=0x1 actions=set_field:0x28d->reg13,set_field:0x287->reg15,resubmit(,39)

Jakub can you confirm that the crash is no longer happening if you use the -O option? If so please use this for now, and in the meantime Mike will create a scratch build with excluding the offending flow from a flow dump with an older protocol.

  ovs-ofctl dump-flows -O OpenFlow15 br-int

(In reply to Eelco Chaudron from comment #11)
> Jakub can you confirm that the crash is no longer happening if you use the
> -O option? If so please use this for now, and in the meantime Mike will
> create a scratch build with excluding the offending flow from a flow dump
> with an older protocol.
> 
>   ovs-ofctl dump-flows -O OpenFlow15 br-int

I confirm it does not crash with OpenFlow15 option passed. Thanks!

Send patch upstream, including test:

https://mail.openvswitch.org/pipermail/ovs-dev/2021-December/389947.html

Sent out a v2 patch:

https://patchwork.ozlabs.org/project/openvswitch/patch/164137609877.78369.18113934022836014613.stgit@ebuild/

Sent out a v4 patch:

https://patchwork.ozlabs.org/project/openvswitch/list/?series=280231

Fix got accepted upstream, and was backported all the way down to 2.13.

$ git show 4056ae487
commit 4056ae4875541197eab1b346ab84f23077ff9dea
Author: Eelco Chaudron <echaudro>
Date:   Mon Jan 10 09:13:49 2022 +0100

    ofp-flow: Skip flow reply if it exceeds the maximum message size.
    
    Currently, if a flow reply results in a message which exceeds
    the maximum reply size, it will assert OVS. This would happen
    when OVN uses OpenFlow15 to add large flows, and they get read
    using OpenFlow10 with ovs-ofctl.
    
    This patch prevents this and adds a test case to make sure the
    code behaves as expected.
    
    Signed-off-by: Eelco Chaudron <echaudro>
    Reviewed-by: Maxime Coquelin <maxime.coquelin>
    Signed-off-by: Ilya Maximets <i.maximets>


Will close this BZ as the fix will make its way down to downstream automatically in the next release (FDP 22.B).