Public bug reported: 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 ** Affects: nova Importance: Undecided Assignee: David-wahlstrom (david-wahlstrom) Status: In Progress -- You received this bug notification because you are a member of Yahoo! Engineering Team, which is subscribed to OpenStack Compute (nova). https://bugs.launchpad.net/bugs/1731936 Title: Nova returns a 500 error when changes-since filter is poorly formatted Status in OpenStack Compute (nova): In Progress 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 To manage notifications about this bug go to: https://bugs.launchpad.net/nova/+bug/1731936/+subscriptions -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : [email protected] Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
