Bug 1867016

Summary: Got no callback for `NM.ActiveConnection.deactivate_connection_async()` when deactivating 100 profiles at once
Product: Red Hat Enterprise Linux 8 Reporter: Gris Ge <fge>
Component: NetworkManagerAssignee: Beniamino Galvani <bgalvani>
Status: CLOSED NOTABUG QA Contact: Desktop QE <desktop-qa-list>
Severity: medium Docs Contact:
Priority: medium    
Version: 8.3CC: acardace, atragler, bgalvani, lrintel, rkhan, sukulkar, thaller, till
Target Milestone: rc   
Target Release: 8.4   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-09-01 14:55:43 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1738136    
Attachments:
Description Flags
300.yml
none
300_absent.yml
none
System logs with NM trace enabled none

Description Gris Ge 2020-08-07 07:10:39 UTC 
Description of problem:

Got no callback after invoked `deactivate_connection_async()` when deactivating
100 profiles at one batch.


Version-Release number of selected component (if applicable):
NetworkManager-1.26.0-0.2.el8.x86_64
nmstate-0.3.4-9.el8.noarch

How reproducible:
100%

Steps to Reproduce:
1. sudo nmstatectl set 300.yml
2. wait 1 minute for STP to finish.
3. sudo nmstatectl set 300_absent.yml

Actual results:

Nmstate complain about timeout on deactivating a dummy profile.

Expected results:

No failure.

Additional info:

The network layout is: dummy0, 300 vlan over dummy0, 300 bridge over each vlan.

In nmstate, only 100 profile deactivation is sent in one batch and nmstate will
wait till all 100 finished to continue on remaining.

By changing dummy0 to veth or real NIC, no such problem.
Comment 1 Gris Ge 2020-08-07 07:11:14 UTC 
Created attachment 1710746 [details]
300.yml
Comment 2 Gris Ge 2020-08-07 07:11:38 UTC 
Created attachment 1710747 [details]
300_absent.yml
Comment 3 Gris Ge 2020-08-07 07:21:07 UTC 
The script `gen_state.py` in https://bugzilla.redhat.com/show_bug.cgi?id=1866269 could be used to generate yml file for nmstatectl to set.
Comment 4 Gris Ge 2020-08-07 07:59:53 UTC 
Created attachment 1710756 [details]
System logs with NM trace enabled
Comment 5 Gris Ge 2020-08-07 08:08:29 UTC 
The error for above logs is:

libnmstate.error.NmstateTimeoutError: Action {'Deactivate profile: dummy0.279'} timeout
Comment 6 Beniamino Galvani 2020-08-07 11:39:06 UTC 
I have added a debug print in nmstate before calling
client.deactivate_connection_async() and one in the callback. I see
them both in the output, meaning that the callback was
invoked:

  2020-08-07 13:27:23,081 root         DEBUG    #### deactivate_connection_async: dummy0.279
  ...
  2020-08-07 13:27:23,186 root         DEBUG    Async queue(100) full, waiting all existing actions to be finished before registering more async action
  2020-08-07 13:27:25,410 root         DEBUG    #### callback: dummy0.279
  2020-08-07 13:27:25,410 root         DEBUG    Connection is not active on dummy0.279, no need to deactivate

Then nmstate fails with:

  libnmstate.error.NmstateTimeoutError: Action {'Deactivate profile: dummy0.279'} timeout

I think NM is behaving correctly in this case and perhaps
nmstate is forgetting to cancel the timer for dummy0.279?
Comment 7 Gris Ge 2020-09-01 14:55:43 UTC 
Confirmed. Not a bug of NM.

Nmstate is ignoring that callback.

Sorry for the troubles.