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

[David-wahlstrom]

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

[David-wahlstrom (david-wahlstrom)]

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

[jichenjc (jichenjc)]

looks like you are using v2 version ?

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

[jichenjc (jichenjc)]

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.....

[David-wahlstrom (david-wahlstrom)]

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 (fgemein)]

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

[OpenStack Infra (hudson-openstack)]

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.