Loading...

Type: Bug
Resolution: Unresolved
Priority: Normal
Fix Version/s: None
Affects Version/s: None
Component/s: None
Labels:
- cloned

Blocked:
False
Blocked Reason:

Hide

None

Show
None
Ready:
False
Intelligence Requested:
Market:

Severity:
Moderate

SFDC Cases Links:
SFDC Cases Counter:
SFDC Cases Open:

What were you trying to do that didn't work?

After create a ovs-dpdkbond port and use 'ovs-vsctl get port' or 'ovs-appctl bond/show' to find the active_member_mac failed. the output mac didn't match any slave interfaces.

Affect version: openvswitch3.3-3.3.0-2.el9fdp openvswitch3.3-3.3.0-13.el9fdp

How reproducible: 100%

Test step:

1. create vf from test pf and add to dpdkbond port.

#!/bin/bash
set -x
systemctl restart openvswitch

lsmod | grep vfio_pci || modprobe vfio_pci
ip link set ens1f0 up
ip link set ens1f1 up
echo 1 > /sys/class/net/ens1f0/device/sriov_numvfs
echo 1 > /sys/class/net/ens1f1/device/sriov_numvfs
ip link set ens1f0 vf 0 spoofchk off
ip link set ens1f1 vf 0 spoofchk off
ip link set ens1f0 vf 0 trust on
ip link set ens1f1 vf 0 trust on
driverctl -v set-override 0000:3b:02.0 vfio-pci
driverctl -v set-override 0000:3b:0a.0 vfio-pci
ovs-vsctl set Open_vSwitch . other_config={}
ovs-vsctl --no-wait set Open_vSwitch . other_config:dpdk-socket-mem='8192,8192'
ovs-vsctl --no-wait set Open_vSwitch . other_config:dpdk-lcore-mask=0x100000000000000
ovs-vsctl --no-wait set Open_vSwitch . other_config:pmd-cpu-mask=0x1400000014000000
ovs-vsctl --no-wait set Open_vSwitch . other_config:vhost-iommu-support=true
ovs-vsctl --no-wait set Open_vSwitch . other_config:dpdk-init=true
ovs-vsctl --may-exist add-br bondbridge -- set bridge bondbridge datapath_type=netdev
ovs-vsctl set Bridge bondbridge mcast_snooping_enable=true
ovs-vsctl add-bond bondbridge active-backup ens1f0v0 ens1f1v0 lacp=off bond_mode=active-backup  -- set Interface ens1f0v0 type=dpdk options:dpdk-devargs=0000:3b:02.0 options:n_rxq=3 mtu_request=9000  -- set Interface ens1f1v0 type=dpdk options:dpdk-devargs=0000:3b:0a.0 options:n_rxq=3 mtu_request=9000  -- set Port active-backup  other_config:lacp-time=fast other_config:bond-primary=ens1f0v0
ovs-appctl bond/show 
ovs-vsctl get port active-backup bond_active_slave
ovs-vsctl get Interface ens1f0v0 mac_in_use
ovs-vsctl get Interface ens1f1v0 mac_in_use

2. check the script output and we can found active mac is 92:94:25:1b:dc:9c, but this mac didn't exist on any slave

+ lsmod
+ grep vfio_pci
vfio_pci               16384  0
vfio_pci_core          94208  1 vfio_pci
vfio                   77824  3 vfio_pci_core,vfio_iommu_type1,vfio_pci
irqbypass              16384  2 vfio_pci_core,kvm
+ ip link set ens1f0 up
+ ip link set ens1f1 up
+ echo 1
+ echo 1
+ ip link set ens1f0 vf 0 spoofchk off
+ ip link set ens1f1 vf 0 spoofchk off
+ ip link set ens1f0 vf 0 trust on
+ ip link set ens1f1 vf 0 trust on
+ driverctl -v set-override 0000:3b:02.0 vfio-pci
driverctl: setting driver override for 0000:3b:02.0: vfio-pci
driverctl: loading driver vfio-pci
driverctl: unbinding previous driver iavf
driverctl: reprobing driver for 0000:3b:02.0
driverctl: saving driver override for 0000:3b:02.0
+ driverctl -v set-override 0000:3b:0a.0 vfio-pci
driverctl: setting driver override for 0000:3b:0a.0: vfio-pci
driverctl: loading driver vfio-pci
driverctl: unbinding previous driver iavf
driverctl: reprobing driver for 0000:3b:0a.0
driverctl: saving driver override for 0000:3b:0a.0
+ ovs-vsctl set Open_vSwitch . 'other_config={}'
+ ovs-vsctl --no-wait set Open_vSwitch . other_config:dpdk-socket-mem=8192,8192
+ ovs-vsctl --no-wait set Open_vSwitch . other_config:dpdk-lcore-mask=0x100000000000000
+ ovs-vsctl --no-wait set Open_vSwitch . other_config:pmd-cpu-mask=0x1400000014000000
+ ovs-vsctl --no-wait set Open_vSwitch . other_config:vhost-iommu-support=true
+ ovs-vsctl --no-wait set Open_vSwitch . other_config:dpdk-init=true
+ ovs-vsctl --may-exist add-br bondbridge -- set bridge bondbridge datapath_type=netdev
+ ovs-vsctl set Bridge bondbridge mcast_snooping_enable=true
+ ovs-vsctl add-bond bondbridge active-backup ens1f0v0 ens1f1v0 lacp=off bond_mode=active-backup -- set Interface ens1f0v0 type=dpdk options:dpdk-devargs=0000:3b:02.0 options:n_rxq=3 mtu_request=9000 -- set Interface ens1f1v0 type=dpdk options:dpdk-devargs=0000:3b:0a.0 options:n_rxq=3 mtu_request=9000 -- set Port active-backup other_config:lacp-time=fast other_config:bond-primary=ens1f0v0
+ sleep 10
+ ovs-appctl bond/show
---- active-backup ----
bond_mode: active-backup
bond may use recirculation: no, Recirc-ID : -1
bond-hash-basis: 0
lb_output action: disabled, bond-id: -1
updelay: 0 ms
downdelay: 0 ms
lacp_status: off
lacp_fallback_ab: false
active-backup primary: ens1f0v0
active member mac: 92:94:25:1b:dc:9c(none)
member ens1f0v0: enabled
  active member
  may_enable: true
member ens1f1v0: enabled
  may_enable: true
+ ovs-vsctl get Interface ens1f0v0 mac_in_use
"f2:2a:2f:45:4b:b3"
+ ovs-vsctl get Interface ens1f1v0 mac_in_use
"a2:b1:0e:48:83:29"

3. Only workaround is restart openvswitch service. After restart openvswitch, the active mac will show as a slave interface.

 systemctl restart openvswitch
ovs-appctl bond/show
---- active-backup ----
bond_mode: active-backup
bond may use recirculation: no, Recirc-ID : -1
bond-hash-basis: 0
lb_output action: disabled, bond-id: -1
updelay: 0 ms
downdelay: 0 ms
lacp_status: off
lacp_fallback_ab: false
active-backup primary: ens1f0v0
active member mac: 2e:ee:1f:cb:e5:97(ens1f0v0)member ens1f0v0: enabled
  active member
  may_enable: truemember ens1f1v0: enabled
  may_enable: true

4. FUll of openvswitch log.

2024-05-14T03:21:46.299Z|00009|memory|INFO|247792 kB peak resident set size after 21.5 seconds
2024-05-14T03:21:46.299Z|00010|memory|INFO|idl-cells-Open_vSwitch:17
2024-05-14T03:21:46.737Z|00001|vlog|INFO|opened log file /var/log/openvswitch/ovs-vswitchd.log
2024-05-14T03:21:46.825Z|00002|ovs_numa|INFO|Discovered 32 CPU cores on NUMA node 1
2024-05-14T03:21:46.825Z|00003|ovs_numa|INFO|Discovered 32 CPU cores on NUMA node 0
2024-05-14T03:21:46.825Z|00004|ovs_numa|INFO|Discovered 2 NUMA nodes and 64 CPU cores
2024-05-14T03:21:46.825Z|00005|reconnect|INFO|unix:/var/run/openvswitch/db.sock: connecting...
2024-05-14T03:21:46.826Z|00006|reconnect|INFO|unix:/var/run/openvswitch/db.sock: connected
2024-05-14T03:21:46.827Z|00007|dpdk|INFO|DPDK Disabled - Use other_config:dpdk-init to enable
2024-05-14T03:21:46.831Z|00008|bridge|INFO|ovs-vswitchd (Open vSwitch) 3.3.1
2024-05-14T03:21:48.834Z|00009|dpdk|INFO|Using DPDK 23.11.0
2024-05-14T03:21:48.835Z|00010|dpdk|INFO|DPDK Enabled - initializing...
2024-05-14T03:21:48.835Z|00011|dpdk|INFO|EAL ARGS: ovs-vswitchd -c 0x100000000000000 --socket-mem 8192,8192 --in-memory.
2024-05-14T03:21:48.840Z|00012|dpdk|INFO|EAL: Detected CPU lcores: 64
2024-05-14T03:21:48.840Z|00013|dpdk|INFO|EAL: Detected NUMA nodes: 2
2024-05-14T03:21:48.841Z|00014|dpdk|INFO|EAL: Detected static linkage of DPDK
2024-05-14T03:21:48.869Z|00015|dpdk|INFO|EAL: rte_mem_virt2phy(): cannot open /proc/self/pagemap: Permission denied
2024-05-14T03:21:48.869Z|00016|dpdk|INFO|EAL: Selected IOVA mode 'VA'
2024-05-14T03:21:48.869Z|00017|dpdk|WARN|EAL: No free 2048 kB hugepages reported on node 0
2024-05-14T03:21:48.869Z|00018|dpdk|WARN|EAL: No free 2048 kB hugepages reported on node 1
2024-05-14T03:21:48.870Z|00019|dpdk|INFO|EAL: VFIO support initialized
2024-05-14T03:21:52.846Z|00020|dpdk|INFO|EAL: Using IOMMU type 1 (Type 1)
2024-05-14T03:21:53.134Z|00021|dpdk|INFO|EAL: Probe PCI driver: net_iavf (8086:154c) device: 0000:3b:02.0 (socket 0)
2024-05-14T03:21:53.446Z|00022|dpdk|INFO|EAL: Probe PCI driver: net_iavf (8086:154c) device: 0000:3b:0a.0 (socket 0)
2024-05-14T03:21:53.549Z|00023|dpdk|INFO|EAL: Probe PCI driver: mlx5_pci (15b3:101f) device: 0000:5e:00.0 (socket 0)
2024-05-14T03:21:53.786Z|00024|dpdk|INFO|EAL: Probe PCI driver: mlx5_pci (15b3:101f) device: 0000:5e:00.1 (socket 0)
2024-05-14T03:21:54.011Z|00025|dpdk|INFO|EAL: Probe PCI driver: mlx5_pci (15b3:1017) device: 0000:86:00.0 (socket 1)
2024-05-14T03:21:54.238Z|00026|dpdk|INFO|EAL: Probe PCI driver: mlx5_pci (15b3:1017) device: 0000:86:00.1 (socket 1)
2024-05-14T03:21:54.469Z|00027|dpdk|WARN|TELEMETRY: No legacy callbacks, legacy socket not created
2024-05-14T03:21:54.469Z|00028|netdev_dpdk|INFO|Per port memory for DPDK devices disabled.
2024-05-14T03:21:54.469Z|00029|netdev_dpdk|INFO|No vhost-sock-dir provided - defaulting to /var/run/openvswitch
2024-05-14T03:21:54.469Z|00030|netdev_dpdk|INFO|IOMMU support for vhost-user-client enabled.
2024-05-14T03:21:54.469Z|00031|netdev_dpdk|INFO|POSTCOPY support for vhost-user-client disabled.
2024-05-14T03:21:54.471Z|00032|dpdk|INFO|DPDK Enabled - initialized
2024-05-14T03:21:54.471Z|00033|timeval|WARN|Unreasonably long 5637ms poll interval (17ms user, 4040ms system)
2024-05-14T03:21:54.471Z|00034|timeval|WARN|faults: 21726 minor, 0 major
2024-05-14T03:21:54.471Z|00035|timeval|WARN|context switches: 3193 voluntary, 269 involuntary
2024-05-14T03:21:54.471Z|00036|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour,  hash=013f7a8d:
2024-05-14T03:21:54.471Z|00037|coverage|INFO|nln_changed                1.2/sec     0.100/sec        0.0017/sec   total: 6
2024-05-14T03:21:54.471Z|00038|coverage|INFO|netlink_sent              84.2/sec     7.017/sec        0.1169/sec   total: 421
2024-05-14T03:21:54.471Z|00039|coverage|INFO|netlink_recv_jumbo         9.8/sec     0.817/sec        0.0136/sec   total: 49
2024-05-14T03:21:54.471Z|00040|coverage|INFO|netlink_received          89.4/sec     7.450/sec        0.1242/sec   total: 447
2024-05-14T03:21:54.471Z|00041|coverage|INFO|util_xalloc              2727.2/sec   227.267/sec        3.7878/sec   total: 13636
2024-05-14T03:21:54.471Z|00042|coverage|INFO|stream_open                0.2/sec     0.017/sec        0.0003/sec   total: 1
2024-05-14T03:21:54.471Z|00043|coverage|INFO|pstream_open               0.2/sec     0.017/sec        0.0003/sec   total: 1
2024-05-14T03:21:54.471Z|00044|coverage|INFO|seq_change               121.6/sec    10.133/sec        0.1689/sec   total: 608
2024-05-14T03:21:54.471Z|00045|coverage|INFO|poll_create_node          89.2/sec     7.433/sec        0.1239/sec   total: 446
2024-05-14T03:21:54.471Z|00046|coverage|INFO|txn_incomplete             0.4/sec     0.033/sec        0.0006/sec   total: 2
2024-05-14T03:21:54.471Z|00047|coverage|INFO|txn_unchanged              4.8/sec     0.400/sec        0.0067/sec   total: 24
2024-05-14T03:21:54.471Z|00048|coverage|INFO|hmap_expand              139.8/sec    11.650/sec        0.1942/sec   total: 699
2024-05-14T03:21:54.471Z|00049|coverage|INFO|hmap_pathological          1.2/sec     0.100/sec        0.0017/sec   total: 6
2024-05-14T03:21:54.471Z|00050|coverage|INFO|miniflow_malloc           32.2/sec     2.683/sec        0.0447/sec   total: 161
2024-05-14T03:21:54.471Z|00051|coverage|INFO|cmap_shrink                8.4/sec     0.700/sec        0.0117/sec   total: 42
2024-05-14T03:21:54.471Z|00052|coverage|INFO|cmap_expand               10.6/sec     0.883/sec        0.0147/sec   total: 53
2024-05-14T03:21:54.471Z|00053|coverage|INFO|bridge_reconfigure         2.4/sec     0.200/sec        0.0033/sec   total: 12
2024-05-14T03:21:54.471Z|00054|coverage|INFO|147 events never hit
2024-05-14T03:21:54.472Z|00055|poll_loop|INFO|wakeup due to [POLLIN] on fd 15 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (53% CPU usage)
2024-05-14T03:21:54.472Z|00056|pmd_perf|INFO|DPDK provided TSC frequency: 2890000 KHz
2024-05-14T03:21:54.474Z|00057|dpif_netdev_extract|INFO|Default MFEX Extract implementation is scalar.
2024-05-14T03:21:54.477Z|00058|dpif_netdev_impl|INFO|Default DPIF implementation is dpif_scalar.
2024-05-14T03:21:54.481Z|00059|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports recirculation
2024-05-14T03:21:54.481Z|00060|ofproto_dpif|INFO|netdev@ovs-netdev: VLAN header stack length probed as 1
2024-05-14T03:21:54.481Z|00061|ofproto_dpif|INFO|netdev@ovs-netdev: MPLS label stack length probed as 3
2024-05-14T03:21:54.481Z|00062|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports truncate action
2024-05-14T03:21:54.481Z|00063|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports unique flow ids
2024-05-14T03:21:54.481Z|00064|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports clone action
2024-05-14T03:21:54.481Z|00065|ofproto_dpif|INFO|netdev@ovs-netdev: Max sample nesting level probed as 10
2024-05-14T03:21:54.481Z|00066|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports eventmask in conntrack action
2024-05-14T03:21:54.481Z|00067|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_clear action
2024-05-14T03:21:54.481Z|00068|ofproto_dpif|INFO|netdev@ovs-netdev: Max dp_hash algorithm probed to be 1
2024-05-14T03:21:54.481Z|00069|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports check_pkt_len action
2024-05-14T03:21:54.481Z|00070|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports timeout policy in conntrack action
2024-05-14T03:21:54.481Z|00071|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_zero_snat
2024-05-14T03:21:54.481Z|00072|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports add_mpls action
2024-05-14T03:21:54.481Z|00073|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_state
2024-05-14T03:21:54.481Z|00074|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_zone
2024-05-14T03:21:54.481Z|00075|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_mark
2024-05-14T03:21:54.481Z|00076|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_label
2024-05-14T03:21:54.481Z|00077|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_state_nat
2024-05-14T03:21:54.481Z|00078|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_orig_tuple
2024-05-14T03:21:54.481Z|00079|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports ct_orig_tuple6
2024-05-14T03:21:54.481Z|00080|ofproto_dpif|INFO|netdev@ovs-netdev: Datapath supports IPv6 ND Extensions
2024-05-14T03:21:54.481Z|00081|ofproto_dpif_upcall|INFO|Setting n-handler-threads to 1, setting n-revalidator-threads to 1
2024-05-14T03:21:54.481Z|00082|ofproto_dpif_upcall|INFO|Starting 2 threads
2024-05-14T03:21:54.484Z|00083|dpif_netdev|INFO|pmd-rxq-affinity isolates PMD core
2024-05-14T03:21:54.484Z|00084|dpif_netdev|INFO|PMD auto load balance interval set to 1 mins
2024-05-14T03:21:54.484Z|00085|dpif_netdev|INFO|PMD auto load balance improvement threshold set to 25%
2024-05-14T03:21:54.484Z|00086|dpif_netdev|INFO|PMD auto load balance load threshold set to 95%
2024-05-14T03:21:54.484Z|00087|dpif_netdev|INFO|PMD auto load balance is disabled.
2024-05-14T03:21:54.484Z|00088|dpif_netdev|INFO|Default PMD thread max sleep:    0 us.
2024-05-14T03:21:54.487Z|00089|bridge|INFO|bridge bondbridge: added interface bondbridge on port 65534
2024-05-14T03:21:54.487Z|00090|bridge|INFO|bridge bondbridge: using datapath ID 0000de031ccbb741
2024-05-14T03:21:54.487Z|00091|connmgr|INFO|bondbridge: added service controller "punix:/var/run/openvswitch/bondbridge.mgmt"
2024-05-14T03:21:54.489Z|00092|poll_loop|INFO|wakeup due to [POLLIN] on fd 14 (NETLINK_ROUTE<->NETLINK_ROUTE) at ../lib/netlink-socket.c:1409 (53% CPU usage)
2024-05-14T03:21:54.489Z|00093|poll_loop|INFO|wakeup due to [POLLIN] on fd 15 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (53% CPU usage)
2024-05-14T03:21:54.490Z|00094|poll_loop|INFO|wakeup due to [POLLIN] on fd 15 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (53% CPU usage)
2024-05-14T03:21:54.490Z|00095|poll_loop|INFO|wakeup due to 0-ms timeout at ../vswitchd/bridge.c:3266 (53% CPU usage)
2024-05-14T03:21:54.490Z|00096|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (FIFO pipe:[12905422]) at ../vswitchd/bridge.c:424 (53% CPU usage)
2024-05-14T03:21:54.495Z|00097|poll_loop|INFO|wakeup due to [POLLIN] on fd 15 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (53% CPU usage)
2024-05-14T03:21:54.495Z|00098|poll_loop|INFO|wakeup due to [POLLIN] on fd 15 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (53% CPU usage)
2024-05-14T03:21:54.495Z|00099|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (FIFO pipe:[12905422]) at ../vswitchd/bridge.c:424 (53% CPU usage)
2024-05-14T03:21:54.505Z|00100|poll_loop|INFO|wakeup due to [POLLIN] on fd 15 (<->/var/run/openvswitch/db.sock) at ../lib/stream-fd.c:157 (53% CPU usage)
2024-05-14T03:21:54.508Z|00101|dpif_netdev|INFO|PMD thread on numa_id: 0, core id: 60, max sleep:    0 us.
2024-05-14T03:21:54.509Z|00102|dpif_netdev|INFO|PMD thread on numa_id: 0, core id: 60 created.
2024-05-14T03:21:54.512Z|00103|dpif_netdev|INFO|PMD thread on numa_id: 0, core id: 58, max sleep:    0 us.
2024-05-14T03:21:54.513Z|00104|dpif_netdev|INFO|PMD thread on numa_id: 0, core id: 58 created.
2024-05-14T03:21:54.517Z|00105|dpif_netdev|INFO|PMD thread on numa_id: 0, core id: 26, max sleep:    0 us.
2024-05-14T03:21:54.517Z|00106|dpif_netdev|INFO|PMD thread on numa_id: 0, core id: 26 created.
2024-05-14T03:21:54.521Z|00107|dpif_netdev|INFO|PMD thread on numa_id: 0, core id: 28, max sleep:    0 us.
2024-05-14T03:21:54.522Z|00108|dpif_netdev|INFO|PMD thread on numa_id: 0, core id: 28 created.
2024-05-14T03:21:54.522Z|00109|dpif_netdev|INFO|There are 4 pmd threads on numa node 0
2024-05-14T03:21:54.522Z|00110|dpdk|INFO|Device with port_id=0 already stopped
2024-05-14T03:21:54.522Z|00001|dpdk(pmd-c58/id:8)|INFO|PMD thread uses DPDK lcore 0.
2024-05-14T03:21:54.529Z|00001|dpdk(pmd-c60/id:9)|INFO|PMD thread uses DPDK lcore 1.
2024-05-14T03:21:54.529Z|00001|dpdk(pmd-c26/id:10)|INFO|PMD thread uses DPDK lcore 2.
2024-05-14T03:21:54.529Z|00001|dpdk(pmd-c28/id:11)|INFO|PMD thread uses DPDK lcore 3.
2024-05-14T03:21:54.597Z|00111|netdev_dpdk|INFO|Virtual function detected, HW_CRC_STRIP will be enabled
2024-05-14T03:21:55.032Z|00112|dpdk|INFO|iavf_set_rx_function(): request RXDID[1] in Queue[0] is legacy, set rx_pkt_burst as legacy for all queues
2024-05-14T03:21:55.032Z|00113|dpdk|INFO|iavf_set_rx_function(): request RXDID[1] in Queue[1] is legacy, set rx_pkt_burst as legacy for all queues
2024-05-14T03:21:55.033Z|00114|dpdk|INFO|iavf_set_rx_function(): request RXDID[1] in Queue[2] is legacy, set rx_pkt_burst as legacy for all queues
2024-05-14T03:21:55.883Z|00115|netdev_dpdk|INFO|Port 0: 9e:3b:81:ab:3a:9e
2024-05-14T03:21:55.883Z|00116|netdev_dpdk|INFO|ens1f0v0: rx-steering: default rss
2024-05-14T03:21:55.883Z|00117|dpif_netdev|INFO|Performing pmd to rx queue assignment using cycles algorithm.
2024-05-14T03:21:55.883Z|00118|dpif_netdev|INFO|Core 26 on numa node 0 assigned port 'ens1f0v0' rx queue 0 (measured processing cycles 0).
2024-05-14T03:21:55.883Z|00119|dpif_netdev|INFO|Core 28 on numa node 0 assigned port 'ens1f0v0' rx queue 1 (measured processing cycles 0).
2024-05-14T03:21:55.883Z|00120|dpif_netdev|INFO|Core 58 on numa node 0 assigned port 'ens1f0v0' rx queue 2 (measured processing cycles 0).
2024-05-14T03:21:55.883Z|00121|bridge|INFO|bridge bondbridge: added interface ens1f0v0 on port 1
2024-05-14T03:21:56.083Z|00122|dpdk|INFO|Device with port_id=1 already stopped
2024-05-14T03:21:56.083Z|00123|netdev_dpdk|INFO|Virtual function detected, HW_CRC_STRIP will be enabled
2024-05-14T03:21:56.519Z|00124|dpdk|INFO|iavf_set_rx_function(): request RXDID[1] in Queue[0] is legacy, set rx_pkt_burst as legacy for all queues
2024-05-14T03:21:56.519Z|00125|dpdk|INFO|iavf_set_rx_function(): request RXDID[1] in Queue[1] is legacy, set rx_pkt_burst as legacy for all queues
2024-05-14T03:21:56.519Z|00126|dpdk|INFO|iavf_set_rx_function(): request RXDID[1] in Queue[2] is legacy, set rx_pkt_burst as legacy for all queues
2024-05-14T03:21:57.369Z|00127|netdev_dpdk|INFO|Port 1: a6:ac:29:24:2f:03
2024-05-14T03:21:57.369Z|00128|netdev_dpdk|INFO|ens1f1v0: rx-steering: default rss
2024-05-14T03:21:57.369Z|00129|dpif_netdev|INFO|Performing pmd to rx queue assignment using cycles algorithm.
2024-05-14T03:21:57.369Z|00130|dpif_netdev|INFO|Core 26 on numa node 0 assigned port 'ens1f0v0' rx queue 0 (measured processing cycles 0).
2024-05-14T03:21:57.369Z|00131|dpif_netdev|INFO|Core 28 on numa node 0 assigned port 'ens1f0v0' rx queue 1 (measured processing cycles 0).
2024-05-14T03:21:57.369Z|00132|dpif_netdev|INFO|Core 58 on numa node 0 assigned port 'ens1f0v0' rx queue 2 (measured processing cycles 0).
2024-05-14T03:21:57.369Z|00133|dpif_netdev|INFO|Core 60 on numa node 0 assigned port 'ens1f1v0' rx queue 0 (measured processing cycles 0).
2024-05-14T03:21:57.369Z|00134|dpif_netdev|INFO|Core 60 on numa node 0 assigned port 'ens1f1v0' rx queue 1 (measured processing cycles 0).
2024-05-14T03:21:57.369Z|00135|dpif_netdev|INFO|Core 58 on numa node 0 assigned port 'ens1f1v0' rx queue 2 (measured processing cycles 0).
2024-05-14T03:21:57.369Z|00136|bridge|INFO|bridge bondbridge: added interface ens1f1v0 on port 2
2024-05-14T03:21:57.570Z|00137|bond|INFO|member ens1f0v0: enabled
2024-05-14T03:21:57.570Z|00138|bond|INFO|member ens1f1v0: enabled
2024-05-14T03:21:57.570Z|00139|timeval|WARN|Unreasonably long 3065ms poll interval (198ms user, 19ms system)
2024-05-14T03:21:57.570Z|00140|timeval|WARN|faults: 11044 minor, 0 major
2024-05-14T03:21:57.570Z|00141|timeval|WARN|context switches: 2704 voluntary, 95 involuntary
2024-05-14T03:21:57.570Z|00142|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour,  hash=46989ce7:
2024-05-14T03:21:57.570Z|00143|coverage|INFO|nln_changed                1.2/sec     0.100/sec        0.0017/sec   total: 13
2024-05-14T03:21:57.570Z|00144|coverage|INFO|netlink_sent              84.2/sec     7.017/sec        0.1169/sec   total: 557
2024-05-14T03:21:57.570Z|00145|coverage|INFO|netlink_recv_jumbo         9.8/sec     0.817/sec        0.0136/sec   total: 79
2024-05-14T03:21:57.570Z|00146|coverage|INFO|netlink_received          89.4/sec     7.450/sec        0.1242/sec   total: 600
2024-05-14T03:21:57.570Z|00147|coverage|INFO|netdev_get_ethtool         0.0/sec     0.000/sec        0.0000/sec   total: 3
2024-05-14T03:21:57.570Z|00148|coverage|INFO|netdev_set_hwaddr          0.0/sec     0.000/sec        0.0000/sec   total: 1
2024-05-14T03:21:57.570Z|00149|coverage|INFO|netdev_set_policing        0.0/sec     0.000/sec        0.0000/sec   total: 2
2024-05-14T03:21:57.570Z|00150|coverage|INFO|util_xalloc              2727.2/sec   227.267/sec        3.7878/sec   total: 19967
2024-05-14T03:21:57.570Z|00151|coverage|INFO|long_poll_interval         0.0/sec     0.000/sec        0.0000/sec   total: 1
2024-05-14T03:21:57.570Z|00152|coverage|INFO|stream_open                0.2/sec     0.017/sec        0.0003/sec   total: 1
2024-05-14T03:21:57.570Z|00153|coverage|INFO|pstream_open               0.2/sec     0.017/sec        0.0003/sec   total: 3
2024-05-14T03:21:57.570Z|00154|coverage|INFO|seq_change               121.6/sec    10.133/sec        0.1689/sec   total: 34828
2024-05-14T03:21:57.570Z|00155|coverage|INFO|poll_zero_timeout          0.0/sec     0.000/sec        0.0000/sec   total: 3
2024-05-14T03:21:57.570Z|00156|coverage|INFO|poll_create_node          89.2/sec     7.433/sec        0.1239/sec   total: 780
2024-05-14T03:21:57.570Z|00157|coverage|INFO|txn_success                0.0/sec     0.000/sec        0.0000/sec   total: 2
2024-05-14T03:21:57.570Z|00158|coverage|INFO|txn_incomplete             0.4/sec     0.033/sec        0.0006/sec   total: 5
2024-05-14T03:21:57.570Z|00159|coverage|INFO|txn_unchanged              4.8/sec     0.400/sec        0.0067/sec   total: 27
2024-05-14T03:21:57.570Z|00160|coverage|INFO|netdev_get_stats           0.0/sec     0.000/sec        0.0000/sec   total: 3
2024-05-14T03:21:57.570Z|00161|coverage|INFO|hmap_shrink                0.0/sec     0.000/sec        0.0000/sec   total: 2
2024-05-14T03:21:57.570Z|00162|coverage|INFO|hmap_expand              139.8/sec    11.650/sec        0.1942/sec   total: 926
2024-05-14T03:21:57.570Z|00163|coverage|INFO|hmap_pathological          1.2/sec     0.100/sec        0.0017/sec   total: 6
2024-05-14T03:21:57.570Z|00164|coverage|INFO|miniflow_malloc           32.2/sec     2.683/sec        0.0447/sec   total: 219
2024-05-14T03:21:57.570Z|00165|coverage|INFO|flow_extract               0.0/sec     0.000/sec        0.0000/sec   total: 4
2024-05-14T03:21:57.570Z|00166|coverage|INFO|dpif_port_add              0.0/sec     0.000/sec        0.0000/sec   total: 3
2024-05-14T03:21:57.570Z|00167|coverage|INFO|dpif_flow_put_error        0.0/sec     0.000/sec        0.0000/sec   total: 1
2024-05-14T03:21:57.570Z|00168|coverage|INFO|dpif_flow_put              0.0/sec     0.000/sec        0.0000/sec   total: 25
2024-05-14T03:21:57.570Z|00169|coverage|INFO|dpif_flow_get              0.0/sec     0.000/sec        0.0000/sec   total: 24
2024-05-14T03:21:57.570Z|00170|coverage|INFO|dpif_flow_flush            0.0/sec     0.000/sec        0.0000/sec   total: 1
2024-05-14T03:21:57.570Z|00171|coverage|INFO|dpif_flow_del              0.0/sec     0.000/sec        0.0000/sec   total: 24
2024-05-14T03:21:57.570Z|00172|coverage|INFO|dpif_execute               0.0/sec     0.000/sec        0.0000/sec   total: 6
2024-05-14T03:21:57.570Z|00173|coverage|INFO|cmap_shrink                8.4/sec     0.700/sec        0.0117/sec   total: 82
2024-05-14T03:21:57.570Z|00174|coverage|INFO|cmap_expand               10.6/sec     0.883/sec        0.0147/sec   total: 102
2024-05-14T03:21:57.570Z|00175|coverage|INFO|ccmap_shrink               0.0/sec     0.000/sec        0.0000/sec   total: 24
2024-05-14T03:21:57.570Z|00176|coverage|INFO|rev_flow_table             0.0/sec     0.000/sec        0.0000/sec   total: 1
2024-05-14T03:21:57.571Z|00177|coverage|INFO|rev_reconfigure            0.0/sec     0.000/sec        0.0000/sec   total: 4
2024-05-14T03:21:57.571Z|00178|coverage|INFO|ofproto_update_port        0.0/sec     0.000/sec        0.0000/sec   total: 4
2024-05-14T03:21:57.571Z|00179|coverage|INFO|ofproto_flush              0.0/sec     0.000/sec        0.0000/sec   total: 1
2024-05-14T03:21:57.571Z|00180|coverage|INFO|bridge_reconfigure         2.4/sec     0.200/sec        0.0033/sec   total: 16
2024-05-14T03:21:57.571Z|00181|coverage|INFO|126 events never hit
2024-05-14T03:21:57.571Z|00182|bond|INFO|bond active-backup: active member is now ens1f0v0
2024-05-14T03:21:57.572Z|00183|memory|INFO|397428 kB peak resident set size after 10.8 seconds
2024-05-14T03:21:57.572Z|00184|memory|INFO|handlers:1 idl-cells-Open_vSwitch:188 idl-outstanding-txns-Open_vSwitch:1 ports:3 revalidators:1 rules:5
2024-05-14T03:21:57.687Z|00185|netdev_dpdk|INFO|Virtual function detected, HW_CRC_STRIP will be enabled
2024-05-14T03:21:57.937Z|00186|dpdk|INFO|iavf_set_rx_function(): request RXDID[1] in Queue[0] is legacy, set rx_pkt_burst as legacy for all queues
2024-05-14T03:21:57.937Z|00187|dpdk|INFO|iavf_set_rx_function(): request RXDID[1] in Queue[1] is legacy, set rx_pkt_burst as legacy for all queues
2024-05-14T03:21:57.937Z|00188|dpdk|INFO|iavf_set_rx_function(): request RXDID[1] in Queue[2] is legacy, set rx_pkt_burst as legacy for all queues
2024-05-14T03:21:58.572Z|00001|ovs_rcu(urcu3)|WARN|blocked 1000 ms waiting for main to quiesce
2024-05-14T03:21:58.687Z|00189|netdev_dpdk|INFO|Port 0: ae:f6:88:77:02:4e
2024-05-14T03:21:58.687Z|00190|netdev_dpdk|INFO|ens1f0v0: rx-steering: default rss
2024-05-14T03:21:58.823Z|00191|netdev_dpdk|INFO|Virtual function detected, HW_CRC_STRIP will be enabled
2024-05-14T03:21:59.074Z|00192|dpdk|INFO|iavf_set_rx_function(): request RXDID[1] in Queue[0] is legacy, set rx_pkt_burst as legacy for all queues
2024-05-14T03:21:59.074Z|00193|dpdk|INFO|iavf_set_rx_function(): request RXDID[1] in Queue[1] is legacy, set rx_pkt_burst as legacy for all queues
2024-05-14T03:21:59.074Z|00194|dpdk|INFO|iavf_set_rx_function(): request RXDID[1] in Queue[2] is legacy, set rx_pkt_burst as legacy for all queues
2024-05-14T03:21:59.572Z|00002|ovs_rcu(urcu3)|WARN|blocked 2000 ms waiting for main to quiesce
2024-05-14T03:21:59.824Z|00195|netdev_dpdk|INFO|Port 1: 6a:84:80:40:75:64
2024-05-14T03:21:59.824Z|00196|netdev_dpdk|INFO|ens1f1v0: rx-steering: default rss
2024-05-14T03:21:59.824Z|00197|dpif_netdev|INFO|Performing pmd to rx queue assignment using cycles algorithm.
2024-05-14T03:21:59.824Z|00198|dpif_netdev|INFO|Core 26 on numa node 0 assigned port 'ens1f0v0' rx queue 0 (measured processing cycles 0).
2024-05-14T03:21:59.824Z|00199|dpif_netdev|INFO|Core 28 on numa node 0 assigned port 'ens1f0v0' rx queue 1 (measured processing cycles 0).
2024-05-14T03:21:59.824Z|00200|dpif_netdev|INFO|Core 58 on numa node 0 assigned port 'ens1f0v0' rx queue 2 (measured processing cycles 0).
2024-05-14T03:21:59.824Z|00201|dpif_netdev|INFO|Core 60 on numa node 0 assigned port 'ens1f1v0' rx queue 0 (measured processing cycles 0).
2024-05-14T03:21:59.824Z|00202|dpif_netdev|INFO|Core 60 on numa node 0 assigned port 'ens1f1v0' rx queue 1 (measured processing cycles 0).
2024-05-14T03:21:59.824Z|00203|dpif_netdev|INFO|Core 58 on numa node 0 assigned port 'ens1f1v0' rx queue 2 (measured processing cycles 0).
2024-05-14T03:21:59.824Z|00204|timeval|WARN|Unreasonably long 2252ms poll interval (4ms user, 2ms system)
2024-05-14T03:21:59.824Z|00205|timeval|WARN|context switches: 2135 voluntary, 53 involuntary
2024-05-14T03:21:59.824Z|00206|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour,  hash=bf6f8b12:
2024-05-14T03:21:59.824Z|00207|coverage|INFO|nln_changed                1.4/sec     0.217/sec        0.0036/sec   total: 14
2024-05-14T03:21:59.824Z|00208|coverage|INFO|netlink_sent              27.2/sec     9.283/sec        0.1547/sec   total: 618
2024-05-14T03:21:59.824Z|00209|coverage|INFO|netlink_recv_jumbo         6.0/sec     1.317/sec        0.0219/sec   total: 89
2024-05-14T03:21:59.824Z|00210|coverage|INFO|netlink_received          30.6/sec    10.000/sec        0.1667/sec   total: 665
2024-05-14T03:21:59.824Z|00211|coverage|INFO|netdev_get_ethtool         0.6/sec     0.050/sec        0.0008/sec   total: 3
2024-05-14T03:21:59.824Z|00212|coverage|INFO|netdev_set_hwaddr          0.2/sec     0.017/sec        0.0003/sec   total: 1
2024-05-14T03:21:59.824Z|00213|coverage|INFO|netdev_set_policing        0.4/sec     0.033/sec        0.0006/sec   total: 2
2024-05-14T03:21:59.824Z|00214|coverage|INFO|util_xalloc              1312.6/sec   336.650/sec        5.6108/sec   total: 24128
2024-05-14T03:21:59.824Z|00215|coverage|INFO|long_poll_interval         0.2/sec     0.017/sec        0.0003/sec   total: 2
2024-05-14T03:21:59.824Z|00216|coverage|INFO|stream_open                0.0/sec     0.017/sec        0.0003/sec   total: 1
2024-05-14T03:21:59.824Z|00217|coverage|INFO|pstream_open               0.4/sec     0.050/sec        0.0008/sec   total: 3
2024-05-14T03:21:59.824Z|00218|coverage|INFO|seq_change               7157.8/sec   606.617/sec       10.1103/sec   total: 58147
2024-05-14T03:21:59.824Z|00219|coverage|INFO|poll_zero_timeout          0.6/sec     0.050/sec        0.0008/sec   total: 4
2024-05-14T03:21:59.824Z|00220|coverage|INFO|poll_create_node          87.2/sec    14.700/sec        0.2450/sec   total: 972
2024-05-14T03:21:59.824Z|00221|coverage|INFO|txn_success                0.4/sec     0.033/sec        0.0006/sec   total: 2
2024-05-14T03:21:59.824Z|00222|coverage|INFO|txn_incomplete             0.6/sec     0.083/sec        0.0014/sec   total: 7
2024-05-14T03:21:59.824Z|00223|coverage|INFO|txn_unchanged              0.6/sec     0.450/sec        0.0075/sec   total: 27
2024-05-14T03:21:59.824Z|00224|coverage|INFO|netdev_get_stats           0.6/sec     0.050/sec        0.0008/sec   total: 3
2024-05-14T03:21:59.824Z|00225|coverage|INFO|hmap_shrink                0.4/sec     0.033/sec        0.0006/sec   total: 15
2024-05-14T03:21:59.824Z|00226|coverage|INFO|hmap_expand               45.6/sec    15.450/sec        0.2575/sec   total: 1025
2024-05-14T03:21:59.824Z|00227|coverage|INFO|hmap_pathological          0.0/sec     0.100/sec        0.0017/sec   total: 6
2024-05-14T03:21:59.824Z|00228|coverage|INFO|miniflow_malloc           11.6/sec     3.650/sec        0.0608/sec   total: 242
2024-05-14T03:21:59.824Z|00229|coverage|INFO|flow_extract               0.8/sec     0.067/sec        0.0011/sec   total: 4
2024-05-14T03:21:59.824Z|00230|coverage|INFO|dpif_port_add              0.6/sec     0.050/sec        0.0008/sec   total: 3
2024-05-14T03:21:59.824Z|00231|coverage|INFO|dpif_flow_put_error        0.2/sec     0.017/sec        0.0003/sec   total: 1
2024-05-14T03:21:59.824Z|00232|coverage|INFO|dpif_flow_put              5.0/sec     0.417/sec        0.0069/sec   total: 25
2024-05-14T03:21:59.824Z|00233|coverage|INFO|dpif_flow_get              4.8/sec     0.400/sec        0.0067/sec   total: 24
2024-05-14T03:21:59.824Z|00234|coverage|INFO|dpif_flow_flush            0.2/sec     0.017/sec        0.0003/sec   total: 1
2024-05-14T03:21:59.824Z|00235|coverage|INFO|dpif_flow_del              4.8/sec     0.400/sec        0.0067/sec   total: 24
2024-05-14T03:21:59.824Z|00236|coverage|INFO|dpif_execute               1.2/sec     0.100/sec        0.0017/sec   total: 6
2024-05-14T03:21:59.824Z|00237|coverage|INFO|cmap_shrink                8.0/sec     1.367/sec        0.0228/sec   total: 89
2024-05-14T03:21:59.824Z|00238|coverage|INFO|cmap_expand                9.8/sec     1.700/sec        0.0283/sec   total: 109
2024-05-14T03:21:59.824Z|00239|coverage|INFO|ccmap_shrink               4.8/sec     0.400/sec        0.0067/sec   total: 24
2024-05-14T03:21:59.824Z|00240|coverage|INFO|rev_flow_table             0.2/sec     0.017/sec        0.0003/sec   total: 1
2024-05-14T03:21:59.824Z|00241|coverage|INFO|rev_reconfigure            0.8/sec     0.067/sec        0.0011/sec   total: 5
2024-05-14T03:21:59.824Z|00242|coverage|INFO|ofproto_update_port        0.8/sec     0.067/sec        0.0011/sec   total: 4
2024-05-14T03:21:59.824Z|00243|coverage|INFO|ofproto_flush              0.2/sec     0.017/sec        0.0003/sec   total: 1
2024-05-14T03:21:59.824Z|00244|coverage|INFO|bridge_reconfigure         0.8/sec     0.267/sec        0.0044/sec   total: 16
2024-05-14T03:21:59.824Z|00245|coverage|INFO|126 events never hit

Details

Description

What were you trying to do that didn't work?

How reproducible: 100%

Attachments

Activity

People

Dates