RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 2179314 - verification state fails with "current '[]'"
Summary: verification state fails with "current '[]'"
Keywords:
Status: CLOSED DUPLICATE of bug 2177592
Alias: None
Product: Red Hat Enterprise Linux 9
Classification: Red Hat
Component: nmstate
Version: 9.2
Hardware: Unspecified
OS: Unspecified
unspecified
urgent
Target Milestone: rc
: ---
Assignee: Gris Ge
QA Contact: Mingyu Shi
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2023-03-17 10:06 UTC by Quique Llorente
Modified: 2023-03-22 07:34 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2023-03-22 07:34:13 UTC
Type: Bug
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github nmstate kubernetes-nmstate pull 1059 0 None open Use nmstatectl rust 2023-03-17 10:06:42 UTC
Github nmstate nmstate pull 2280 0 None open state: Set interface as up when `mark_as_changed()` 2023-03-21 11:40:49 UTC
Red Hat Issue Tracker NMT-394 0 None None None 2023-03-17 10:08:33 UTC
Red Hat Issue Tracker RHELPLAN-152168 0 None None None 2023-03-17 10:08:37 UTC

Description Quique Llorente 2023-03-17 10:06:42 UTC 
Description of problem:
At kubernetes-nmstate CI we suffer from massive failures from nmstate verifycation state since the state is empty.

Also checking NM logs looks like state get removed before verify kicks in.


Version-Release number of selected component (if applicable): nmstate-2.2.7


How reproducible: Not always


Steps to Reproduce:
1. Apply a state and repeat until it fails
2.
3.

Actual results:
Verification failure: br6.interface.bridge.port desire '[{\"name\"..., current: '[]'


Expected results:
State is as expected on verification and nmstate do not fail


Additional info:

Checking CI runs and NM versions:
NM 1.41.90 + nmstate 2.2.5 -> Success
NM 1.42.0 + nmstate-2.2.7 -> ?
NM 1.42.2 + nmstate-2.2.7 -> Fail
NM 1.43.3 + nmstate-2.2.7 -> Fail
NM 1.43.3 + nmstate-2.2.6 -> Fail
NM 1.43.3 + nmstate-2.2.5 -> Success



nmstate logs:
https://storage.googleapis.com/kubevirt-prow/pr-logs/pull/nmstate_kubernetes-nmstate/1059/pull-kubernetes-nmstate-e2e-handler-k8s/1636319764265570304/artifacts/NNCP_with_maxUnavailable_when_applying_a_policy_to_matching_nodes/pods.log

