Neutron Port creation fails with postgresql on centos- H2 staging

[Ashok kumaran B]

Hello ,

When using postgresql as sql backend, port creation seems failing

Client debug log http://paste.openstack.org/show/44875/

Server side log http://paste.openstack.org/show/44876/

The following patch https://review.openstack.org/#/c/36426/ was applied already however issue didnt seem to be resolved.

-Ashok

[Ashok kumaran B (ashokkumaran-b)]

Additional info

root@testopenstack2 ~]# neutron port-list
+--------------------------------------+------+-------------------+------------------------------------------------------------------------------------+
| id | name | mac_address | fixed_ips |
+--------------------------------------+------+-------------------+------------------------------------------------------------------------------------+
| d428cf54-e73a-47bb-97f7-5575c2ab2cb2 | | fa:16:3e:b2:74:52 | {"subnet_id": "247c4d3e-39d7-4ac2-8cb6-25cabd1c91f3", "ip_address": "172.16.21.2"} |
| f1e73585-8b28-43bf-830f-88f8989f4951 | | fa:16:3e:b6:1e:19 | {"subnet_id": "b90a02fd-fea5-4b7b-8eb3-70c94215a376", "ip_address": "172.16.20.3"} |
+--------------------------------------+------+-------------------+------------------------------------------------------------------------------------+
[root@testopenstack2 ~]# neutron net-list
which: no gedit in (/usr/lib64/qt-3.3/bin:/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/root/bin)
which: no kate in (/usr/lib64/qt-3.3/bin:/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/root/bin)
+--------------------------------------+-------+-----------------------------------------------------+
| id | name | subnets |
+--------------------------------------+-------+-----------------------------------------------------+
| 7b857042-d47e-4b80-aad2-02db3fdaadfa | test1 | 247c4d3e-39d7-4ac2-8cb6-25cabd1c91f3 172.16.21.0/24 |
| aa626552-79d8-494d-8838-9054cd2075a2 | test | b90a02fd-fea5-4b7b-8eb3-70c94215a376 172.16.20.0/24 |
+--------------------------------------+-------+-----------------------------------------------------+
[root@testopenstack2 ~]# neutron subnet-list
+--------------------------------------+------+----------------+--------------------------------------------------+
| id | name | cidr | allocation_pools |
+--------------------------------------+------+----------------+--------------------------------------------------+
| b90a02fd-fea5-4b7b-8eb3-70c94215a376 | | 172.16.20.0/24 | {"start": "172.16.20.2", "end": "172.16.20.254"} |
| 247c4d3e-39d7-4ac2-8cb6-25cabd1c91f3 | | 172.16.21.0/24 | {"start": "172.16.21.2", "end": "172.16.21.254"} |
+--------------------------------------+------+----------------+--------------------------------------------------+
[root@testopenstack2 ~]# neutron subnet-show 247c4d3e-39d7-4ac2-8cb6-25cabd1c91f3

+------------------+--------------------------------------------------+
| Field | Value |
+------------------+--------------------------------------------------+
| allocation_pools | {"start": "172.16.21.2", "end": "172.16.21.254"} |
| cidr | 172.16.21.0/24 |
| dns_nameservers | |
| enable_dhcp | True ...

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/43305

[Ashok kumaran B (ashokkumaran-b)]

Few more observations.
whenever I create a new network and a subnet, port creation happens for first time, further port creation request fails. sometimes intermittently creation and deletion succeeds.

[Jian Wen (wenjianhn)]

I didn't reproduce it by creating new ports.
When I delete a port it also raises NotSupportedError.

Ubuntu 12.04

devstack
enable_service postgresql
disable_service mysql

2013-08-23 05:13:53.226 28038 ERROR neutron.api.v2.resource [-] delete failed
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource Traceback (most recent call last):
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/api/v2/resource.py", line 84, in resource
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource result = method(request=request, **args)
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/api/v2/base.py", line 432, in delete
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource obj_deleter(request.context, id, **kwargs)
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/plugins/openvswitch/ovs_neutron_plugin.py", line 585, in delete_port
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource super(OVSNeutronPluginV2, self).delete_port(context, id)
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/db/db_base_plugin_v2.py", line 1366, in delete_port
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource self._delete_port(context, id)
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/db/db_base_plugin_v2.py", line 1384, in _delete_port
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource a['ip_address'])
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/db/db_base_plugin_v2.py", line 320, in _recycle_ip
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource for allocation_pool in allocation_pools:
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2227, in __iter__
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource return self._execute_and_instances(context)
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2242, in _execute_and_instances
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource result = conn.execute(querycontext.statement, self._params)
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1449, in execute
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource params)
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1584, in _execute_clauseelement
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource compiled_sql, distilled_params
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1698, in _execute_context
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource context)
2013-08-23 05:13:53.226 28038 TRACE neutron.api.v2.resource File "/usr...

[Ashok kumaran B (ashokkumaran-b)]

Jian,
I had even tested this in ubuntu , creation of ports does fails sometimes there also, however as you said delete gets into trouble most of the times, which I have observed.

Check the below logs which was taken from Ubuntu 12.04, I also mentioned the nova-compute logs where you can see that instance is unable to spawn since it is unable to create the port on neutron(neutron exception).

http://paste.openstack.org/show/44995/

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/43410

[Jian Wen (wenjianhn)]

_recycle_expired_ip_allocations was removed by commit d983228
So when I create a new port in a devstack enviroment, neutron server won't call _recycle_ip.
When I delete a port, neutron server call _recycle_ip and it raises NotSupportedError.

[Mark McClain (markmcclain)]

Actual review is here: https://review.openstack.org/#/c/43305/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/43305
Committed: http://github.com/openstack/neutron/commit/e43c5c1ea6441ad7d36e25bd283a5a580bf5cb09
Submitter: Jenkins
Branch: master

commit e43c5c1ea6441ad7d36e25bd283a5a580bf5cb09
Author: Eugene Nikanorov <email address hidden>
Date: Thu Aug 22 19:08:34 2013 +0400

    Fix port creation issue appeared with postgresql backend

    IPAllocationPool has relation to IPAvailabilityRange which is setup to
    load eagerly. Eager loading is implemented with left outer join which is
    incompatible with with_lockmode('update') on postgresql.
    The fix redefines eager loading with options(joinedload) making it use
    inner join.

    fixes bug 1215350

    Change-Id: I148d37f2a1c2a340327d36c240eb8173aee9219a