← Back to team overview

yahoo-eng-team team mailing list archive

  1. yahoo-eng-team team
  2. Mailing list archive
  3. Message #69133

[Bug 1731936] [NEW] Nova returns a 500 error when changes-since filter is poorly formatted

  Thread Previous • Date Previous • • Thread Next 
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
  Thread Previous • Date Previous • • Thread Next