2202999 – Random failure on configuring vlan device on netdev used by OVNKubernetes

Bug 2202999 - Random failure on configuring vlan device on netdev used by OVNKubernetes

Summary: Random failure on configuring vlan device on netdev used by OVNKubernetes

Keywords:
Status:	VERIFIED
Alias:	None
Product:	Red Hat Enterprise Linux 9
Classification:	Red Hat
Component:	nmstate
Sub Component:
Version:	9.2
Hardware:	x86_64
OS:	Linux
Priority:	unspecified
Severity:	medium
Target Milestone:	rc
Target Release:	---
Assignee:	Gris Ge
QA Contact:	Mingyu Shi
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	2209894
TreeView+	depends on / blocked

Reported:	2023-05-11 02:52 UTC by Germano Veit Michel
Modified:	2023-07-18 07:34 UTC (History)
CC List:	11 users (show)
Fixed In Version:	nmstate-2.2.12-1.el9
Doc Type:	No Doc Update
Doc Text:
Clone Of:
Clones:	2209894 (view as bug list)
Environment:
Last Closed:
Type:	Bug
Target Upstream Version:
Embargoed:
Dependent Products:

Attachments	(Terms of Use)
logs_with_sucess_after_nm_restart.txt (3.04 MB, text/plain) 2023-05-15 22:02 UTC, Germano Veit Michel	no flags	Details
View All

Links
System	ID	Priority	Status	Summary	Last Updated
Github	nmstate nmstate pull 2355	None	open	nm: Use activated connection when referring parent or controller	2023-05-23 08:41:57 UTC
Red Hat Issue Tracker	NMT-536	None	None	None	2023-05-11 02:52:59 UTC
Red Hat Issue Tracker	RHELPLAN-156921	None	None	None	2023-05-11 02:53:02 UTC
Red Hat Knowledge Base (Solution)	7013254	None	None	None	2023-05-15 23:10:40 UTC

Description Germano Veit Michel 2023-05-11 02:52:40 UTC

Description of problem:

Nodes randomly fail to configure this:

  desiredState:
    interfaces:
    - ipv4:
        enabled: false
      ipv6:
        enabled: false
      name: enp4s0.2
      state: up
      type: vlan
      vlan:
        base-iface: enp4s0
        id: 2
    - bridge:
        options:
          stp:
            enabled: false
        port:
        - name: enp4s0.2
          vlan:
            mode: trunk
            trunk-tags:
            - id-range:
                max: 4094
                min: 2
      description: bridge for vlan 2
      ipv4:
        enabled: false
      ipv6:
        enabled: false
      name: virt.toca
      state: up
      type: linux-bridge

With this error:

      INFO  nmstate::nm::query_apply::profile] Will retry activation 32 seconds\n[2023-05-11T01:29:22Z
      INFO  nmstate::nm::query_apply::profile] Reapplying connection 1aa8c24f-3334-4304-889e-2eee566cffb5:
      enp4s0.2/vlan\n[2023-05-11T01:29:22Z INFO  nmstate::query_apply::net_state]
      Rollbacked to checkpoint /org/freedesktop/NetworkManager/Checkpoint/4\nNmstateError:
      Bug: Manager(UnknownDevice): Failed to find a compatible device for this connection\n'"

On a system with this initial configuration:

[core@orange ~]$ nmcli c
NAME                UUID                                  TYPE           DEVICE 
ovs-if-br-ex        86d38e72-4b20-4866-badc-483d9687f791  ovs-interface  br-ex  
lo                  a43e6283-3efd-4f5a-b74d-d05b461007db  loopback       lo     
br-ex               e9c95b51-2be8-454c-979c-d583a7b0e250  ovs-bridge     br-ex  
ovs-if-phys0        28b2515f-a13d-4dd7-a545-daaf7f8049af  ethernet       enp4s0 
ovs-port-br-ex      194ba912-8332-4874-928f-e83e3982c687  ovs-port       br-ex  
ovs-port-phys0      e32c6654-4537-4d57-a658-b8e11d4f829d  ovs-port       enp4s0 

It seems to be unable to find enp4s0 (ethernet) to activate the connection.

Perhaps its trying to use enp4s (ovs-port)?

Rebooting and reprovisioning the node sometimes fixes it. 

Version-Release number of selected component (if applicable):
OpenShift 4.13-rc7
NMState operator 4.13.0-202304280215

NetworkManager-libnm-1.42.2-1.el9.x86_64
containernetworking-plugins-1.2.0-1.el9.x86_64
NetworkManager-1.42.2-1.el9.x86_64
NetworkManager-team-1.42.2-1.el9.x86_64
NetworkManager-tui-1.42.2-1.el9.x86_64
NetworkManager-cloud-setup-1.42.2-1.el9.x86_64
NetworkManager-ovs-1.42.2-1.el9.x86_64

I had no issues with this on RHEL 8.6 based OCP 4.12.

How reproducible:
20-30%

Steps to Reproduce:
1. Use a NNCP to create a vlan interface on the device used by OVNKubernetes 

apiVersion: nmstate.io/v1
kind: NodeNetworkConfigurationPolicy
metadata:
  name: virt-toca-orange
spec:
  desiredState:
    interfaces:
    - ipv4:
        enabled: false
      ipv6:
        enabled: false
      name: enp4s0.2
      state: up
      type: vlan
      vlan:
        base-iface: enp4s0
        id: 2
    - bridge:
        options:
          stp:
            enabled: false
        port:
        - name: enp4s0.2
      description: bridge for vlan 2
      ipv4:
        enabled: false
      ipv6:
        enabled: false
      name: virt.toca
      state: up
      type: linux-bridge
  nodeSelector:
    kubernetes.io/hostname: orange.toca.local


Actual results:
* Some nodes will fail, some will succeed, randomly. 

Expected results:
* All succeed, its the same configuration on all of them

Comment 1 Germano Veit Michel 2023-05-11 02:57:19 UTC

May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.6797] audit: op="checkpoint-create" arg="/org/freedesktop/NetworkManager/Checkpoint/4" pid=17584 uid=0 result="success"
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.6805] audit: op="checkpoint-adjust-rollback-timeout" arg="/org/freedesktop/NetworkManager/Checkpoint/4" pid=17584 uid=0 result="success"
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7147] manager: (virt.toca): new Bridge device (/org/freedesktop/NetworkManager/Devices/54)
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7149] audit: op="connection-add" uuid="6ee9e2ca-03c3-4fc2-9a0f-5f8048e1cdc1" name="virt.toca" pid=17584 uid=0 result="success"
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7155] manager: (enp4s0.2): new VLAN device (/org/freedesktop/NetworkManager/Devices/55)
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7156] audit: op="connection-add" uuid="1aa8c24f-3334-4304-889e-2eee566cffb5" name="enp4s0.2" pid=17584 uid=0 result="success"
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7194] device (virt.toca): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7202] device (virt.toca): state change: unavailable -> disconnected (reason 'user-requested', sys-iface-state: 'managed')
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7205] device (virt.toca): Activation: starting connection 'virt.toca' (6ee9e2ca-03c3-4fc2-9a0f-5f8048e1cdc1)
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7206] audit: op="connection-activate" uuid="6ee9e2ca-03c3-4fc2-9a0f-5f8048e1cdc1" name="virt.toca" pid=17584 uid=0 result="success"
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7218] device (enp4s0.2): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7225] device (enp4s0.2): state change: unavailable -> disconnected (reason 'user-requested', sys-iface-state: 'managed')
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7230] device (enp4s0.2): Activation: starting connection 'enp4s0.2' (1aa8c24f-3334-4304-889e-2eee566cffb5)
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7230] device (virt.toca): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7237] device (virt.toca): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7241] device (enp4s0.2): carrier: link connected
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7242] device (enp4s0.2): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7244] device (enp4s0.2): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7246] device (virt.toca): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
May 11 01:27:16 orange.toca.local NetworkManager[1286]: <info>  [1683768436.7249] audit: op="connection-activate" uuid="1aa8c24f-3334-4304-889e-2eee566cffb5" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"

Comment 2 Germano Veit Michel 2023-05-11 03:04:45 UTC

In the brief moment that the connections exist, before it rolls back, it looks like this:

[core@orange ~]$ nmcli c
NAME                UUID                                  TYPE           DEVICE    
ovs-if-br-ex        86d38e72-4b20-4866-badc-483d9687f791  ovs-interface  br-ex     
lo                  a43e6283-3efd-4f5a-b74d-d05b461007db  loopback       lo        
br-ex               e9c95b51-2be8-454c-979c-d583a7b0e250  ovs-bridge     br-ex     
enp4s0.2            e1df5d0f-1420-45d6-9334-6af1e8b9754a  vlan           enp4s0.2  
ovs-if-phys0        28b2515f-a13d-4dd7-a545-daaf7f8049af  ethernet       enp4s0    
ovs-port-br-ex      194ba912-8332-4874-928f-e83e3982c687  ovs-port       br-ex     
ovs-port-phys0      e32c6654-4537-4d57-a658-b8e11d4f829d  ovs-port       enp4s0    
virt.toca           d860ef0e-4365-44eb-9e32-4a13517d3e31  bridge         virt.toca

Comment 3 Germano Veit Michel 2023-05-11 09:30:05 UTC

Reproduced manually now:

sh-4.4# cat config.yml 
desiredState:
  interfaces:
  - ipv4:
      enabled: false
    ipv6:
      enabled: false
    name: enp4s0.2
    state: up
    type: vlan
    vlan:
      base-iface: enp4s0
      id: 2
  - bridge:
      options:
        stp:
          enabled: false
      port:
      - name: enp4s0.2
        vlan:
          mode: trunk
          trunk-tags:
          - id-range:
              max: 4094
              min: 2
    description: bridge for vlan 2
    ipv4:
      enabled: false
    ipv6:
      enabled: false
    name: virt.toca
    state: up
    type: linux-bridge
