Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1779138

Summary: Add additional debug logging for neutron OVN/ML2 trunk deletion
Product: Red Hat OpenStack Reporter: Andreas Karis <akaris>
Component: openstack-neutronAssignee: Nate Johnston <nate.johnston>
Status: CLOSED ERRATA QA Contact: Eran Kuris <ekuris>
Severity: medium Docs Contact:
Priority: medium    
Version: 13.0 (Queens)CC: amuller, chrisw, jraju, lmartins, nate.johnston, scohen
Target Milestone: z12Keywords: Triaged, ZStream
Target Release: 13.0 (Queens)   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: openstack-neutron-12.1.1-7.el7ost Doc Type: No Doc Update
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-06-24 11:53:05 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:

Description Andreas Karis 2019-12-03 11:50:45 UTC
Description of problem:
Please add additional debug logging for neutron OVN/ML2

neutron logs with OVN contain barely any useful information. Take the case in the "Additional info" field. Trunk deletion just prints a "409". There's no indication why this is happening. We need way more detailed debug and info logging. As you can see from the below, in the logs, we cannot even see the "Trunk 09d352d7-ef24-435b-bff5-820fa2a868f7 is currently in use" message. Also, I'd expect that neutron shows me how the port is used (e.g. bound to an instance). At the bare minimum, I'd expect neutron to point to the OVN message or nova API call etc. that indicates that the port is bound if this issue is being reported by another component.

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


How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

~~~
(overcloud) [stack@undercloud-0 ~]$ openstack port create --network private-mgmt trunk1
(overcloud) [stack@undercloud-0 ~]$ openstack port create --network private1 --mac-address fa:16:3e:1d:f4:43 trunk1-vlan100
(overcloud) [stack@undercloud-0 ~]$ openstack port create --network private2 --mac-address fa:16:3e:1d:f4:43 trunk1-vlan200
(overcloud) [stack@undercloud-0 ~]$ openstack network trunk create --parent-port trunk1 trunk1
+-----------------+--------------------------------------+
| Field           | Value                                |
+-----------------+--------------------------------------+
| admin_state_up  | UP                                   |
| created_at      | 2019-12-03T11:30:16Z                 |
| description     |                                      |
| id              | 09d352d7-ef24-435b-bff5-820fa2a868f7 |
| name            | trunk1                               |
| port_id         | 5a4b2dbe-23c9-4eb6-922c-529f945fe68b |
| project_id      | 64e818c8843f4874852c28d09ab4110e     |
| revision_number | 1                                    |
| status          | ACTIVE                               |
| sub_ports       |                                      |
| tags            | []                                   |
| tenant_id       | 64e818c8843f4874852c28d09ab4110e     |
| updated_at      | 2019-12-03T11:30:16Z                 |
+-----------------+--------------------------------------+
(overcloud) [stack@undercloud-0 ~]$ openstack network trunk set --subport port=trunk1-vlan100,segmentation-type=vlan,segmentation-id=100 trunk1

(overcloud) [stack@undercloud-0 ~]$ 
(overcloud) [stack@undercloud-0 ~]$ openstack network trunk set --subport port=trunk1-vlan200,segmentation-type=vlan,segmentation-id=200 trunk1
(overcloud) [stack@undercloud-0 ~]$ openstack server add port rhel-test1 5a4b2dbe-23c9-4eb6-922c-529f945fe68b
~~~

Enabled debugging with:
https://access.redhat.com/solutions/3275771

~~~
(overcloud) [stack@undercloud-0 ~]$ openstack --debug network trunk delete trunk1
(...)
DELETE call to network for http://172.16.0.106:9696/v2.0/trunks/09d352d7-ef24-435b-bff5-820fa2a868f7 used request id req-42e387a8-b04a-4e4f-888e-6613c3f7cd3a
Error message: {"NeutronError": {"message": "Trunk 09d352d7-ef24-435b-bff5-820fa2a868f7 is currently in use.", "type": "TrunkInUse", "detail": ""}}
Failed to delete trunk with name or ID 'trunk1': Trunk 09d352d7-ef24-435b-bff5-820fa2a868f7 is currently in use.
Neutron server returns request_ids: ['req-42e387a8-b04a-4e4f-888e-6613c3f7cd3a']
1 of 1 trunks failed to delete.
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/cliff/app.py", line 400, in run_subcommand
    result = cmd.run(parsed_args)
  File "/usr/lib/python2.7/site-packages/osc_lib/command/command.py", line 41, in run
    return super(Command, self).run(parsed_args)
  File "/usr/lib/python2.7/site-packages/cliff/command.py", line 184, in run
    return_code = self.take_action(parsed_args) or 0
  File "/usr/lib/python2.7/site-packages/neutronclient/osc/v2/trunk/network_trunk.py", line 124, in take_action
    raise exceptions.CommandError(msg)
CommandError: 1 of 1 trunks failed to delete.
clean_up DeleteNetworkTrunk: 1 of 1 trunks failed to delete.
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/osc_lib/shell.py", line 134, in run
    ret_val = super(OpenStackShell, self).run(argv)
  File "/usr/lib/python2.7/site-packages/cliff/app.py", line 279, in run
    result = self.run_subcommand(remainder)
  File "/usr/lib/python2.7/site-packages/osc_lib/shell.py", line 169, in run_subcommand
    ret_value = super(OpenStackShell, self).run_subcommand(argv)
  File "/usr/lib/python2.7/site-packages/cliff/app.py", line 400, in run_subcommand
    result = cmd.run(parsed_args)
  File "/usr/lib/python2.7/site-packages/osc_lib/command/command.py", line 41, in run
    return super(Command, self).run(parsed_args)
  File "/usr/lib/python2.7/site-packages/cliff/command.py", line 184, in run
    return_code = self.take_action(parsed_args) or 0
  File "/usr/lib/python2.7/site-packages/neutronclient/osc/v2/trunk/network_trunk.py", line 124, in take_action
    raise exceptions.CommandError(msg)
CommandError: 1 of 1 trunks failed to delete.

END return value: 1
~~~

But in the logs, the only trace that we see:
~~~
[root@overcloud-controller-0 ~]# grep 09d352d7-ef24-435b-bff5-820fa2a868f7 /var/log/containers/neutron/ -R
/var/log/containers/neutron/server.log:2019-12-03 11:30:39.225 32 INFO neutron.wsgi [req-beaec9b4-dc56-4d09-b141-c8909310e4d6 e98511aae5b04531a755eb84e5c8d6b0 64e818c8843f4874852c28d09ab4110e - default default] 172.17.0.18 "PUT /v2.0/trunks/09d352d7-ef24-435b-bff5-820fa2a868f7 HTTP/1.1" status: 200  len: 590 time: 0.3845000
/var/log/containers/neutron/server.log:2019-12-03 11:30:49.407 30 INFO neutron.wsgi [req-bbb69b10-a1f5-49ce-a366-53a4f37e0e1d e98511aae5b04531a755eb84e5c8d6b0 64e818c8843f4874852c28d09ab4110e - default default] 172.17.0.18 "PUT /v2.0/trunks/09d352d7-ef24-435b-bff5-820fa2a868f7/add_subports HTTP/1.1" status: 200  len: 787 time: 1.7547321
[root@overcloud-controller-0 ~]# 
~~~

~~~
[root@overcloud-controller-1 neutron]#  grep 09d352d7-ef24-435b-bff5-820fa2a868f7 /var/log/containers/neutron/ -R
/var/log/containers/neutron/server.log:2019-12-03 11:30:47.177 29 INFO neutron.wsgi [req-0b826e6e-a55c-4d01-992f-e027075dfb95 e98511aae5b04531a755eb84e5c8d6b0 64e818c8843f4874852c28d09ab4110e - default default] 172.17.0.18 "PUT /v2.0/trunks/09d352d7-ef24-435b-bff5-820fa2a868f7 HTTP/1.1" status: 200  len: 694 time: 0.3796430
/var/log/containers/neutron/server.log:2019-12-03 11:32:36.740 30 INFO neutron.wsgi [req-42e387a8-b04a-4e4f-888e-6613c3f7cd3a e98511aae5b04531a755eb84e5c8d6b0 64e818c8843f4874852c28d09ab4110e - default default] 172.17.0.18 "DELETE /v2.0/trunks/09d352d7-ef24-435b-bff5-820fa2a868f7 HTTP/1.1" status: 409  len: 313 time: 0.5599408
~~~

~~~
[root@overcloud-controller-2 ~]#  grep 09d352d7-ef24-435b-bff5-820fa2a868f7 /var/log/containers/neutron/ -R
/var/log/containers/neutron/server.log:2019-12-03 11:30:42.032 30 INFO neutron.wsgi [req-248f9d11-787c-426b-b6d3-2dc3a20f8dc3 e98511aae5b04531a755eb84e5c8d6b0 64e818c8843f4874852c28d09ab4110e - default default] 172.17.0.18 "PUT /v2.0/trunks/09d352d7-ef24-435b-bff5-820fa2a868f7/add_subports HTTP/1.1" status: 200  len: 681 time: 2.4018731
~~~

~~~
[root@overcloud-controller-0 ~]# grep req-42e387a8-b04a-4e4f-888e-6613c3f7cd3a /var/log/containers/neutron/ -R
[root@overcloud-controller-0 ~]# 
~~~

~~~
[root@overcloud-controller-2 ~]# grep req-42e387a8-b04a-4e4f-888e-6613c3f7cd3a /var/log/containers/neutron/ -R
[root@overcloud-controller-2 ~]# 
~~~

~~~
[root@overcloud-controller-1 neutron]#  grep 09d352d7-ef24-435b-bff5-820fa2a868f7 /var/log/containers/neutron/ -R
/var/log/containers/neutron/server.log:2019-12-03 11:30:47.177 29 INFO neutron.wsgi [req-0b826e6e-a55c-4d01-992f-e027075dfb95 e98511aae5b04531a755eb84e5c8d6b0 64e818c8843f4874852c28d09ab4110e - default default] 172.17.0.18 "PUT /v2.0/trunks/09d352d7-ef24-435b-bff5-820fa2a868f7 HTTP/1.1" status: 200  len: 694 time: 0.3796430
/var/log/containers/neutron/server.log:2019-12-03 11:32:36.740 30 INFO neutron.wsgi [req-42e387a8-b04a-4e4f-888e-6613c3f7cd3a e98511aae5b04531a755eb84e5c8d6b0 64e818c8843f4874852c28d09ab4110e - default default] 172.17.0.18 "DELETE /v2.0/trunks/09d352d7-ef24-435b-bff5-820fa2a868f7 HTTP/1.1" status: 409  len: 313 time: 0.5599408
[root@overcloud-controller-1 neutron]# 
~~~

And these are the lines from the server.log around the 409 above:
~~~
~~~
2019-12-03 11:32:35.013 28 INFO neutron.wsgi [req-f009b4b1-b9d1-42df-a237-a89049b1005a d103d1c460b9412dab870e29504da2d5 5090d7700d0d48839bb169009cbae05b - default default] 172.17.0.16 "GET /v2.0/floatingips?fixed_ip_address=2000%3A192%3A168%3A10%3Af816%3A3eff%3Afe1d%3Af443&port_id=5a4b2dbe-23c9-4eb6-922c-529f945fe68b HTTP/1.1" status: 200  len: 193 time: 1.3354280
2019-12-03 11:32:35.205 31 DEBUG neutron.wsgi [-] (31) accepted ('172.17.0.16', 46358) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:35.279 31 INFO neutron.wsgi [req-f0e05840-7537-4937-8e74-a381dc01316e d103d1c460b9412dab870e29504da2d5 5090d7700d0d48839bb169009cbae05b - default default] 172.17.0.16 "GET /v2.0/ports?network_id=f41c59e3-f5b3-4b49-912a-90044ed94a81&device_owner=network%3Adhcp HTTP/1.1" status: 200  len: 1425 time: 0.0727589
2019-12-03 11:32:36.138 37 DEBUG networking_ovn.ovn_db_sync [-] Starting OVN-Northbound DB sync process do_sync /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:86
2019-12-03 11:32:36.139 37 DEBUG networking_ovn.ovn_db_sync [req-2fe6731d-c779-4979-abd4-b0d76b15475d - - - - -] Address-Set-SYNC: started @ 2019-12-03 11:32:36.139009 sync_address_sets /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:245
2019-12-03 11:32:36.147 37 DEBUG networking_ovn.ovn_db_sync [-] Starting OVN-Southbound DB sync process do_sync /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:1212
2019-12-03 11:32:36.147 37 DEBUG networking_ovn.ovn_db_sync [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] OVN-SB Sync hostname and physical networks started sync_hostname_and_physical_networks /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:1220
2019-12-03 11:32:36.165 37 DEBUG networking_ovn.ovn_db_sync [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Host overcloud-compute-2.localdomain found both in OVN SB DB and Neutron. Trigger updating its SegmentHostMapping in Neutron, to keep OVN SB DB and Neutron have consistent data sync_hostname_and_physical_networks /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:
1242
2019-12-03 11:32:36.179 30 DEBUG neutron.wsgi [-] (30) accepted ('172.17.0.18', 43842) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:36.239 37 DEBUG oslo_concurrency.lockutils [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Lock "update_segment_host_mapping" acquired by "neutron.services.segments.db.update_segment_host_mapping" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
2019-12-03 11:32:36.298 37 DEBUG oslo_concurrency.lockutils [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Lock "update_segment_host_mapping" released by "neutron.services.segments.db.update_segment_host_mapping" :: held 0.058s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
2019-12-03 11:32:36.298 37 DEBUG networking_ovn.ovn_db_sync [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Host overcloud-compute-1.localdomain found both in OVN SB DB and Neutron. Trigger updating its SegmentHostMapping in Neutron, to keep OVN SB DB and Neutron have consistent data sync_hostname_and_physical_networks /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:
1242
2019-12-03 11:32:36.376 37 DEBUG oslo_concurrency.lockutils [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Lock "update_segment_host_mapping" acquired by "neutron.services.segments.db.update_segment_host_mapping" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
2019-12-03 11:32:36.395 37 DEBUG oslo_concurrency.lockutils [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Lock "update_segment_host_mapping" released by "neutron.services.segments.db.update_segment_host_mapping" :: held 0.019s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
2019-12-03 11:32:36.395 37 DEBUG networking_ovn.ovn_db_sync [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Host overcloud-controller-0.localdomain found both in OVN SB DB and Neutron. Trigger updating its SegmentHostMapping in Neutron, to keep OVN SB DB and Neutron have consistent data sync_hostname_and_physical_networks /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:1242
2019-12-03 11:32:36.431 37 DEBUG networking_ovn.ovn_db_sync [req-2fe6731d-c779-4979-abd4-b0d76b15475d - - - - -] Address_Sets added 0, removed 0, updated 0 sync_address_sets /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:283
2019-12-03 11:32:36.432 37 DEBUG networking_ovn.ovn_db_sync [req-2fe6731d-c779-4979-abd4-b0d76b15475d - - - - -] OVN-NB Sync networks, ports and DHCP options started sync_networks_ports_and_dhcp_opts /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:956
2019-12-03 11:32:36.446 37 DEBUG oslo_concurrency.lockutils [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Lock "update_segment_host_mapping" acquired by "neutron.services.segments.db.update_segment_host_mapping" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
2019-12-03 11:32:36.508 30 WARNING oslo_config.cfg [req-42e387a8-b04a-4e4f-888e-6613c3f7cd3a e98511aae5b04531a755eb84e5c8d6b0 64e818c8843f4874852c28d09ab4110e - default default] Option "rabbit_port" from group "oslo_messaging_rabbit" is deprecated for removal (Replaced by [DEFAULT]/transport_url).  Its value may be silently ignored in the future.
2019-12-03 11:32:36.508 30 WARNING oslo_config.cfg [req-42e387a8-b04a-4e4f-888e-6613c3f7cd3a e98511aae5b04531a755eb84e5c8d6b0 64e818c8843f4874852c28d09ab4110e - default default] Option "rabbit_userid" from group "oslo_messaging_rabbit" is deprecated for removal (Replaced by [DEFAULT]/transport_url).  Its value may be silently ignored in the future.
2019-12-03 11:32:36.509 30 WARNING oslo_config.cfg [req-42e387a8-b04a-4e4f-888e-6613c3f7cd3a e98511aae5b04531a755eb84e5c8d6b0 64e818c8843f4874852c28d09ab4110e - default default] Option "rabbit_password" from group "oslo_messaging_rabbit" is deprecated for removal (Replaced by [DEFAULT]/transport_url).  Its value may be silently ignored in the future.
2019-12-03 11:32:36.525 37 DEBUG oslo_concurrency.lockutils [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Lock "update_segment_host_mapping" released by "neutron.services.segments.db.update_segment_host_mapping" :: held 0.078s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
2019-12-03 11:32:36.525 37 DEBUG networking_ovn.ovn_db_sync [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Host overcloud-controller-1.localdomain found both in OVN SB DB and Neutron. Trigger updating its SegmentHostMapping in Neutron, to keep OVN SB DB and Neutron have consistent data sync_hostname_and_physical_networks /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:1242
2019-12-03 11:32:36.556 31 DEBUG neutron.wsgi [-] (31) accepted ('172.17.0.16', 46444) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:36.558 31 INFO neutron.wsgi [-] 172.17.0.16 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0013630
2019-12-03 11:32:36.561 31 DEBUG neutron.wsgi [-] (31) accepted ('172.17.0.10', 59874) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:36.563 31 INFO neutron.wsgi [-] 172.17.0.10 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0012209
2019-12-03 11:32:36.566 31 DEBUG neutron.wsgi [-] (31) accepted ('172.17.0.18', 43864) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:36.567 31 INFO neutron.wsgi [-] 172.17.0.18 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0010240
2019-12-03 11:32:36.592 37 DEBUG oslo_concurrency.lockutils [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Lock "update_segment_host_mapping" acquired by "neutron.services.segments.db.update_segment_host_mapping" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
2019-12-03 11:32:36.614 37 DEBUG oslo_concurrency.lockutils [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Lock "update_segment_host_mapping" released by "neutron.services.segments.db.update_segment_host_mapping" :: held 0.023s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
2019-12-03 11:32:36.615 37 DEBUG networking_ovn.ovn_db_sync [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Host overcloud-controller-2.localdomain found both in OVN SB DB and Neutron. Trigger updating its SegmentHostMapping in Neutron, to keep OVN SB DB and Neutron have consistent data sync_hostname_and_physical_networks /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:1242
2019-12-03 11:32:36.681 37 DEBUG oslo_concurrency.lockutils [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Lock "update_segment_host_mapping" acquired by "neutron.services.segments.db.update_segment_host_mapping" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
2019-12-03 11:32:36.701 37 DEBUG oslo_concurrency.lockutils [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Lock "update_segment_host_mapping" released by "neutron.services.segments.db.update_segment_host_mapping" :: held 0.020s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
2019-12-03 11:32:36.702 37 DEBUG networking_ovn.ovn_db_sync [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Host overcloud-compute-0.localdomain found both in OVN SB DB and Neutron. Trigger updating its SegmentHostMapping in Neutron, to keep OVN SB DB and Neutron have consistent data sync_hostname_and_physical_networks /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:1242
2019-12-03 11:32:36.738 30 INFO neutron.api.v2.resource [req-42e387a8-b04a-4e4f-888e-6613c3f7cd3a e98511aae5b04531a755eb84e5c8d6b0 64e818c8843f4874852c28d09ab4110e - default default] delete failed (client error): There was a conflict when trying to complete your request.
2019-12-03 11:32:36.740 30 INFO neutron.wsgi [req-42e387a8-b04a-4e4f-888e-6613c3f7cd3a e98511aae5b04531a755eb84e5c8d6b0 64e818c8843f4874852c28d09ab4110e - default default] 172.17.0.18 "DELETE /v2.0/trunks/09d352d7-ef24-435b-bff5-820fa2a868f7 HTTP/1.1" status: 409  len: 313 time: 0.5599408
2019-12-03 11:32:36.740 37 DEBUG oslo_concurrency.lockutils [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Lock "update_segment_host_mapping" acquired by "neutron.services.segments.db.update_segment_host_mapping" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
2019-12-03 11:32:36.794 37 DEBUG oslo_concurrency.lockutils [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Lock "update_segment_host_mapping" released by "neutron.services.segments.db.update_segment_host_mapping" :: held 0.054s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
2019-12-03 11:32:36.795 37 DEBUG networking_ovn.ovn_db_sync [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] OVN-SB Sync hostname and physical networks finished sync_hostname_and_physical_networks /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:1246
2019-12-03 11:32:36.970 37 DEBUG networking_ovn.ovn_db_sync [req-2fe6731d-c779-4979-abd4-b0d76b15475d - - - - -] OVN sync metadata ports started _sync_metadata_ports /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:900
2019-12-03 11:32:37.216 37 INFO networking_ovn.l3.l3_ovn [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Getting OvsdbSbOvnIdl
2019-12-03 11:32:37.227 37 INFO ovsdbapp.backend.ovs_idl.vlog [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] tcp:172.17.0.33:6642: connecting...
2019-12-03 11:32:37.228 37 INFO ovsdbapp.backend.ovs_idl.vlog [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] tcp:172.17.0.33:6642: connected
2019-12-03 11:32:37.248 37 INFO networking_ovn.l3.l3_ovn [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] Getting OvsdbNbOvnIdl
2019-12-03 11:32:37.259 37 INFO ovsdbapp.backend.ovs_idl.vlog [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] tcp:172.17.0.33:6641: connecting...
2019-12-03 11:32:37.259 37 INFO ovsdbapp.backend.ovs_idl.vlog [req-a4ad50a5-b26f-4c99-8f5e-9a5a781a2882 - - - - -] tcp:172.17.0.33:6641: connected
2019-12-03 11:32:37.642 37 DEBUG networking_ovn.ovn_db_sync [req-2fe6731d-c779-4979-abd4-b0d76b15475d - - - - -] OVN sync metadata ports finished _sync_metadata_ports /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:953
2019-12-03 11:32:37.643 37 DEBUG networking_ovn.ovn_db_sync [req-2fe6731d-c779-4979-abd4-b0d76b15475d - - - - -] OVN-NB Sync DHCP options for Neutron subnets started _sync_subnet_dhcp_options /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:763
2019-12-03 11:32:37.969 37 DEBUG networking_ovn.ovn_db_sync [req-2fe6731d-c779-4979-abd4-b0d76b15475d - - - - -] OVN-NB Sync DHCP options for Neutron subnets finished _sync_subnet_dhcp_options /usr/lib/python2.7/site-packages/networking_ovn/ovn_db_sync.py:826
2019-12-03 11:32:37.970 37 ERROR ovsdbapp.backend.ovs_idl.transaction [-] OVSDB Error: The transaction failed because the IDL has been configured to require a database lock but didn't get it yet or has already lost it: RuntimeError: OVSDB Error: The transaction failed because the IDL has been configured to require a database lock but didn't get it yet or has already lost it
2019-12-03 11:32:37.971 37 ERROR ovsdbapp.backend.ovs_idl.transaction [req-2fe6731d-c779-4979-abd4-b0d76b15475d - - - - -] Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/connection.py", line 122, in run
    txn.results.put(txn.do_commit())
  File "/usr/lib/python2.7/site-packages/ovsdbapp/backend/ovs_idl/transaction.py", line 115, in do_commit
    raise RuntimeError(msg)
RuntimeError: OVSDB Error: The transaction failed because the IDL has been configured to require a database lock but didn't get it yet or has already lost it

2019-12-03 11:32:38.560 31 DEBUG neutron.wsgi [-] (31) accepted ('172.17.0.16', 46568) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:38.563 31 INFO neutron.wsgi [-] 172.17.0.16 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0012698
2019-12-03 11:32:38.565 31 DEBUG neutron.wsgi [-] (31) accepted ('172.17.0.10', 60010) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:38.566 31 INFO neutron.wsgi [-] 172.17.0.10 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0009840
2019-12-03 11:32:38.569 28 DEBUG neutron.wsgi [-] (28) accepted ('172.17.0.18', 43978) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:38.571 28 INFO neutron.wsgi [-] 172.17.0.18 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0013680
2019-12-03 11:32:40.564 28 DEBUG neutron.wsgi [-] (28) accepted ('172.17.0.16', 46686) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:40.566 28 INFO neutron.wsgi [-] 172.17.0.16 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0012422
2019-12-03 11:32:40.567 31 DEBUG neutron.wsgi [-] (31) accepted ('172.17.0.10', 60122) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:40.569 31 INFO neutron.wsgi [-] 172.17.0.10 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0011852
2019-12-03 11:32:40.574 29 DEBUG neutron.wsgi [-] (29) accepted ('172.17.0.18', 44234) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:40.576 29 INFO neutron.wsgi [-] 172.17.0.18 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0013990
2019-12-03 11:32:42.568 28 DEBUG neutron.wsgi [-] (28) accepted ('172.17.0.16', 46984) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:42.570 29 DEBUG neutron.wsgi [-] (29) accepted ('172.17.0.10', 60244) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:42.571 28 INFO neutron.wsgi [-] 172.17.0.16 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0013270
2019-12-03 11:32:42.572 29 INFO neutron.wsgi [-] 172.17.0.10 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0010381
2019-12-03 11:32:42.578 29 DEBUG neutron.wsgi [-] (29) accepted ('172.17.0.18', 44366) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:883
2019-12-03 11:32:42.579 29 INFO neutron.wsgi [-] 172.17.0.18 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0009100
~~~


~~~

Comment 1 Andreas Karis 2019-12-03 11:51:56 UTC
[root@overcloud-controller-1 containers]# docker ps | grep neutron
7c910bce2a13        registry.access.redhat.com/rhosp13/openstack-neutron-server-ovn:13.0-92        "dumb-init --singl..."   4 days ago          Up 19 minutes (healthy)                       neutron_api

Comment 2 Andreas Karis 2019-12-03 12:00:43 UTC
I'm taking back my more generic request wrt OVN. I'd like to see more debug logging in this specific use case for deleting trunk ports, both for ML2-OVS and OVN:

~~~
[root@overcloud-controller-1 containers]# grep 'Trunk' /usr/lib/python2.7/site-packages/neutron -R | grep 'in use' -C2 -n
42-/usr/lib/python2.7/site-packages/neutron/services/trunk/exceptions.py:class PortInUseAsTrunkParent(n_exc.InUse):
43-/usr/lib/python2.7/site-packages/neutron/services/trunk/exceptions.py:class TrunkInUse(n_exc.InUse):
44:/usr/lib/python2.7/site-packages/neutron/services/trunk/exceptions.py:    message = _("Trunk %(trunk_id)s is currently in use.")
45-/usr/lib/python2.7/site-packages/neutron/services/trunk/exceptions.py:class TrunkDisabled(n_exc.Conflict):
46-/usr/lib/python2.7/site-packages/neutron/services/trunk/exceptions.py:    message = _("Trunk %(trunk_id)s is currently disabled.")
[root@overcloud-controller-1 containers]# 
~~~

~~~
[root@overcloud-controller-1 containers]# grep TrunkInUse /usr/lib/python2.7/site-packages/neutron/ -R
Binary file /usr/lib/python2.7/site-packages/neutron/services/trunk/plugin.pyc matches
Binary file /usr/lib/python2.7/site-packages/neutron/services/trunk/exceptions.pyo matches
/usr/lib/python2.7/site-packages/neutron/services/trunk/exceptions.py:class TrunkInUse(n_exc.InUse):
/usr/lib/python2.7/site-packages/neutron/services/trunk/plugin.py:                raise trunk_exc.TrunkInUse(trunk_id=trunk_id)
Binary file /usr/lib/python2.7/site-packages/neutron/services/trunk/plugin.pyo matches
Binary file /usr/lib/python2.7/site-packages/neutron/services/trunk/exceptions.pyc matches
~~~

~~~
/usr/lib/python2.7/site-packages/neutron/services/trunk/plugin.py
(...)
    261         """Delete the specified trunk."""
    262         with db_api.autonested_transaction(context.session):
    263             trunk = self._get_trunk(context, trunk_id)
    264             rules.trunk_can_be_managed(context, trunk)
    265             trunk_port_validator = rules.TrunkPortValidator(trunk.port_id)
    266             if not trunk_port_validator.is_bound(context):
    267                 # NOTE(status_police): when a trunk is deleted, the logical
    268                 # object disappears from the datastore, therefore there is no
    269                 # status transition involved. If PRECOMMIT failures occur,
    270                 # the trunk remains in the status where it was.
    271                 trunk.delete()
    272                 payload = callbacks.TrunkPayload(context, trunk_id,
    273                                                  original_trunk=trunk)
    274                 registry.notify(constants.TRUNK, events.PRECOMMIT_DELETE, self,
    275                                 payload=payload)
    276             else:
    277                 raise trunk_exc.TrunkInUse(trunk_id=trunk_id)
    278         registry.notify(constants.TRUNK, events.AFTER_DELETE, self,
    279                         payload=payload)
(...)

Comment 3 ffernand 2019-12-17 21:26:47 UTC
With the merge of https://bugzilla.redhat.com/show_bug.cgi?id=1765640 we have added logs that
display the addition and removal of trunk subports [0].


These logs are available on version python-networking-ovn-4.0.3-18.el7ost or newer.


Could you please let us know if that is enough and if not, what kind of information in the logs is
being required? Also, it may be better to have these log requirements done outside OVN, so it is
not dependent on a given ml2 provider.


[0]:  openstack/networking-ovn / networking_ovn/ml2/trunk_driver.py


    def _set_binding_profile(self, context, subport, parent_port, ovn_txn):
        LOG.debug("Setting parent %s for subport %s",
                  parent_port, subport.port_id)
 ...

   def _unset_binding_profile(self, context, subport, ovn_txn):
        LOG.debug("Unsetting parent for subport %s", subport.port_id)

 ...

Comment 4 Andreas Karis 2019-12-18 10:45:15 UTC
Looking at the file that I pointed to initially, this seems to be outside of OVN:
~~~
(undercloud) [stack@undercloud-0 ~]$ rpm -qf /usr/lib/python2.7/site-packages/neutron/services/trunk/plugin.py
python-neutron-12.1.0-2.el7ost.noarch
~~~

What I'd like to see is the following:

If a user tries to delete a trunk port that is still bound to an instance:
a) print the current error message that's returned to the API client in the logs as well. Note the following message is currently absent from the logs:
~~~
Error message: {"NeutronError": {"message": "Trunk 09d352d7-ef24-435b-bff5-820fa2a868f7 is currently in use.", "type": "TrunkInUse", "detail": ""}}
~~~
b) In both cases, logging the message to file and sending an error to the API cient, I'd like to see by whom the trunk is currently being used, e.g. instance xyz

Let me know if that's feasible or not.

Thanks,

Andreas

Comment 18 errata-xmlrpc 2020-06-24 11:53:05 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2020:2724