[2023-03-16T11:14:30Z INFO  nmstate::nispor::base_iface] Got unsupported interface type Other(\"IpTun\"): tunl0, ignoring
[2023-03-16T11:14:30Z INFO  nmstate::nispor::show] Got unsupported interface tunl0 type Other(\"IpTun\")
[2023-03-16T11:14:30Z INFO  nmstate::nm::show] Got unsupported interface type ip-tunnel: tunl0, ignoring
[2023-03-16T11:14:30Z INFO  nmstate::query_apply::net_state] Created checkpoint /org/freedesktop/NetworkManager/Checkpoint/18
[2023-03-16T11:14:30Z INFO  nmstate::ifaces::inter_ifaces] Ignoring interface cali9fa290ddf78 type ethernet
[2023-03-16T11:14:30Z INFO  nmstate::iface] Include interface eth2 to edit as its controller required so
[2023-03-16T11:14:30Z INFO  nmstate::iface] Include interface eth1 to edit as its controller required so
[2023-03-16T11:14:30Z INFO  nmstate::nm::query_apply::profile] Creating connection UUID Some(\"e1ed7c0f-0f4d-4219-afba-c07fc02cdd80\"), ID Some(\"br6\"), type Some(\"bridge\") name Some(\"br6\")
[2023-03-16T11:14:30Z INFO  nmstate::nm::query_apply::profile] Modifying connection UUID Some(\"6ca9014e-f39d-4935-b8b5-b5e9b3a086cc\"), ID Some(\"eth1\"), type Some(\"802-3-ethernet\") name Some(\"eth1\")
[2023-03-16T11:14:30Z INFO  nmstate::nm::query_apply::profile] Modifying connection UUID Some(\"6ff34640-86d9-49af-a1f8-c6961fa2a55f\"), ID Some(\"eth2\"), type Some(\"802-3-ethernet\") name Some(\"eth2\")
[2023-03-16T11:14:30Z INFO  nmstate::nm::query_apply::profile] Activating connection e1ed7c0f-0f4d-4219-afba-c07fc02cdd80: br6/bridge
[2023-03-16T11:14:30Z INFO  nmstate::nm::query_apply::profile] Activating connection 6ca9014e-f39d-4935-b8b5-b5e9b3a086cc: eth1/802-3-ethernet
[2023-03-16T11:14:30Z INFO  nmstate::nm::query_apply::profile] Activating connection 6ff34640-86d9-49af-a1f8-c6961fa2a55f: eth2/802-3-ethernet
[2023-03-16T11:14:30Z INFO  nmstate::nm::query_apply::profile] Deactivating connection 6ca9014e-f39d-4935-b8b5-b5e9b3a086cc: eth1/802-3-ethernet
[2023-03-16T11:14:31Z INFO  nmstate::nm::query_apply::profile] Deactivating connection 6ff34640-86d9-49af-a1f8-c6961fa2a55f: eth2/802-3-ethernet
[2023-03-16T11:14:31Z INFO  nmstate::nispor::base_iface] Got unsupported interface type Other(\"IpTun\"): tunl0, ignoring
[2023-03-16T11:14:31Z INFO  nmstate::nispor::show] Got unsupported interface tunl0 type Other(\"IpTun\")
[2023-03-16T11:14:31Z INFO  nmstate::nm::show] Got unsupported interface type ip-tunnel: tunl0, ignoring
[2023-03-16T11:14:31Z INFO  nmstate::query_apply::net_state] Retrying on: VerificationError: Verification failure: br6.interface.bridge.port desire 

networkmanager logs before retry/verify:
https://storage.googleapis.com/kubevirt-prow/pr-logs/pull/nmstate_kubernetes-nmstate/1059/pull-kubernetes-nmstate-e2e-handler-k8s/1636319764265570304/artifacts/NNCP_with_maxUnavailable_when_applying_a_policy_to_matching_nodes/NetworkManager.log

[Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2340] manager: (br6): new Bridge device (/org/freedesktop/NetworkManager/Devices/8)
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2342] audit: op="connection-add" uuid="e1ed7c0f-0f4d-4219-afba-c07fc02cdd80" name="br6" pid=10515 uid=0 result="success"
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2365] audit: op="connection-update" uuid="6ca9014e-f39d-4935-b8b5-b5e9b3a086cc" name="eth1" args="bridge-port.vlans,ipv4.dns,ipv4.routing-rules,ipv4.routes,ipv4.dns-search,ipv4.addresses,ipv4.method,ipv6.dns,ipv6.addr-gen-mode,ipv6.routing-rules,ipv6.routes,ipv6.dns-search,ipv6.addresses,ipv6.method,connection.master,connection.timestamp,connection.slave-type" pid=10515 uid=0 result="success"
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2381] audit: op="connection-update" uuid="6ff34640-86d9-49af-a1f8-c6961fa2a55f" name="eth2" args="bridge-port.vlans,ipv4.dns,ipv4.routing-rules,ipv4.routes,ipv4.dns-search,ipv4.addresses,ipv4.method,ipv6.dns,ipv6.addr-gen-mode,ipv6.routing-rules,ipv6.routes,ipv6.dns-search,ipv6.addresses,ipv6.method,connection.master,connection.slave-type" pid=10515 uid=0 result="success"
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2423] device (br6): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2435] device (br6): state change: unavailable -> disconnected (reason 'user-requested', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2441] device (br6): Activation: starting connection 'br6' (e1ed7c0f-0f4d-4219-afba-c07fc02cdd80)
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2441] audit: op="connection-activate" uuid="e1ed7c0f-0f4d-4219-afba-c07fc02cdd80" name="br6" pid=10515 uid=0 result="success"
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2444] device (eth1): Activation: starting connection 'eth1' (6ca9014e-f39d-4935-b8b5-b5e9b3a086cc)
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2446] device (eth2): Activation: starting connection 'eth2' (6ff34640-86d9-49af-a1f8-c6961fa2a55f)
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2446] device (br6): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2454] device (br6): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2458] device (eth1): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2463] device (eth1): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2467] device (eth2): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2470] device (eth2): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2474] device (br6): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.2478] device (eth1): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.4068] device (br6): attached bridge port eth1
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.4068] device (eth1): Activation: connection 'eth1' enslaved, continuing activation
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.4074] device (eth2): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.5665] device (br6): attached bridge port eth2
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.5665] device (eth2): Activation: connection 'eth2' enslaved, continuing activation
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.5670] device (br6): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.5674] device (eth1): state change: ip-config -> deactivating (reason 'new-activation', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.7222] device (br6): detached bridge port eth1
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.7223] device (eth1): released from master device br6
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.7229] device (eth1): disconnecting for new activation request.
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.7229] audit: op="connection-activate" uuid="6ca9014e-f39d-4935-b8b5-b5e9b3a086cc" name="eth1" pid=10515 uid=0 result="success"
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.7235] device (eth2): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.7238] device (br6): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.7241] device (br6): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.7245] device (br6): Activation: successful, device activated.
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.7250] device (eth2): state change: ip-check -> deactivating (reason 'new-activation', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8935] device (br6): detached bridge port eth2
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8936] device (eth2): released from master device br6
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8955] device (eth2): disconnecting for new activation request.
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8956] audit: op="connection-activate" uuid="6ff34640-86d9-49af-a1f8-c6961fa2a55f" name="eth2" pid=10515 uid=0 result="success"
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8957] device (eth1): state change: deactivating -> disconnected (reason 'new-activation', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8963] device (eth1): Activation: starting connection 'eth1' (6ca9014e-f39d-4935-b8b5-b5e9b3a086cc)
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8965] device (eth2): state change: deactivating -> disconnected (reason 'new-activation', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8974] device (eth2): Activation: starting connection 'eth2' (6ff34640-86d9-49af-a1f8-c6961fa2a55f)
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8990] device (eth1): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8992] device (eth1): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8994] device (eth2): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8996] device (eth2): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:30 node02 NetworkManager[5268]: <info>  [1678965270.8999] device (eth1): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.0842] device (br6): attached bridge port eth1
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.0844] device (eth1): Activation: connection 'eth1' enslaved, continuing activation
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.0848] device (eth2): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.2498] device (br6): attached bridge port eth2
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.2498] device (eth2): Activation: connection 'eth2' enslaved, continuing activation
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.2506] device (eth1): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.2511] device (eth2): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.2519] device (eth1): state change: ip-check -> deactivating (reason 'user-requested', sys-iface-state: 'managed')
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.4074] device (br6): detached bridge port eth1
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.4074] device (eth1): released from master device br6
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.4079] audit: op="connection-deactivate" uuid="6ca9014e-f39d-4935-b8b5-b5e9b3a086cc" name="eth1" pid=10515 uid=0 result="success"
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.4080] device (eth2): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.4081] device (eth2): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.4085] device (eth2): Activation: successful, device activated.
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.4108] device (eth1): state change: deactivating -> disconnected (reason 'user-requested', sys-iface-state: 'managed')
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.4121] device (eth2): state change: activated -> deactivating (reason 'user-requested', sys-iface-state: 'managed')
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.5719] device (br6): detached bridge port eth2
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.5720] device (eth2): released from master device br6
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.5725] audit: op="connection-deactivate" uuid="6ff34640-86d9-49af-a1f8-c6961fa2a55f" name="eth2" pid=10515 uid=0 result="success"
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.5732] device (eth2): state change: deactivating -> disconnected (reason 'user-requested', sys-iface-state: 'managed')
Mar 16 11:14:31 node02 NetworkManager[5268]: <info>  [1678965271.5759] audit: op="checkpoint-adjust-rollback-timeout" arg="/org/freedesktop/NetworkManager/Checkpoint/18" pid=10515 uid=0 result="success"
Mar 16 11:14:32 node02 NetworkManager[5268]: <info>  [1678965272.6244] audit: op="checkpoint-adjust-rollback-timeout" arg="/org/freedesktop/NetworkManager/Checkpoint/18" pid=10515 uid=0 result="success"
Mar 16 11:14:33 node02 NetworkManager[5268]: <info>  [1678965273.6628] audit: op="checkpoint-adjust-rollback-timeout" arg="/org/freedesktop/NetworkManager/Checkpoint/18" pid=10515 uid=0 result="success"
Mar 16 11:14:34 node02 NetworkManager[5268]: <info>  [1678965274.6899] audit: op="checkpoint-adjust-rollback-timeout" arg="/org/freedesktop/NetworkManager/Checkpoint/18" pid=10515 uid=0 result="success"
Mar 16 11:14:35 node02 NetworkManager[5268]: <info>  [1678965275.7178] audit: op="checkpoint-adjust-rollback-timeout" arg="/org/freedesktop/NetworkManager/Checkpoint/18" pid=10515 uid=0 result="success"
Mar 16 11:14:36 node02 NetworkManager[5268]: <info>  [1678965276.7453] audit: op="checkpoint-adjust-rollback-timeout" arg="/org/freedesktop/NetworkManager/Checkpoint/18" pid=10515 uid=0 result="success"
Comment 1 Gris Ge 2023-03-20 05:03:15 UTC 
This might be duplicate report of https://bugzilla.redhat.com/show_bug.cgi?id=2177592

Please use `dnf copr enable packit/nmstate-nmstate-2280 ` to check whether it fix your problem.

Thanks!
Comment 2 Quique Llorente 2023-03-21 11:40:13 UTC 
(In reply to Gris Ge from comment #1)
> This might be duplicate report of
> https://bugzilla.redhat.com/show_bug.cgi?id=2177592
> 
> Please use `dnf copr enable packit/nmstate-nmstate-2280 ` to check whether
> it fix your problem.
> 
> Thanks!

With the copr we don't suffer from massive failures anymore, there is one error but it's not related I think.
Comment 3 Quique Llorente 2023-03-22 07:31:26 UTC 
Confirmed that it really fix the issue, QE this.
Comment 4 Gris Ge 2023-03-22 07:34:13 UTC 

*** This bug has been marked as a duplicate of bug 2177592 ***
Note You need to log in before you can comment on or make changes to this bug.