internal neutron server error on tempest VolumesActionsTest

Bug #1239637 reported by Attila Fazekas
38
This bug affects 8 people
Affects Status Importance Assigned to Milestone
neutron
High
Armando Migliaccio
Havana
High
Armando Migliaccio

Bug Description

Logstash query:
@message:"DBError: (IntegrityError) null value in column \"network_id\" violates not-null constraint" AND @fields.filename:"logs/screen-q-svc.txt"

http://logs.openstack.org/22/51522/2/check/check-tempest-devstack-vm-neutron-pg-isolated/015b3d9/logs/screen-q-svc.txt.gz#_2013-10-14_10_13_01_431
http://logs.openstack.org/22/51522/2/check/check-tempest-devstack-vm-neutron-pg-isolated/015b3d9/console.html

2013-10-14 10:16:28.034 | ======================================================================
2013-10-14 10:16:28.034 | FAIL: tearDownClass (tempest.api.volume.test_volumes_actions.VolumesActionsTest)
2013-10-14 10:16:28.035 | tearDownClass (tempest.api.volume.test_volumes_actions.VolumesActionsTest)
2013-10-14 10:16:28.035 | ----------------------------------------------------------------------
2013-10-14 10:16:28.035 | _StringException: Traceback (most recent call last):
2013-10-14 10:16:28.035 | File "tempest/api/volume/test_volumes_actions.py", line 55, in tearDownClass
2013-10-14 10:16:28.036 | super(VolumesActionsTest, cls).tearDownClass()
2013-10-14 10:16:28.036 | File "tempest/api/volume/base.py", line 72, in tearDownClass
2013-10-14 10:16:28.036 | cls.isolated_creds.clear_isolated_creds()
2013-10-14 10:16:28.037 | File "tempest/common/isolated_creds.py", line 453, in clear_isolated_creds
2013-10-14 10:16:28.037 | self._clear_isolated_net_resources()
2013-10-14 10:16:28.037 | File "tempest/common/isolated_creds.py", line 445, in _clear_isolated_net_resources
2013-10-14 10:16:28.038 | self._clear_isolated_network(network['id'], network['name'])
2013-10-14 10:16:28.038 | File "tempest/common/isolated_creds.py", line 399, in _clear_isolated_network
2013-10-14 10:16:28.038 | net_client.delete_network(network_id)
2013-10-14 10:16:28.038 | File "tempest/services/network/json/network_client.py", line 76, in delete_network
2013-10-14 10:16:28.039 | resp, body = self.delete(uri, self.headers)
2013-10-14 10:16:28.039 | File "tempest/common/rest_client.py", line 308, in delete
2013-10-14 10:16:28.039 | return self.request('DELETE', url, headers)
2013-10-14 10:16:28.040 | File "tempest/common/rest_client.py", line 436, in request
2013-10-14 10:16:28.040 | resp, resp_body)
2013-10-14 10:16:28.040 | File "tempest/common/rest_client.py", line 522, in _error_checker
2013-10-14 10:16:28.041 | raise exceptions.ComputeFault(message)
2013-10-14 10:16:28.041 | ComputeFault: Got compute fault
2013-10-14 10:16:28.041 | Details: {"NeutronError": "Request Failed: internal server error while processing your request."}

Changed in neutron:
assignee: nobody → Armando Migliaccio (armando-migliaccio)
status: New → Confirmed
summary: - DBError: (IntegrityError) null value in column "network_id" violates
- not-null constraint
+ internal neutron server error on tempest VolumesActionsTest
Changed in neutron:
status: Confirmed → In Progress
Revision history for this message
Armando Migliaccio (armando-migliaccio) wrote :

This snippet of log is critical to understanding why we get an Integrity error on network delete:

2013-11-01 05:45:29.608 460 DEBUG neutron.plugins.ml2.plugin [-] Ports to auto-delete: [] delete_network /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:387
2013-11-01 05:45:29.610 460 DEBUG neutron.plugins.ml2.plugin [-] Subnets to auto-delete: [] delete_network /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:401
2013-11-01 05:45:29.627 460 DEBUG neutron.plugins.ml2.plugin [-] Deleting network record delete_network /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:411
2013-11-01 05:45:29.629 460 DEBUG neutron.db.db_base_plugin_v2 [-] Generated mac for network 3022a674-2f18-4120-abde-86192d239879 is fa:16:3e:14:92:66 _generate_mac /opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py:302
2013-11-01 05:45:29.631 460 DEBUG neutron.plugins.ml2.plugin [-] Committing transaction delete_network /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:420

