Re: [ovs-discuss] [BUG] ovn-controller stops sending DHCPOFFER

Ilia Baikov via discuss Thu, 20 Feb 2025 14:13:48 -0800

Hi

Over a lot of observes and testing various number of possible fixes camewith nothing...


Yes, there are messages that contains NXT_RESUME substring.

ovn-controller:

2025-02-18T21:05:51.771Z|1041129|vconn(ovn_pinctrl0)|DBG|unix:/var/run/openvswitch/br-int.mgmt:sent (Success): NXT_RESUME (OF1.5) (xid=0x0): cookie=0x404b44bctotal_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0x13c,reg14=0x4a8,metadata=0x2,in_port=312(via action) data_len=348 (unbuffered)2025-02-18T21:08:23.729Z|1044255|vconn(ovn_pinctrl0)|DBG|unix:/var/run/openvswitch/br-int.mgmt:sent (Success): NXT_RESUME (OF1.5) (xid=0x0): cookie=0xffe9d519total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0x112,reg14=0x2dd,metadata=0x2,in_port=363(via action) data_len=348 (unbuffered)2025-02-18T21:10:33.865Z|1046917|vconn(ovn_pinctrl0)|DBG|unix:/var/run/openvswitch/br-int.mgmt:sent (Success): NXT_RESUME (OF1.5) (xid=0x0): cookie=0x5bc96bd6total_len=348reg0=0x28b,reg11=0x9,reg12=0xa,reg13=0x57,reg14=0x423,metadata=0x2,in_port=83(via action) data_len=348 (unbuffered)2025-02-18T21:11:06.733Z|1047596|vconn(ovn_pinctrl0)|DBG|unix:/var/run/openvswitch/br-int.mgmt:sent (Success): NXT_RESUME (OF1.5) (xid=0x0): cookie=0x5bc96bd6total_len=348reg0=0x28b,reg11=0x9,reg12=0xa,reg13=0x5f,reg14=0x413,metadata=0x2,in_port=91(via action) data_len=348 (unbuffered)2025-02-18T21:12:16.984Z|1048995|vconn(ovn_pinctrl0)|DBG|unix:/var/run/openvswitch/br-int.mgmt:sent (Success): NXT_RESUME (OF1.5) (xid=0x0): cookie=0xfded3de0total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0xc5,reg14=0x354,metadata=0x2,in_port=373(via action) data_len=348 (unbuffered)2025-02-18T21:13:03.396Z|1049934|vconn(ovn_pinctrl0)|DBG|unix:/var/run/openvswitch/br-int.mgmt:sent (Success): NXT_RESUME (OF1.5) (xid=0x0): cookie=0xfded3de0total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0xc5,reg14=0x354,metadata=0x2,in_port=373(via action) data_len=348 (unbuffered)2025-02-18T21:19:48.641Z|1058227|vconn(ovn_pinctrl0)|DBG|unix:/var/run/openvswitch/br-int.mgmt:sent (Success): NXT_RESUME (OF1.5) (xid=0x0): cookie=0xbbfea837total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0x132,reg14=0x434,metadata=0x2,in_port=302(via action) data_len=348 (unbuffered)2025-02-18T21:19:50.069Z|1058255|vconn(ovn_pinctrl0)|DBG|unix:/var/run/openvswitch/br-int.mgmt:sent (Success): NXT_RESUME (OF1.5) (xid=0x0): cookie=0x5bc96bd6total_len=348reg0=0x28b,reg11=0x9,reg12=0xa,reg13=0x6f,reg14=0x148,metadata=0x2,in_port=107(via action) data_len=348 (unbuffered)2025-02-18T21:21:38.224Z|1060474|vconn(ovn_pinctrl0)|DBG|unix:/var/run/openvswitch/br-int.mgmt:sent (Success): NXT_RESUME (OF1.5) (xid=0x0): cookie=0x5bc96bd6total_len=348reg0=0x28b,reg11=0x9,reg12=0xa,reg13=0xdb,reg14=0x336,metadata=0x2,in_port=215(via action) data_len=348 (unbuffered)2025-02-18T21:21:42.735Z|1060568|vconn(ovn_pinctrl0)|DBG|unix:/var/run/openvswitch/br-int.mgmt:sent (Success): NXT_RESUME (OF1.5) (xid=0x0): cookie=0xffe9d519total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0x112,reg14=0x2dd,metadata=0x2,in_port=363(via action) data_len=348 (unbuffered)


ovs-vswitchd

2025-02-18T20:55:45.673Z|1086321|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0x58482a66 total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0x151,reg14=0x4b1,metadata=0x2,in_port=375(via action) data_len=348 (unbuffered)2025-02-18T21:01:05.872Z|1092877|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0x983e6272 total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0x15f,reg14=0x4d3,metadata=0x2,in_port=368(via action) data_len=348 (unbuffered)2025-02-18T21:01:23.672Z|1093239|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0xfded3de0 total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0xc5,reg14=0x354,metadata=0x2,in_port=373(via action) data_len=348 (unbuffered)2025-02-18T21:04:03.272Z|1096513|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0xfded3de0 total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0xc5,reg14=0x354,metadata=0x2,in_port=373(via action) data_len=348 (unbuffered)2025-02-18T21:07:36.773Z|1100887|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0xfded3de0 total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0xc5,reg14=0x354,metadata=0x2,in_port=373(via action) data_len=348 (unbuffered)2025-02-18T21:07:51.472Z|1101187|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0xa6d16298 total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0x4b,reg14=0x1bb,metadata=0x2,in_port=349(via action) data_len=348 (unbuffered)2025-02-18T21:08:08.673Z|1101537|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0x8b831d17 total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0x26,reg14=0x123,metadata=0x2,in_port=34(via action) data_len=348 (unbuffered)2025-02-18T21:09:09.173Z|1102776|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0xbf424a23 total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0x85,reg14=0x2d9,metadata=0x2,in_port=371(via action) data_len=348 (unbuffered)2025-02-18T21:13:03.574Z|1108046|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0xfded3de0 total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0xc5,reg14=0x354,metadata=0x2,in_port=373(via action) data_len=348 (unbuffered)2025-02-18T21:17:18.772Z|1113273|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0x5bc96bd6 total_len=348reg0=0x28b,reg11=0x9,reg12=0xa,reg13=0x7c,reg14=0x241,metadata=0x2,in_port=120(via action) data_len=348 (unbuffered)2025-02-18T21:18:51.673Z|1115178|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0xfded3de0 total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0xc5,reg14=0x354,metadata=0x2,in_port=373(via action) data_len=348 (unbuffered)2025-02-18T21:19:36.872Z|1116105|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0x5bc96bd6 total_len=348reg0=0x28b,reg11=0x9,reg12=0xa,reg13=0x87,reg14=0x4b,metadata=0x2,in_port=131(via action) data_len=348 (unbuffered)2025-02-18T21:19:52.172Z|1116417|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0xfded3de0 total_len=348reg0=0x308,reg11=0x9,reg12=0xa,reg13=0xc5,reg14=0x354,metadata=0x2,in_port=373(via action) data_len=348 (unbuffered)2025-02-18T21:20:24.572Z|1117078|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0x5bc96bd6 total_len=348reg0=0x28b,reg11=0x9,reg12=0xa,reg13=0x8b,reg14=0x2fb,metadata=0x2,in_port=135(via action) data_len=348 (unbuffered)2025-02-18T21:21:31.672Z|1118459|vconn|DBG|unix#0: received: NXT_RESUME(OF1.5) (xid=0x0): cookie=0x5bc96bd6 total_len=348reg0=0x28b,reg11=0x9,reg12=0xa,reg13=0x93,reg14=0xdd,metadata=0x2,in_port=143(via action) data_len=348 (unbuffered)


The interesting logs is also at ovn-controller logs

IPs are sanitized, anyway 13.37.13 belongs to subnet #1 and 13.38.13 tosubnet #2. Observing large regression across all infra, like almost 50%overall network bandwith loss over time.


Any thoughts guys?

Context: we run a lot of small instances with 1 x fixed IP with littleamount of external traffic, about 300 per hypervisor, sometimes more,sometimes less anyway didn't see anything similar with plain ovs andneutron-openvswitch-agent (openstack).UPD: Once i manually cleared dhcpv4_options column in all ports seemslike neutron-dhcp-agent (dnsmasq based) started to send dhcpoffers andmost of instances back to normal. However, didn't manage what is thereason to ovn-controller not send DHCPOFFER to VIF. Seems like a bigpoint of regression starting from N number of instances or something else.

10.02.2025 17:36, Numan Siddique:

On Sat, Feb 8, 2025 at 1:27 PM support via discuss<ovs-discuss@openvswitch.org> wrote:


    I'm observing for a long time next bug: ovn-controller doesn't
    send DHCPOFFER but it logs that it does. However this VIF doesn't
    get it at all.
    But once ovn-controller restarted it successfully seems like it
    actually send DHCPOFFER and immediately receives DHCPACK from VIF.

When you see this issue, can you enable vconn and rcon debug logs inboth ovn-controller and ovs-vswitchd ?


ovn-appctl vlog/set rconn:dbg
ovn-appctl vlog/set vconn:dbg

ovs-appctl vlog/set rconn:dbg
ovs-appctl vlog/set rconn:dbg

If ovn-controller replies with a DHCPOFFER, you should see theNXT_RESUME related logs in both ovn-controller and ovs-vswitchd.


This can help you narrow down the issue.

Thanks
Numan

    |2025-02-08T14:27:57.462Z|00053|pinctrl(ovn_pinctrl0)|INFO|DHCPOFFER
    fa:16:3e:80:67:62 13.37.0.5
    2025-02-08T14:28:01.746Z|00054|pinctrl(ovn_pinctrl0)|INFO|DHCPOFFER
    fa:16:3e:80:67:62 13.37.0.5
    2025-02-08T14:28:05.582Z|00055|pinctrl(ovn_pinctrl0)|INFO|DHCPOFFER
    fa:16:3e:80:67:62 13.37.0.5
    2025-02-08T14:28:13.053Z|00056|pinctrl(ovn_pinctrl0)|INFO|DHCPOFFER
    fa:16:3e:80:67:62 13.37.0.5
    2025-02-08T14:28:21.972Z|00057|pinctrl(ovn_pinctrl0)|INFO|DHCPOFFER
    fa:16:3e:84:8e:7f 13.37.0.37
    2025-02-08T14:28:25.109Z|00058|pinctrl(ovn_pinctrl0)|INFO|DHCPOFFER
    fa:16:3e:84:8e:7f 13.37.0.37
    2025-02-08T14:28:29.362Z|00059|pinctrl(ovn_pinctrl0)|INFO|DHCPOFFER
    fa:16:3e:84:8e:7f 13.37.0.37
    2025-02-08T14:28:30.003Z|00060|pinctrl(ovn_pinctrl0)|INFO|DHCPOFFER
    fa:16:3e:80:67:62 13.37.0.5
    2025-02-08T14:28:37.820Z|00061|pinctrl(ovn_pinctrl0)|INFO|DHCPOFFER
    fa:16:3e:84:8e:7f 13.37.0.37
    2025-02-08T14:28:38.619Z|00002|fatal_signal(ovn_statctrl2)|WARN|terminating
    with signal 15 (Terminated) # ovn_controller is restarted by
    docker restart ovn_controller
    2025-02-08T14:28:50.639Z|00001|vlog|INFO|opened log file
    /var/log/kolla/openvswitch/ovn-controller.log
    2025-02-08T14:28:50.640Z|00002|vif_plug_representor|INFO|unable
    to set udev receive buffer size: Operation not permitted
    2025-02-08T14:28:50.641Z|00003|reconnect|INFO|tcp:127.0.0.1:6640
    <http://127.0.0.1:6640>: connecting...
    2025-02-08T14:28:50.641Z|00004|reconnect|INFO|tcp:127.0.0.1:6640
    <http://127.0.0.1:6640>: connected
    2025-02-08T14:28:50.738Z|00005|main|INFO|OVN internal version is
    : [24.09.0-20.37.0-73.6]
    2025-02-08T14:28:50.738Z|00006|main|INFO|OVS IDL reconnected,
    force recompute.
    2025-02-08T14:28:50.738Z|00007|reconnect|INFO|tcp:10.10.9.5:6642
    <http://10.10.9.5:6642>: connecting...
    2025-02-08T14:28:50.738Z|00008|main|INFO|OVNSB IDL reconnected,
    force recompute.
    2025-02-08T14:28:50.739Z|00009|ovn_util|INFO|statctrl: connecting
    to switch: "unix:/var/run/openvswitch/br-int.mgmt"
    
2025-02-08T14:28:50.739Z|00010|rconn|INFO|unix:/var/run/openvswitch/br-int.mgmt:
    connecting...
    2025-02-08T14:28:50.739Z|00011|ovn_util|INFO|pinctrl: connecting
    to switch: "unix:/var/run/openvswitch/br-int.mgmt"
    
2025-02-08T14:28:50.739Z|00012|rconn|INFO|unix:/var/run/openvswitch/br-int.mgmt:
    connecting...
    2025-02-08T14:28:50.739Z|00013|reconnect|INFO|tcp:10.10.9.5:6642
    <http://10.10.9.5:6642>: connected
    
2025-02-08T14:28:50.739Z|00001|rconn(ovn_statctrl2)|INFO|unix:/var/run/openvswitch/br-int.mgmt:
    connected
    
2025-02-08T14:28:50.743Z|00001|rconn(ovn_pinctrl0)|INFO|unix:/var/run/openvswitch/br-int.mgmt:
    connected 2025-02-08T14:28:50.756Z|00014|ovn_util|INFO|features:
    connecting to switch: "unix:/var/run/openvswitch/br-int.mgmt"
    
2025-02-08T14:28:50.757Z|00015|rconn|INFO|unix:/var/run/openvswitch/br-int.mgmt:
    connecting... 2025-02-08T14:28:50.757Z|00016|features|INFO|OVS
    Feature: ct_zero_snat, state: supported
    2025-02-08T14:28:50.757Z|00017|features|INFO|OVS Feature:
    ct_flush, state: supported
    2025-02-08T14:28:50.757Z|00018|features|INFO|OVS Feature:
    dp_hash_l4_sym_support, state: supported
    2025-02-08T14:28:50.757Z|00019|main|INFO|OVS feature set changed,
    force recompute.
    2025-02-08T14:28:50.757Z|00020|ovn_util|INFO|ofctrl: connecting
    to switch: "unix:/var/run/openvswitch/br-int.mgmt"
    
2025-02-08T14:28:50.757Z|00021|rconn|INFO|unix:/var/run/openvswitch/br-int.mgmt:
    connecting...
    
2025-02-08T14:28:50.758Z|00022|rconn|INFO|unix:/var/run/openvswitch/br-int.mgmt:
    connected 2025-02-08T14:28:50.758Z|00023|main|INFO|OVS OpenFlow
    connection reconnected,force recompute.
    
2025-02-08T14:28:50.759Z|00024|rconn|INFO|unix:/var/run/openvswitch/br-int.mgmt:
    connected 2025-02-08T14:28:50.760Z|00025|features|INFO|OVS
    Feature: meter_support, state: supported
    2025-02-08T14:28:50.760Z|00026|features|INFO|OVS Feature:
    group_support, state: supported
    2025-02-08T14:28:50.760Z|00027|features|INFO|OVS Feature:
    sample_action_with_registers, state: supported
    2025-02-08T14:28:50.760Z|00028|main|INFO|OVS feature set changed,
    force recompute.
    2025-02-08T14:28:51.483Z|00029|binding|INFO|Releasing lport
    978a923d-1076-484b-a1d5-ff5827ae69ec from this chassis
    (sb_readonly=0)
    2025-02-08T14:28:53.658Z|00030|poll_loop|INFO|wakeup due to
    [POLLIN] on fd 30 (10.10.9.3:60902
    <http://10.10.9.3:60902><->10.10.9.5:6642
    <http://10.10.9.5:6642>) at lib/stream-fd.c:157 (78% CPU usage)
    2025-02-08T14:28:54.726Z|00002|pinctrl(ovn_pinctrl0)|INFO|DHCPOFFER
    fa:16:3e:84:8e:7f 13.37.0.37
    2025-02-08T14:28:59.134Z|00003|pinctrl(ovn_pinctrl0)|INFO|DHCPACK
    fa:16:3e:84:8e:7f 13.37.0.37
    2025-02-08T14:29:01.499Z|00004|pinctrl(ovn_pinctrl0)|INFO|DHCPOFFER
    fa:16:3e:80:67:62 13.37.0.5
    2025-02-08T14:29:03.245Z|00005|pinctrl(ovn_pinctrl0)|INFO|DHCPACK
    fa:16:3e:84:8e:7f 13.37.0.37
    2025-02-08T14:29:03.455Z|00031|memory|INFO|98744 kB peak resident
    set size after 12.8 seconds
    2025-02-08T14:29:03.455Z|00032|memory|INFO|idl-cells-OVN_Southbound:168023
    idl-cells-Open_vSwitch:36874 lflow-cache-entries-cache-expr:6494
    lflow-cache-entries-cache-matches:1413 lflow-cache-size-KB:20726
    local_datapath_usage-KB:1 ofctrl_desired_flow_usage-KB:6342
    ofctrl_installed_flow_usage-KB:4695 ofctrl_sb_flow_ref_usage-KB:2355 |

    Any suggestions?

    Environment:
    OpenStack 2024.2
    Kernel 6.8.0-50-generic #51
    <https://github.com/ovn-org/ovn/issues/51>~22.04.1-Ubuntu SMP
    PREEMPT_DYNAMIC

    |ovs-vsctl (Open vSwitch) 3.4.0 DB Schema 8.7.0 |

    |ovs-ofctl (Open vSwitch) 3.4.0 OpenFlow versions 0x1:0x6 |

    |# ovn-nbctl --version ovn-nbctl 24.09.0 Open vSwitch Library
    3.4.0 DB Schema 7.6.0 |

    |# ovn-sbctl --version ovn-sbctl 24.09.0 Open vSwitch Library
    3.4.0 DB Schema 20.37.0|

      _______________________________________________
    discuss mailing list
    disc...@openvswitch.org
    https://mail.openvswitch.org/mailman/listinfo/ovs-discuss

_______________________________________________
discuss mailing list
disc...@openvswitch.org
https://mail.openvswitch.org/mailman/listinfo/ovs-discuss

Re: [ovs-discuss] [BUG] ovn-controller stops sending DHCPOFFER

Reply via email to