sh-4.4# nmstatectl apply config.yml 
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T09:27:36Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T09:27:36Z INFO  nmstate::nm::show] Got unsupported interface type generic: genev_sys_6081, ignoring
[2023-05-11T09:27:36Z INFO  nmstate::query_apply::net_state] Created checkpoint /org/freedesktop/NetworkManager/Checkpoint/4
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface b3a290e32e77bf4 type ethernet
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface a5581a80b04273f type ethernet
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface 53dbea48161925f type ethernet
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface patch-br-ex_orange.toca.local-to-br-int type ovs-interface
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface efa708a74ce4e38 type ethernet
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface patch-br-int-to-br-ex_orange.toca.local type ovs-interface
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface br-int type ovs-interface
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface 9a7714d434df22b type ethernet
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface fb9b775658e441b type ethernet
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface 8c11bee9469f792 type ethernet
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface veth14b2b4a2 type ethernet
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface ovn-k8s-mp0 type ovs-interface
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface a0700d22f79373e type ethernet
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface 1fc4ec81d0a3d62 type ethernet
[2023-05-11T09:27:36Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface 03dcb0fa1e553c9 type ethernet
[2023-05-11T09:27:36Z INFO  nmstate::nm::query_apply::profile] Creating connection UUID Some("67ae1a85-e653-4a4c-a138-eabc55029dcb"), ID Some("virt.toca"), type Some("bridge") name Some("virt.toca")
[2023-05-11T09:27:36Z INFO  nmstate::nm::query_apply::profile] Creating connection UUID Some("6e2165b3-d334-43fa-9fbb-0deaa8690c00"), ID Some("enp4s0.2"), type Some("vlan") name Some("enp4s0.2")
[2023-05-11T09:27:36Z INFO  nmstate::nm::query_apply::profile] Activating connection 67ae1a85-e653-4a4c-a138-eabc55029dcb: virt.toca/bridge
[2023-05-11T09:27:36Z INFO  nmstate::nm::query_apply::profile] Activating connection 6e2165b3-d334-43fa-9fbb-0deaa8690c00: enp4s0.2/vlan
[2023-05-11T09:27:36Z INFO  nmstate::nm::query_apply::profile] Got activation failure Bug: Manager(UnknownDevice): Failed to find a compatible device for this connection
[2023-05-11T09:27:36Z INFO  nmstate::nm::query_apply::profile] Will retry activation 2 seconds
[2023-05-11T09:27:38Z INFO  nmstate::nm::query_apply::profile] Activating connection 6e2165b3-d334-43fa-9fbb-0deaa8690c00: enp4s0.2/vlan
[2023-05-11T09:27:38Z INFO  nmstate::nm::query_apply::profile] Got activation failure Bug: Manager(UnknownDevice): Failed to find a compatible device for this connection
[2023-05-11T09:27:38Z INFO  nmstate::nm::query_apply::profile] Will retry activation 4 seconds
^Csh-4.4#

Comment 5 Germano Veit Michel 2023-05-11 09:42:02 UTC

It actually "activates" it just fine, the device is briefly present, enslaved to the bridge and UP, all set correctly:

30: virt.toca: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP mode DEFAULT group default qlen 1000
    link/ether 88:ae:dd:0e:b5:fc brd ff:ff:ff:ff:ff:ff
31: enp4s0.2@enp4s0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue master virt.toca state UP mode DEFAULT group default qlen 1000
    link/ether 88:ae:dd:0e:b5:fc brd ff:ff:ff:ff:ff:ff

Then that error comes up, and it rolls back to the previous configuration, as if it failed. But AFAICS, it did set it up just fine.

Comment 6 Germano Veit Michel 2023-05-11 10:19:23 UTC

If I restart NetworkManager and try the exact same thing again, then it works....

Comment 7 Gris Ge 2023-05-11 12:53:53 UTC

Hi Garmano,

Can you collect trace level log of NetworkManager when you reproduced the problem?

 * sudo nmcli g logging level trace domains all
 * # Reproduce the problem
 * sudo journalctl  -u NetworkManager


After that, can you try to install nmstate scratch build in https://people.redhat.com/fge/bz_2202999/

Comment 8 Germano Veit Michel 2023-05-11 21:10:35 UTC

With trace:

May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3032] auth: call[62]: CheckAuthorization(org.freedesktop.NetworkManager.checkpoint-rollback), subject=unix-process[pid=10857, uid=0, start=56152] (succeeding for root)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3033] auth: call[62]: completed: authorized=1, challenge=0 (simulated)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3040] dbus-object[1c6c567e0b9f3a67]: export: "/org/freedesktop/NetworkManager/Checkpoint/4"
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <info>  [1683839344.3040] audit: op="checkpoint-create" arg="/org/freedesktop/NetworkManager/Checkpoint/4" pid=10857 uid=0 result="success"
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3051] auth: call[63]: CheckAuthorization(org.freedesktop.NetworkManager.checkpoint-rollback), subject=unix-process[pid=10857, uid=0, start=56152] (succeeding for root)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3051] auth: call[63]: completed: authorized=1, challenge=0 (simulated)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <info>  [1683839344.3051] audit: op="checkpoint-adjust-rollback-timeout" arg="/org/freedesktop/NetworkManager/Checkpoint/4" pid=10857 uid=0 result="success"
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3401] auth: call[64]: CheckAuthorization(org.freedesktop.NetworkManager.settings.modify.system), subject=unix-process[pid=10857, uid=0, start=56152] (succeeding for root)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3402] auth: call[64]: completed: authorized=1, challenge=0 (simulated)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3465] keyfile: commit: "/etc/NetworkManager/system-connections/enp4s0.2.nmconnection": profile 8ccf3d6f-9762-4cb9-b300-0e45669a9eea (enp4s0.2) written
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3465] settings: update[8ccf3d6f-9762-4cb9-b300-0e45669a9eea]: update-from-dbus: update profile "enp4s0.2"
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3466] settings: storage[8ccf3d6f-9762-4cb9-b300-0e45669a9eea,7d8cbe4df313ff97/keyfile]: change event with connection "enp4s0.2" (file "/etc/NetworkManager/system-connections/enp4s0.2.nmconnection")
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3466] settings: update[8ccf3d6f-9762-4cb9-b300-0e45669a9eea]: updating connection "enp4s0.2" (7d8cbe4df313ff97/keyfile)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3466] settings-connection[3f80facc3fe74ef2,8ccf3d6f-9762-4cb9-b300-0e45669a9eea]: autoconnect: blocked reason: user-request
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3466] ++ connection 'update connection' (0x5623b0b00990/NMSimpleConnection/"vlan" < 0x5623b0b00210/NMSimpleConnection/"vlan") [/org/freedesktop/NetworkManager/Settings/2]:
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3467] ++ connection                [ 0x5623b0b025b0 < 0x5623b0b020d0 ]
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3467] ++ connection.timestamp      = 1683839275 < 1683838942
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3468] l3cfg[bea6ec1f6d65c8fe,ifindex=19] referenced
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3468] l3cfg[bea6ec1f6d65c8fe,ifindex=19]: commit type register (type "none", source "device", existing 46941776b50b33f3) -> 46941776b50b33f3
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3468] device[4eed18f54d8924d2] (enp4s0.2): ifindex: set ifindex 19 (l3cfg: bea6ec1f6d65c8fe)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3468] device[4eed18f54d8924d2] (enp4s0.2): constructed (NMDeviceVlan)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3469] manager: (enp4s0.2) create virtual device enp4s0.2
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <warn>  [1683839344.3469] manager: (enp4s0.2) can't register the device with manager: A device with ifindex 19 already exists
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3469] device[4eed18f54d8924d2] (enp4s0.2): disposing
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3469] device[4eed18f54d8924d2] (enp4s0.2): ip6: addrgenmode6: set eui64
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3469] platform-linux: link: change 19: user-ipv6ll: set IPv6 address generation mode to eui64
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3476] platform-linux: do-request-link: 19 
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3476] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 0: ignore
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3476] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 0: 19: enp4s0.2@2 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 master 7 arp 1 vlan* not-init addrgenmode eui64 addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:267,55719 tx:0,0; vlan 2 protocol 802.1Q
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3476] platform: (enp4s0.2) signal: link changed: 19: enp4s0.2@2 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 master 7 arp 1 vlan* init addrgenmode eui64 addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF driver vlan rx:267,55719 tx:0,0
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3476] l3cfg[bea6ec1f6d65c8fe,ifindex=19]: emit signal (platform-change, obj-type=link, change=changed, obj=19: enp4s0.2@2 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 master 7 arp 1 vlan* init addrgenmode eui64 addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF driver vlan rx:267,55719 tx:0,0; vlan 2 protocol 802.1Q)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3477] device[8a6d11d9f0daa452] (enp4s0.2): queued link change for ifindex 19
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3477] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 180: 19: enp4s0.2@2 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 master 7 arp 1 vlan* not-init addrgenmode eui64 addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:267,55719 tx:0,0; vlan 2 protocol 802.1Q
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3477] platform-linux: do-change-link[19]: success
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3477] device[4eed18f54d8924d2] (enp4s0.2): ifindex: set ifindex 0 (old-l3cfg: bea6ec1f6d65c8fe)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3478] device[4eed18f54d8924d2] (enp4s0.2): finalize(): NMDeviceVlan
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3480] Saving secrets for connection /org/freedesktop/NetworkManager/Settings/2 (enp4s0.2)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <info>  [1683839344.3480] audit: op="connection-update" uuid="8ccf3d6f-9762-4cb9-b300-0e45669a9eea" name="enp4s0.2" args="connection.timestamp" pid=10857 uid=0 result="success"
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3481] device[fb7cf434a4f93202] (lo): add_pending_action (1): 'autoactivate'
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3481] l3cfg[bea6ec1f6d65c8fe,ifindex=19]: emit signal (platform-change-on-idle, obj-type-flags=0x2)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3481] device[ecccc781bf3d6d1c] (virt.toca): master: add one slave 8a6d11d9f0daa452/enp4s0.2 (already registered)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3482] device[fb7cf434a4f93202] (lo): remove_pending_action (0): 'autoactivate'
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3486] auth: call[65]: CheckAuthorization(org.freedesktop.NetworkManager.settings.modify.system), subject=unix-process[pid=10857, uid=0, start=56152] (succeeding for root)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3486] auth: call[65]: completed: authorized=1, challenge=0 (simulated)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3539] keyfile: commit: "/etc/NetworkManager/system-connections/virt.toca.nmconnection": profile 3f866354-31ee-4d8f-a9b9-a4830d210b48 (virt.toca) written
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3540] settings: update[3f866354-31ee-4d8f-a9b9-a4830d210b48]: update-from-dbus: update profile "virt.toca"
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3541] settings: storage[3f866354-31ee-4d8f-a9b9-a4830d210b48,46dc44124ab9d42e/keyfile]: change event with connection "virt.toca" (file "/etc/NetworkManager/system-connections/virt.toca.nmconnection")
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3541] settings: update[3f866354-31ee-4d8f-a9b9-a4830d210b48]: updating connection "virt.toca" (46dc44124ab9d42e/keyfile)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3542] manager: (virt.toca) already created virtual interface name virt.toca
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3543] Saving secrets for connection /org/freedesktop/NetworkManager/Settings/1 (virt.toca)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <info>  [1683839344.3544] audit: op="connection-update" uuid="3f866354-31ee-4d8f-a9b9-a4830d210b48" name="virt.toca" pid=10857 uid=0 result="success"
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3544] device[fb7cf434a4f93202] (lo): add_pending_action (1): 'autoactivate'
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3544] device[fb7cf434a4f93202] (lo): remove_pending_action (0): 'autoactivate'
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3582] auth: call[66]: CheckAuthorization(org.freedesktop.NetworkManager.network-control), subject=unix-process[pid=10857, uid=0, start=56152] (succeeding for root)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3582] auth: call[66]: completed: authorized=1, challenge=0 (simulated)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3583] device[ecccc781bf3d6d1c] (virt.toca): reapply (version-id 2 (unmodified))
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3583] device[ecccc781bf3d6d1c] (virt.toca): reapplying bridge settings
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3583] platform: (virt.toca) link: changing link: bridge "virt.toca", forward_delay 1500 hello_time 200 max_age 2000 ageing_time 30000 stp_state 0 priority 32768 vlan_protocol 33024 vlan_stats_enabled 0 group_fwd_mask 0 group_address 01:80:C2:00:00:00 mcast_snooping 1 mcast_router 1 mcast_query_use_ifaddr 0 mcast_querier 0 mcast_hash_max 4096 mcast_last_member_count 2 mcast_startup_query_count 2 mcast_last_member_interval 100 mcast_membership_interval 26000 mcast_querier_interval 25500 mcast_query_interval 12500 mcast_query_response_interval 1000 mcast_startup_query_interv
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3583] platform-linux: do-request-link: 7 
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3583] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 0: 7: virt.toca <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 arp 1 bridge* not-init addrgenmode none addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:620,131828 tx:0,0; forward_delay 1500 hello_time 200 max_age 2000 ageing_time 30000 stp_state 0 priority 32768 vlan_protocol 33024 vlan_stats_enabled 0 group_fwd_mask 0 group_address 01:80:C2:00:00:00 mcast_snooping 1 mcast_router 1 mcast_query_use_ifaddr 0 mcast_querier 0 mcast_hash_max 4096 mcast_last_member_count 2 mcast_startup_query_count 2 mcast_last_member_interval 100 mcast_membership_interval 26000 mcast_querier_interval 25500 mcast_query_interval 12500 mcast_query_response_interval 1000 mcast_startup_query_interval 3125
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3583] platform: (virt.toca) signal: link changed: 7: virt.toca <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 arp 1 bridge* init addrgenmode none addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF driver bridge rx:620,131828 tx:0,0
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3584] l3cfg[10b00ae75f3772e8,ifindex=7]: emit signal (platform-change, obj-type=link, change=changed, obj=7: virt.toca <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 arp 1 bridge* init addrgenmode none addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF driver bridge rx:620,131828 tx:0,0; forward_delay 1500 hello_time 200 max_age 2000 ageing_time 30000 stp_state 0 priority 32768 vlan_protocol 33024 vlan_stats_enabled 0 group_fwd_mask 0 group_address 01:80:C2:00:00:00 mcast_snooping 1 mcast_router 1 mcast_query_use_ifaddr 0 mcast_querier 0 mcast_hash_max 4096 mcast_last_member_count 2 mcast_startup_query_count 2 mcast_last_member_interval 100 mcast_membership_interval 26000 mcast_querier_interval 25500 mcast_query_interval 12500 mcast_query_response_interval 1000 mcast_startup_query_interval 3125)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3584] device[ecccc781bf3d6d1c] (virt.toca): queued link change for ifindex 7
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3584] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 182: 7: virt.toca <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 arp 1 bridge* not-init addrgenmode none addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:620,131828 tx:0,0; forward_delay 1500 hello_time 200 max_age 2000 ageing_time 30000 stp_state 0 priority 32768 vlan_protocol 33024 vlan_stats_enabled 0 group_fwd_mask 0 group_address 01:80:C2:00:00:00 mcast_snooping 1 mcast_router 1 mcast_query_use_ifaddr 0 mcast_querier 0 mcast_hash_max 4096 mcast_last_member_count 2 mcast_startup_query_count 2 mcast_last_member_interval 100 mcast_membership_interval 26000 mcast_querier_interval 25500 mcast_query_interval 12500 mcast_query_response_interval 1000 mcast_startup_query_interval 3125
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3585] platform-linux: do-change-link[7]: success
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3586] platform-linux: sysctl: setting 'net:/sys/class/net/virt.toca/bridge/vlan_filtering' to '0' (current value is '1')
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3723] platform-linux: sysctl: setting 'net:/sys/class/net/virt.toca/bridge/default_pvid' to '0' (current value is '1')
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3724] platform: (virt.toca) link: clearing bridge VLANs on self
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3728] platform-linux: do-request-link: 7 
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3728] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 0: 2: enp4s0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 master 3 arp 1 ethernet? not-init addrgenmode none addr 88:AE:DD:0E:B5:FC permaddr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:69218,77013146 tx:35426,12872790
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3728] platform: (enp4s0) signal: link changed: 2: enp4s0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 master 3 arp 1 ethernet? init addrgenmode none addr 88:AE:DD:0E:B5:FC permaddr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF driver igc rx:69218,77013146 tx:35426,12872790
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3728] l3cfg[ebba62c975e0dc82,ifindex=2]: emit signal (platform-change, obj-type=link, change=changed, obj=2: enp4s0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 master 3 arp 1 ethernet? init addrgenmode none addr 88:AE:DD:0E:B5:FC permaddr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF driver igc rx:69218,77013146 tx:35426,12872790)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3728] device[70980b920ddb2fae] (enp4s0): queued link change for ifindex 2
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3728] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 0: 19: enp4s0.2@2 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 master 7 arp 1 vlan* not-init addrgenmode eui64 addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:267,55719 tx:0,0; vlan 2 protocol 802.1Q
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3728] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 0: 7: virt.toca <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 arp 1 bridge* not-init addrgenmode none addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:620,131828 tx:0,0; forward_delay 1500 hello_time 200 max_age 2000 ageing_time 30000 stp_state 0 priority 32768 vlan_protocol 33024 vlan_stats_enabled 0 group_fwd_mask 0 group_address 01:80:C2:00:00:00 mcast_snooping 1 mcast_router 1 mcast_query_use_ifaddr 0 mcast_querier 0 mcast_hash_max 4096 mcast_last_member_count 2 mcast_startup_query_count 2 mcast_last_member_interval 100 mcast_membership_interval 26000 mcast_querier_interval 25500 mcast_query_interval 12500 mcast_query_response_interval 1000 mcast_startup_query_interval 3125
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3729] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 0: 7: virt.toca <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 arp 1 bridge* not-init addrgenmode none addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:620,131828 tx:0,0; forward_delay 1500 hello_time 200 max_age 2000 ageing_time 30000 stp_state 0 priority 32768 vlan_protocol 33024 vlan_stats_enabled 0 group_fwd_mask 0 group_address 01:80:C2:00:00:00 mcast_snooping 1 mcast_router 1 mcast_query_use_ifaddr 0 mcast_querier 0 mcast_hash_max 4096 mcast_last_member_count 2 mcast_startup_query_count 2 mcast_last_member_interval 100 mcast_membership_interval 26000 mcast_querier_interval 25500 mcast_query_interval 12500 mcast_query_response_interval 1000 mcast_startup_query_interval 3125
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3730] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 184: 7: virt.toca <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 arp 1 bridge* not-init addrgenmode none addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:620,131828 tx:0,0; forward_delay 1500 hello_time 200 max_age 2000 ageing_time 30000 stp_state 0 priority 32768 vlan_protocol 33024 vlan_stats_enabled 0 group_fwd_mask 0 group_address 01:80:C2:00:00:00 mcast_snooping 1 mcast_router 1 mcast_query_use_ifaddr 0 mcast_querier 0 mcast_hash_max 4096 mcast_last_member_count 2 mcast_startup_query_count 2 mcast_last_member_interval 100 mcast_membership_interval 26000 mcast_querier_interval 25500 mcast_query_interval 12500 mcast_query_response_interval 1000 mcast_startup_query_interval 3125
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3730] platform-linux: do-change-link[7]: success
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3730] platform-linux: sysctl: setting 'net:/sys/class/net/virt.toca/bridge/default_pvid' to '1' (current value is '0')
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3736] platform-linux: sysctl: setting 'net:/sys/class/net/virt.toca/bridge/vlan_filtering' to '1' (current value is '0')
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3874] device[ecccc781bf3d6d1c] (virt.toca): activation-stage: schedule activate_stage3_ip_config
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3874] global-tracker: sync routing-rule
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3874] pacrunner: call[13]: removing...
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3874] pacrunner: call[15]: add config: ({'Interface': <'virt.toca'>, 'Method': <'direct'>, 'BrowserOnly': <false>},) (pacrunner D-Bus service not running)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3874] l3cfg[10b00ae75f3772e8,ifindex=7]: commit on idle (scheduled) (reapply)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3875] firewalld: [0e86a9e6f5cb4a49,change*:"virt.toca"]: firewall zone change virt.toca:default (not running, simulate success)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3875] device[ecccc781bf3d6d1c] (virt.toca): Notifying re-apply complete
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3875] dispatcher: (45) (virt.toca) dispatching action 'reapply'
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <info>  [1683839344.3876] audit: op="device-reapply" interface="virt.toca" ifindex=7 pid=10857 uid=0 result="success"
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3877] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 0: 7: virt.toca <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 arp 1 bridge* not-init addrgenmode none addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:620,131828 tx:0,0; forward_delay 1500 hello_time 200 max_age 2000 ageing_time 30000 stp_state 0 priority 32768 vlan_protocol 33024 vlan_stats_enabled 0 group_fwd_mask 0 group_address 01:80:C2:00:00:00 mcast_snooping 1 mcast_router 1 mcast_query_use_ifaddr 0 mcast_querier 0 mcast_hash_max 4096 mcast_last_member_count 2 mcast_startup_query_count 2 mcast_last_member_interval 100 mcast_membership_interval 26000 mcast_querier_interval 25500 mcast_query_interval 12500 mcast_query_response_interval 1000 mcast_startup_query_interval 3125
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3877] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 0: 2: enp4s0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 master 3 arp 1 ethernet? not-init addrgenmode none addr 88:AE:DD:0E:B5:FC permaddr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:69221,77014029 tx:35429,12872988
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3877] platform: (enp4s0) signal: link changed: 2: enp4s0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 master 3 arp 1 ethernet? init addrgenmode none addr 88:AE:DD:0E:B5:FC permaddr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF driver igc rx:69221,77014029 tx:35429,12872988
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3878] l3cfg[ebba62c975e0dc82,ifindex=2]: emit signal (platform-change, obj-type=link, change=changed, obj=2: enp4s0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 master 3 arp 1 ethernet? init addrgenmode none addr 88:AE:DD:0E:B5:FC permaddr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF driver igc rx:69221,77014029 tx:35429,12872988)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3878] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 0: 19: enp4s0.2@2 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 master 7 arp 1 vlan* not-init addrgenmode eui64 addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:267,55719 tx:0,0; vlan 2 protocol 802.1Q
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3878] platform-linux: event-notification: RTM_NEWLINK, flags 0, seq 0: 7: virt.toca <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 1500 arp 1 bridge* not-init addrgenmode none addr 88:AE:DD:0E:B5:FC brd FF:FF:FF:FF:FF:FF rx:620,131828 tx:0,0; forward_delay 1500 hello_time 200 max_age 2000 ageing_time 30000 stp_state 0 priority 32768 vlan_protocol 33024 vlan_stats_enabled 0 group_fwd_mask 0 group_address 01:80:C2:00:00:00 mcast_snooping 1 mcast_router 1 mcast_query_use_ifaddr 0 mcast_querier 0 mcast_hash_max 4096 mcast_last_member_count 2 mcast_startup_query_count 2 mcast_last_member_interval 100 mcast_membership_interval 26000 mcast_querier_interval 25500 mcast_query_interval 12500 mcast_query_response_interval 1000 mcast_startup_query_interval 3125
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3878] l3cfg[10b00ae75f3772e8,ifindex=7]: emit signal (platform-change-on-idle, obj-type-flags=0x2)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3878] l3cfg[ebba62c975e0dc82,ifindex=2]: emit signal (platform-change-on-idle, obj-type-flags=0x2)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3879] device[70980b920ddb2fae] (enp4s0): the device claimed by openvswitch
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3880] device[ecccc781bf3d6d1c] (virt.toca): activation-stage: invoke activate_stage3_ip_config
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3880] l3cfg[10b00ae75f3772e8,ifindex=7]: commit reapply (idle handler)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3880] l3cfg[10b00ae75f3772e8,ifindex=7]: emit signal (pre-commit)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3880] l3cfg[10b00ae75f3772e8,ifindex=7]: committing IPv4 configuration (reapply)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3880] netns[7c1aef99ec4632da]: ecmp-route: committing IPv4 ECMP routes
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3880] global-tracker: sync ip4-route
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3880] l3cfg[10b00ae75f3772e8,ifindex=7]: committing IPv6 configuration (reapply)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3880] l3cfg[10b00ae75f3772e8,ifindex=7]: commit-ip6-privacy: set value 0 (after 0, initial value was 0), ifname virt.toca
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3880] platform-linux: sysctl: setting '/proc/sys/net/ipv6/conf/virt.toca/use_tempaddr' to '0' (current value is identical)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3881] global-tracker: sync ip6-route
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3881] global-tracker: sync mptcp-addr (reapply)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3881] platform-linux: mptcp: 0 addresses dumped
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3881] l3cfg[10b00ae75f3772e8,ifindex=7]: emit signal (post-commit)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.3881] firewalld: [0e86a9e6f5cb4a49,change*:"virt.toca"]: complete: fake success
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3881] device[ecccc781bf3d6d1c] (virt.toca): ip4: check-state: state done => done, is_failed=0, is_pending=0, is_started=0 temp_na=0, may-fail-4=1, may-fail-6=1; disabled4; manualip4=done; disabled6 manualip6=done
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3882] device[ecccc781bf3d6d1c] (virt.toca): ip: check-state: (combined) state done => done
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3882] device[ecccc781bf3d6d1c] (virt.toca): ip6: check-state: state done => done, is_failed=0, is_pending=0, is_started=0 temp_na=0, may-fail-4=1, may-fail-6=1; disabled4; manualip4=done; disabled6 manualip6=done
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3882] device[ecccc781bf3d6d1c] (virt.toca): ip: check-state: (combined) state done => done
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3885] auth: call[67]: CheckAuthorization(org.freedesktop.NetworkManager.network-control), subject=unix-process[pid=10857, uid=0, start=56152] (succeeding for root)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <trace> [1683839344.3886] auth: call[67]: completed: authorized=1, challenge=0 (simulated)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <info>  [1683839344.3886] audit: op="device-reapply" interface="enp4s0.2" ifindex=19 args="vlan.parent,connection.master" pid=10857 uid=0 result="fail" reason="Can't reapply any changes to 'vlan' setting"
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <info>  [1683839344.3890] audit: op="connection-activate" uuid="8ccf3d6f-9762-4cb9-b300-0e45669a9eea" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.4176] dispatcher: (45) succeeded (after 0.030 sec, 7 scripts invoked)
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.4176] dispatcher: (45) /usr/lib/NetworkManager/dispatcher.d/04-iscsi succeeded
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.4176] dispatcher: (45) /usr/lib/NetworkManager/dispatcher.d/20-chrony-dhcp succeeded
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.4176] dispatcher: (45) /usr/lib/NetworkManager/dispatcher.d/20-chrony-onoffline succeeded
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.4176] dispatcher: (45) /etc/NetworkManager/dispatcher.d/20-coreos-chrony-dhcp succeeded
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.4176] dispatcher: (45) /etc/NetworkManager/dispatcher.d/90-console-login-helper-messages-gensnippet_if succeeded
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.4176] dispatcher: (45) /usr/lib/NetworkManager/dispatcher.d/90-nm-cloud-setup.sh succeeded
May 11 21:09:04 orange.toca.local NetworkManager[1309]: <debug> [1683839344.4176] dispatcher: (45) /etc/NetworkManager/dispatcher.d/99-vsphere-disable-tx-udp-tnl succeeded
May 11 21:09:06 orange.toca.local NetworkManager[1309]: <trace> [1683839346.3912] auth: call[68]: CheckAuthorization(org.freedesktop.NetworkManager.network-control), subject=unix-process[pid=10857, uid=0, start=56152] (succeeding for root)
May 11 21:09:06 orange.toca.local NetworkManager[1309]: <trace> [1683839346.3912] auth: call[68]: completed: authorized=1, challenge=0 (simulated)
May 11 21:09:06 orange.toca.local NetworkManager[1309]: <info>  [1683839346.3913] audit: op="device-reapply" interface="enp4s0.2" ifindex=19 args="vlan.parent,connection.master" pid=10857 uid=0 result="fail" reason="Can't reapply any changes to 'vlan' setting"
May 11 21:09:06 orange.toca.local NetworkManager[1309]: <info>  [1683839346.3920] audit: op="connection-activate" uuid="8ccf3d6f-9762-4cb9-b300-0e45669a9eea" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 11 21:09:10 orange.toca.local NetworkManager[1309]: <trace> [1683839350.3947] auth: call[69]: CheckAuthorization(org.freedesktop.NetworkManager.network-control), subject=unix-process[pid=10857, uid=0, start=56152] (succeeding for root)
May 11 21:09:10 orange.toca.local NetworkManager[1309]: <trace> [1683839350.3947] auth: call[69]: completed: authorized=1, challenge=0 (simulated)
May 11 21:09:10 orange.toca.local NetworkManager[1309]: <info>  [1683839350.3947] audit: op="device-reapply" interface="enp4s0.2" ifindex=19 args="vlan.parent,connection.master" pid=10857 uid=0 result="fail" reason="Can't reapply any changes to 'vlan' setting"
May 11 21:09:10 orange.toca.local NetworkManager[1309]: <info>  [1683839350.3954] audit: op="connection-activate" uuid="8ccf3d6f-9762-4cb9-b300-0e45669a9eea" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"

Comment 9 Germano Veit Michel 2023-05-11 21:22:45 UTC

The test build seems to work (tried 4 times, didn't reproduce - but this thing is temperamental).

Also, enabling NM debug as above seems to make it harder to reproduce, is this a race condition?

# rpm -qa | grep nmstate
nmstate-libs-2.2.11-0.alpha.20230511.7f5d24ba.el9.x86_64
nmstate-2.2.11-0.alpha.20230511.7f5d24ba.el9.x86_64
nmstate-devel-2.2.11-0.alpha.20230511.7f5d24ba.el9.x86_64
python3-libnmstate-2.2.11-0.alpha.20230511.7f5d24ba.el9.x86_64

[root@orange /]# nmstatectl apply config.yml 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z INFO  nmstate::nm::show] Got unsupported interface type generic: genev_sys_6081, ignoring
[2023-05-11T21:17:33Z INFO  nmstate::query_apply::net_state] Created checkpoint /org/freedesktop/NetworkManager/Checkpoint/5
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface patch-br-ex_orange.toca.local-to-br-int type ovs-interface
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface 94b381756975cbd type ethernet
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface br-int type ovs-interface
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface d5b267d19fc3c56 type ethernet
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface 219852c73049ff2 type ethernet
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface 02ddcf2422391ef type ethernet
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface a74950f12f1afdb type ethernet
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface patch-br-int-to-br-ex_orange.toca.local type ovs-interface
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface 0ea981a05920aef type ethernet
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface 759408ade62bfaf type ethernet
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface 731718f6937edac type ethernet
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface f1728410f143a9b type ethernet
[2023-05-11T21:17:33Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface ovn-k8s-mp0 type ovs-interface
[2023-05-11T21:17:33Z INFO  nmstate::nm::query_apply::profile] Modifying connection UUID Some("3f866354-31ee-4d8f-a9b9-a4830d210b48"), ID Some("virt.toca"), type Some("bridge") name Some("virt.toca")
[2023-05-11T21:17:33Z INFO  nmstate::nm::query_apply::profile] Modifying connection UUID Some("8ccf3d6f-9762-4cb9-b300-0e45669a9eea"), ID Some("enp4s0.2"), type Some("vlan") name Some("enp4s0.2")
[2023-05-11T21:17:33Z INFO  nmstate::nm::query_apply::profile] Activating connection 3f866354-31ee-4d8f-a9b9-a4830d210b48: virt.toca/bridge
[2023-05-11T21:17:33Z INFO  nmstate::nm::query_apply::profile] Activating connection 8ccf3d6f-9762-4cb9-b300-0e45669a9eea: enp4s0.2/vlan
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type geneve
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z WARN  nmstate::ovsdb::show] Unknown OVS interface type 
[2023-05-11T21:17:33Z INFO  nmstate::nm::show] Got unsupported interface type generic: genev_sys_6081, ignoring
[2023-05-11T21:17:33Z INFO  nmstate::query_apply::net_state] Destroyed checkpoint /org/freedesktop/NetworkManager/Checkpoint/5
dns-resolver: {}
route-rules: {}
routes: {}
interfaces:
- name: enp4s0.2
  type: vlan
  state: up
  ipv4:
    enabled: false
  ipv6:
    enabled: false
  vlan:
    base-iface: enp4s0
    id: 2
- name: virt.toca
  type: linux-bridge
  description: bridge for vlan 2
  state: up
  ipv4:
    enabled: false
  ipv6:
    enabled: false
  bridge:
    options:
      stp:
        enabled: false
    port:
    - name: enp4s0.2
      vlan:
        mode: trunk
        trunk-tags:
        - id-range:
            min: 2
            max: 4094
ovs-db: {}

Comment 10 Germano Veit Michel 2023-05-15 03:25:36 UTC

Cold startup on Monday, 5 out of 9 nodes affected

$ oc get nnce
NAME                                 STATUS      REASON
black.toca.local.virt-toca-black     Available   SuccessfullyConfigured
blue.toca.local.virt-toca-blue       Failing     FailedToConfigure
green.toca.local.virt-toca-green     Available   SuccessfullyConfigured
indigo.toca.local.virt-toca-indigo   Failing     FailedToConfigure
orange.toca.local.virt-toca-orange   Available   SuccessfullyConfigured
red.toca.local.virt-toca-red         Failing     FailedToConfigure
violet.toca.local.virt-toca-violet   Failing     FailedToConfigure
white.toca.local.virt-toca-white     Failing     FailedToConfigure
yellow.toca.local.virt-toca-yellow   Available   SuccessfullyConfigured 

Looks like its more than 20-30% I initially estimated.

Comment 11 Gris Ge 2023-05-15 06:47:48 UTC

I am afraid this is a race problem, let's wait NetworkManager developer to clarify this using above trace logs.

Comment 12 Beniamino Galvani 2023-05-15 07:22:31 UTC

The issue happens here:

NetworkManager[1309]: <warn>  [1683839344.3469] manager: (enp4s0.2) can't register the device with manager: A device with ifindex 19 already exists

Germano, can you please attach the trace log of NM since it started, so that it is possible to check which other device is claiming the ifindex?

Comment 13 Germano Veit Michel 2023-05-15 21:36:01 UTC

(In reply to Gris Ge from comment #11)
> I am afraid this is a race problem, let's wait NetworkManager developer to
> clarify this using above trace logs.

I think you are right, because with trace logs it gets considerably harder to reproduce.

Comment 14 Germano Veit Michel 2023-05-15 21:51:51 UTC

(In reply to Beniamino Galvani from comment #12)
> The issue happens here:
> 
> NetworkManager[1309]: <warn>  [1683839344.3469] manager: (enp4s0.2) can't
> register the device with manager: A device with ifindex 19 already exists
> 
> Germano, can you please attach the trace log of NM since it started, so that
> it is possible to check which other device is claiming the ifindex?

Its harder to reproduce with tracing enabled.

Sequence of events for context:

1. Starting point was a successfully configured node (I fixed them all yesterday with NM restarts)
2. Enable NM tracing permanently
3. Delete the NNCP (configuration yaml in comment #0)
3. Reboot the node
4. SSH to the node and manually cleanup the devices (deleting the NNCP does not cleanup, IMHO thats another bug)
5. Reboot again
6. Create the NNCP
7. Hit the problem

Attaching logs.txt

Comment 15 Germano Veit Michel 2023-05-15 21:54:01 UTC

Created attachment 1964746 [details]
trace logs since NM start

You will see multiple failures as it backs off and retries

# grep "compatible" logs.txt 
May 15 21:34:43 orange.toca.local NetworkManager[1323]: <info>  [1684186483.3337] audit: op="connection-activate" uuid="c79d15c3-527a-43ed-aa50-41bd32701f32" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 15 21:34:45 orange.toca.local NetworkManager[1323]: <info>  [1684186485.3348] audit: op="connection-activate" uuid="c79d15c3-527a-43ed-aa50-41bd32701f32" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 15 21:34:49 orange.toca.local NetworkManager[1323]: <info>  [1684186489.3359] audit: op="connection-activate" uuid="c79d15c3-527a-43ed-aa50-41bd32701f32" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 15 21:34:57 orange.toca.local NetworkManager[1323]: <info>  [1684186497.3375] audit: op="connection-activate" uuid="c79d15c3-527a-43ed-aa50-41bd32701f32" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 15 21:35:13 orange.toca.local NetworkManager[1323]: <info>  [1684186513.3401] audit: op="connection-activate" uuid="c79d15c3-527a-43ed-aa50-41bd32701f32" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 15 21:35:45 orange.toca.local NetworkManager[1323]: <info>  [1684186545.3441] audit: op="connection-activate" uuid="c79d15c3-527a-43ed-aa50-41bd32701f32" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 15 21:35:47 orange.toca.local NetworkManager[1323]: <info>  [1684186547.4404] audit: op="connection-activate" uuid="c79d15c3-527a-43ed-aa50-41bd32701f32" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 15 21:35:49 orange.toca.local NetworkManager[1323]: <info>  [1684186549.4438] audit: op="connection-activate" uuid="c79d15c3-527a-43ed-aa50-41bd32701f32" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 15 21:35:53 orange.toca.local NetworkManager[1323]: <info>  [1684186553.4465] audit: op="connection-activate" uuid="c79d15c3-527a-43ed-aa50-41bd32701f32" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 15 21:36:01 orange.toca.local NetworkManager[1323]: <info>  [1684186561.4510] audit: op="connection-activate" uuid="c79d15c3-527a-43ed-aa50-41bd32701f32" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 15 21:36:17 orange.toca.local NetworkManager[1323]: <info>  [1684186577.4568] audit: op="connection-activate" uuid="c79d15c3-527a-43ed-aa50-41bd32701f32" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"
May 15 21:36:49 orange.toca.local NetworkManager[1323]: <info>  [1684186609.4658] audit: op="connection-activate" uuid="c79d15c3-527a-43ed-aa50-41bd32701f32" name="enp4s0.2" result="fail" reason="Failed to find a compatible device for this connection"

Comment 16 Germano Veit Michel 2023-05-15 21:54:52 UTC

Restoring needinfo from comment #11, sorry

Comment 17 Germano Veit Michel 2023-05-15 22:02:06 UTC

Created attachment 1964748 [details]
logs_with_sucess_after_nm_restart.txt

Here is the entire logs.txt file again, but at the end of the file you will now see me restarting NM again and then retrying 2 times to delete the NNCP and add it again, it succeeds on the second attempt.

Maybe it helps, as you can compare a successful with an unsuccessful one from the same system and exact same config.

Comment 22 Beniamino Galvani 2023-05-22 09:23:15 UTC

Okay, so the problem seems to be the following.

After the initial configuration done by MCO, there is a OVS bridge, and a connection "ovs-if-phys0" of type ovs-interface is active on enp4s0. There previous Ethernet connection named "Wired Connection 1" that refers to enp4s0 is still present but deactivated.

The nmstate YAML defines a Linux bridge with a "enp4s0.2" port of type VLAN which has parent enp4s0. nmstate creates a bridge connection and a VLAN connection that has "Wired Connection 1" as parent. The activation of the VLAN then fails because the current parent (ovs-if-phys0) is different from the UUID specified in the profile (Wired Connection 1).

This seems a bug in nmstate which is selecting the wrong (not active) connection as the parent for the VLAN.

It is also true that NM could be more helpful here and should just do what the user asks: activate the VLAN and if necessary also activate the parent (disconnecting the existing profile on the parent). However, this would be wrong in this scenario because the existing parent (the ovs-interface) must be preserved.

Thus, I think this must be fixed in nmstate; I'm reassigning the bugzilla.

What could be improved in NM is the logging:

- there can be multiple ovs devices with the same name; in that case it's difficult to correlate log messages with the right device. To solve this, the log should also indicate the device type, at least for OVS devices.

- it would be useful to log the reason why a connection is considered incompatible with a device. Since those messages scale with the number of connections times the number of devices, they are very verbose even at TRACE. We should consider using log domains to enable or disable them.

I will file a separate bugzilla for these improvements.

Comment 23 Beniamino Galvani 2023-05-22 09:26:06 UTC

@fge please check the previous comment.

Comment 24 Gris Ge 2023-05-23 08:38:22 UTC

Thanks for the hints!

Reproduced this problem locally:
 1. Use nmstate to create eth1 setting by:

```
---
interfaces:
  - name: eth1
    type: ethernet
    state: up
```

 2. Use nmcli to create another NM connection for eth1:

```
nmcli c add type ethernet ifname eth1 \
    connection.id 0eth1 ipv4.method disabled ipv6.method disabled
```

 3. Activate the newly created connection `nmcli c up 0eth1`

 4. Use nmstatectl to apply:

```yml
---
interfaces:
  - name: eth1.101
    type: vlan
    state: up
    vlan:
      base-iface: eth1
      id: 101
```

You have to try step 4 multiple times to trigger this issue.

Comment 25 Gris Ge 2023-05-23 08:41:57 UTC

Patch sent to upstream: https://github.com/nmstate/nmstate/pull/2355

Scratch build for RHEL 9.2 could be download from https://people.redhat.com/fge/bz_2202999/

Comment 33 Mingyu Shi 2023-06-09 10:21:50 UTC

Verified with:
nmstate-2.2.12-2.el9.x86_64
nispor-1.2.10-1.el9.x86_64
NetworkManager-1.43.9-1.el9.x86_64
openvswitch2.15-2.15.0-82.el9fdp.x86_64
Linux dell-per750-20.rhts.eng.pek2.redhat.com 5.14.0-323.el9.x86_64 #1 SMP PREEMPT_DYNAMIC Tue Jun 6 12:16:07 EDT 2023 x86_64 x86_64 x86_64 GNU/Linux
DISTRO=RHEL-9.3.0-20230609.0

Note You need to log in before you can comment on or make changes to this bug.