The trace about mac generation before committing the network delete is due to the dhcp port being created concurrently by the the dhcp agent. There are many ways in which this can be addressed, for instance, marking the network for deletion and ensuring that the dhcp does not create the port in the first place. However, since adding a new status to the network may be more convoluted and require a more thorough inspection of the code, it may be safer to just catch the integrity violation and try deleting the network again after the port gets re-read by the delete method.

Revision history for this message
Armando Migliaccio (armando-migliaccio) wrote :
Download full text (14.2 KiB)

I did experience another concurrent port creation while deleting the network, and it looks like the delete is successful this time. See snippet below:

Committing transaction delete_network /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:423
2013-11-02 00:47:37.546 467 DEBUG neutron.plugins.ml2.db [-] get_port_and_sgs() called for port_id 0437693e-2eac-41b8-9016-8f082397825d get_port_and_sgs /opt/stack/new/neutron/neutron/plugins/ml2/db.py:99
2013-11-02 00:47:37.553 467 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is 89ab404a77874722a55ae71666bbc9ab. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-02 00:47:37.561 467 ERROR neutron.plugins.ml2.plugin [-] A concurrent port creation has occurred
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin Traceback (most recent call last):
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin File "/opt/stack/new/neutron/neutron/plugins/ml2/plugin.py", line 424, in delete_network
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin break
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 456, in __exit__
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin self.commit()
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 368, in commit
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin self._prepare_impl()
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 347, in _prepare_impl
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin self.session.flush()
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin File "/opt/stack/new/neutron/neutron/openstack/common/db/sqlalchemy/session.py", line 542, in _wrap
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin raise exception.DBError(e)
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin DBError: (IntegrityError) null value in column "network_id" violates not-null constraint
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin 'UPDATE ports SET network_id=%(network_id)s WHERE ports.id = %(ports_id)s' {'network_id': None, 'ports_id': u'36db6fb5-81d2-4b71-82af-8523b92ed91d'}
2013-11-02 00:47:37.561 467 TRACE neutron.plugins.ml2.plugin
2013-11-02 00:47:37.566 467 DEBUG neutron.plugins.ml2.plugin [-] Ports to auto-delete: [<neutron.db.models_v2.Port[object at 4d887d0] {tenant_id=u'7d4d1f8fdb354c349e29c062dc9e7816', id=u'36db6fb5-81d2-4b71-82af-8523b92ed91d', name=u'', network_id=u'743431fd-ce7f-4883-aa34-d23e8e191df0', mac_address=u'fa:16:3e:65:85:19', admin_state_up=True, status=u'DOWN', device_id=u'dhcp34261b77-1da5-5129-b453-d9d5028a1629-743431fd-ce7f-4883-aa34-d23e8e191df0', device_owner=u'network:dhcp'}>] delete_network /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:390
2013-11-02 00:47:37.569 467 DEBUG neutron.plugins.ml2.plugin [-] Subnets to auto-delete: [] delete_network /opt/stack/new/neutron/neutron/plugins/ml2/plugin.py:404
2...

Changed in neutron:
status: In Progress → Fix Committed
Revision history for this message
Akihiro Motoki (amotoki) wrote :

The corresponding review is https://review.openstack.org/#/c/54850/ .

Revision history for this message
Joe Gordon (jogo) wrote :
Changed in neutron:
status: Fix Committed → Confirmed
Revision history for this message
Armando Migliaccio (armando-migliaccio) wrote :

Please see comment on the review.

Changed in neutron:
status: Confirmed → Fix Committed
tags: added: havana-backport-potential
Changed in neutron:
milestone: none → icehouse-1
importance: Undecided → High
Thierry Carrez (ttx)
Changed in neutron:
status: Fix Committed → Fix Released
Revision history for this message
Alan Pevec (apevec) wrote :

stable/havana review was https://review.openstack.org/57479

tags: removed: havana-backport-potential
Revision history for this message
Eugene Nikanorov (enikanorov) wrote :
Revision history for this message
Armando Migliaccio (armando-migliaccio) wrote :

IMHO, what you're reporting is a different bug.

Revision history for this message
Armando Migliaccio (armando-migliaccio) wrote :

potentially a new one.

Revision history for this message
Eugene Nikanorov (enikanorov) wrote :

Ok, will report as different one

Thierry Carrez (ttx)
Changed in neutron:
milestone: icehouse-1 → 2014.1
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers