Nova returns a 500 error when changes-since filter is poorly formatted

Bug #1731936 reported by David-wahlstrom on 2017-11-13
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Undecided
David-wahlstrom

Bug Description

Description
===========
When running tempest, we are seeing failures in nova-api. The test test_get_servers_allows_changes_since_bad_value (https://github.com/openstack/nova/blob/stable/pike/nova/tests/unit/api/openstack/compute/test_serversV21.py#L1186) causes nova to return a 500 error. The core of the issue is that when passing a "changes-since" filter to nova in a poor format, oslo_utils.timeutils raises an error that isn't being caught. This appears to be due to a recent commit which added whitelisting to nova, but seems to have over-zealously removed a try/except that was catching the error.

Steps to reproduce
==================
Run tempest's nova tests.

Expected result
===============
Nova-api should be returning a 400 code when given a bad changes-since filter, as defined by https://developer.openstack.org/api-ref/compute/#list-servers.

Actual result
=============
We're seeing a 500 error in nova-api logs.

Environment
===========
Currently seeing this in Ocata, but it looks like it should be happening in anything Ocata+. This is a pretty simple/basic install with kvm HVs and a ceph backend.

Logs & Configs
==============
2017-11-08 15:46:38.271 2640892 INFO nova.osapi_compute.wsgi.server [req-0fb396b8-98b8-4edf-b5d8-d1fcaa381171 7be9f09f79e44d80b213b516abaa0a4e f7ba36851c724e939369cda1731c9a41 - - -] 10.6.30.3,10.6.8.56 "GET /v2/f7ba36851c724e939369cda1731
c9a41/servers?changes-since=2051-01-01T12%3A34%3A00Z HTTP/1.1" status: 200 len: 206 time: 0.0878329
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions [req-6e521f71-8526-4671-9c06-384eec3d0b8d 7be9f09f79e44d80b213b516abaa0a4e f7ba36851c724e939369cda1731c9a41 - - -] Unexpected exception in API method
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions Traceback (most recent call last):
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions File "/opt/nova/lib/python2.7/site-packages/nova/api/openstack/extensions.py", line 338, in wrapped
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions return f(*args, **kwargs)
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions File "/opt/nova/lib/python2.7/site-packages/nova/api/validation/__init__.py", line 181, in wrapper
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions return func(*args, **kwargs)
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions File "/opt/nova/lib/python2.7/site-packages/nova/api/validation/__init__.py", line 181, in wrapper
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions return func(*args, **kwargs)
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions File "/opt/nova/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 201, in index
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions servers = self._get_servers(req, is_detail=False)
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions File "/opt/nova/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 260, in _get_servers
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions search_opts['changes-since'])
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions File "/opt/nova/lib/python2.7/site-packages/oslo_utils/timeutils.py", line 67, in parse_isotime
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions raise ValueError(six.text_type(e))
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions ValueError: Unable to parse date string u'2011/01/01'
2017-11-08 15:46:38.315 2640894 ERROR nova.api.openstack.extensions
2017-11-08 15:46:38.317 2640894 INFO nova.api.openstack.wsgi [req-6e521f71-8526-4671-9c06-384eec3d0b8d 7be9f09f79e44d80b213b516abaa0a4e f7ba36851c724e939369cda1731c9a41 - - -] HTTP exception thrown: Unexpected API Error. Please report this
 at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<type 'exceptions.ValueError'>
2017-11-08 15:46:38.318 2640894 INFO nova.osapi_compute.wsgi.server [req-6e521f71-8526-4671-9c06-384eec3d0b8d 7be9f09f79e44d80b213b516abaa0a4e f7ba36851c724e939369cda1731c9a41 - - -] 10.6.30.3,10.6.8.56 "GET /v2/f7ba36851c724e939369cda1731
c9a41/servers?changes-since=2011%2F01%2F01 HTTP/1.1" status: 500 len: 420 time: 0.0323260

Changed in nova:
assignee: nobody → David-wahlstrom (david-wahlstrom)
status: New → In Progress

I have submitted https://review.openstack.org/#/c/519356/ as a fix for this bug.

jichenjc (jichenjc) wrote :

looks like you are using v2 version ?

/v2/f7ba36851c724e939369cda1731
c9a41/servers?changes-since=2051-01-01T12%3A34%3A00Z

jichenjc (jichenjc) wrote :

I tried on newton version and

curl -g -i --cacert "/data/PKIcerts/certs/cacert.pem" -X GET https://x.x.x.x:8774/v2/8423bc83177f4d28a1f2ba2b557345de/servers?changes-since=2051-01-01T12%3A34%3A00Z -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: a9ef755a33e244f2ad5d1abe389df8f5"

works for me ..{"servers": []}

need find a devstack to try on.....

Correct, using V2. Also, to trigger the bug, you need to use an incorrect datetime stamp. So the datetime should look something like the tempest test uses (https://github.com/openstack/tempest/blob/master/tempest/api/compute/servers/test_list_servers_negative.py#L115). Your curl command would need to look more like:

curl -g -i --cacert "/data/PKIcerts/certs/cacert.pem" -X GET https://x.x.x.x:8774/v2/8423bc83177f4d28a1f2ba2b557345de/servers?changes-since=2011/01/01 -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: a9ef755a33e244f2ad5d1abe389df8f5"

When this incorrect datetime format comes through, the server is supposed to gracefully handle it and return a 400, but instead an uncaught exception is raised, causing the server to return a 500.

Frank Gemein (flank) wrote :

The same here with pike and keystone v3.
>>> Unexpected exception in API method: ValueError: Unable to parse date string u'2011/01/01' <<<
Is a 500 where there should be a 400

Change abandoned by Stephen Finucane (<email address hidden>) on branch: master
Review: https://review.openstack.org/519356
Reason: This has been up here for a long time, is in merge conflict and looks stalled. I'm going to abandon to cut down the review queue. Feel free to reopen/rebase if this is still applicable.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers