Nova api throws 500 error when invalid name passed to servers

[Prashant Shetty]

System was running with 2k cirrOS vm on 100 KVM hypervisors, and seeing below DB exception while trying to delete using nova api.

Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'oslo_db.exception.DBError'> (HTTP 500) (Request-ID: req-379addbc-c4e5-43b4-bf37-f64436e13750)

stack@controller:/opt/stack/nova$ git log -1
commit 5aee67a80a30725a7d2b95533baf8bfb73476ef1
Merge: 2e28de7 0ecc870
Author: Jenkins <email address hidden>
Date: Mon Feb 15 21:56:09 2016 +0000

    Merge "Move Disk allocation ratio to ResourceTracker"
stack@controller:/opt/stack/nova$

Have attached nova-api logs to bug.

Logs:

2016-02-16 20:47:29.186 DEBUG nova.api.openstack.wsgi [req-eff95987-035d-48fe-8c3b-5b947167e72c admin admin] Calling method '<bound method ServersController.index of <nova.api.openstack.compute.servers.Se
rversController object at 0x7fb61374f210>>' from (pid=29444) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:699
2016-02-16 20:47:29.187 DEBUG nova.compute.api [req-eff95987-035d-48fe-8c3b-5b947167e72c admin admin] Searching by: {'deleted': False, 'project_id': u'3122784921764f0c8e2ca9feb5fc7424', u'name': u'|'} fro
m (pid=29444) get_all /opt/stack/nova/nova/compute/api.py:2001
2016-02-16 20:47:29.225 ERROR oslo_db.sqlalchemy.exc_filters [req-eff95987-035d-48fe-8c3b-5b947167e72c admin admin] DBAPIError exception wrapped from (pymysql.err.InternalError) (1139, u"Got error 'empty (sub)expression' from regexp") [SQL: u'SELECT anon_1.instances_created_at AS anon_1_instances_created_at, anon_1.instances_updated_at AS anon_1_instances_updated_at, anon_1.instances_deleted_at AS anon_1_
instances_deleted_at, anon_1.instances_deleted AS anon_1_instances_deleted, anon_1.instances_id AS anon_1_instances_id, anon_1.instances_user_id AS anon_1_instances_user_id, anon_1.instances_project_id AS
 anon_1_instances_project_id, anon_1.instances_image_ref AS anon_1_instances_image_ref, anon_1.instances_kernel_id AS anon_1_instances_kernel_id, anon_1.instances_ramdisk_id AS anon_1_instances_ramdisk_id
, anon_1.instances_hostname AS anon_1_instances_hostname, anon_1.instances_launch_index AS anon_1_instances_launch_index, anon_1.instances_key_name AS anon_1_instances_key_name, anon_1.instances_key_data
AS anon_1_instances_key_data, anon_1.instances_power_state AS anon_1_instances_power_state, anon_1.instances_vm_state AS anon_1_instances_vm_state, anon_1.instances_task_state AS anon_1_instances_task_sta
te, anon_1.instances_memory_mb AS anon_1_instances_memory_mb, anon_1.instances_vcpus AS anon_1_instances_vcpus, anon_1.instances_root_gb AS anon_1_instances_root_gb, anon_1.instances_ephemeral_gb AS anon_
1_instances_ephemeral_gb, anon_1.instances_ephemeral_key_uuid AS anon_1_instances_ephemeral_key_uuid, anon_1.instances_host AS anon_1_instances_host, anon_1.instances_node AS anon_1_instances_node, anon_1
.instances_instance_type_id AS anon_1_instances_instance_type_id, anon_1.instances_user_data AS anon_1_instances_user_data, anon_1.instances_reservation_id AS anon_1_instances_reservation_id, anon_1.insta
nces_launched_at AS anon_1_instances_launched_at, anon_1.instances_terminated_at AS anon_1_instances_terminated_at, anon_1.instances_availability_zone AS anon_1_instances_availability_zone, anon_1.instanc
es_display_name AS anon_1_instances_display_name, anon_1.instances_display_description AS anon_1_instances_display_description, anon_1.instances_launched_on AS anon_1_instances_launched_on, anon_1.instanc
es_locked AS anon_1_instances_locked, anon_1.instances_locked_by AS anon_1_instances_locked_by, anon_1.instances_os_type AS anon_1_instances_os_type, anon_1.instances_architecture AS anon_1_instances_arch
itecture, anon_1.instances_vm_mode AS anon_1_instances_vm_mode, anon_1.instances_uuid AS anon_1_instances_uuid, anon_1.instances_root_device_name AS anon_1_instances_root_device_name, anon_1.instances_def
ault_ephemeral_device AS anon_1_instances_default_ephemeral_device, anon_1.instances_default_swap_device AS anon_1_instances_default_swap_device, anon_1.instances_config_drive AS anon_1_instances_config_d
rive, anon_1.instances_access_ip_v4 AS anon_1_instances_access_ip_v4, anon_1.instances_access_ip_v6 AS anon_1_instances_access_ip_v6, anon_1.instances_auto_disk_config AS anon_1_instances_auto_disk_config
, anon_1.instances_progress AS anon_1_instances_progress, anon_1.instances_shutdown_terminate AS anon_1_instances_shutdown_terminate, anon_1.instances_disable_terminate AS anon_1_instances_disable_termina
te, anon_1.instances_cell_name AS anon_1_instances_cell_name, anon_1.instances_internal_id AS anon_1_instances_internal_id, anon_1.instances_cleaned AS anon_1_instances_cleaned, instance_info_caches_1.cre
ated_at AS instance_info_caches_1_created_at, instance_info_caches_1.updated_at AS instance_info_caches_1_updated_at, instance_info_caches_1.deleted_at AS instance_info_caches_1_deleted_at, instance_info_
caches_1.deleted AS instance_info_caches_1_deleted, instance_info_caches_1.id AS instance_info_caches_1_id, instance_info_caches_1.network_info AS instance_info_caches_1_network_info, instance_info_caches
_1.instance_uuid AS instance_info_caches_1_instance_uuid, security_groups_1.created_at AS security_groups_1_created_at, security_groups_1.updated_at AS security_groups_1_updated_at, security_groups_1.dele
ted_at AS security_groups_1_deleted_at, security_groups_1.deleted AS security_groups_1_deleted, security_groups_1.id AS security_groups_1_id, security_groups_1.name AS security_groups_1_name, security_gro
ups_1.description AS security_groups_1_description, security_groups_1.user_id AS security_groups_1_user_id, security_groups_1.project_id AS security_groups_1_project_id \nFROM (SELECT instances.created_at
 AS instances_created_at, instances.updated_at AS instances_updated_at, instances.deleted_at AS instances_deleted_at, instances.deleted AS instances_deleted, instances.id AS instances_id, instances.user_i
d AS instances_user_id, instances.project_id AS instances_project_id, instances.image_ref AS instances_image_ref, instances.kernel_id AS instances_kernel_id, instances.ramdisk_id AS instances_ramdisk_id,
instances.hostname AS instances_hostname, instances.launch_index AS instances_launch_index, instances.key_name AS instances_key_name, instances.key_data AS instances_key_data, instances.power_state AS ins
tances_power_state, instances.vm_state AS instances_vm_state, instances.task_state AS instances_task_state, instances.memory_mb AS instances_memory_mb, instances.vcpus AS instances_vcpus, instances.root_g
b AS instances_root_gb, instances.ephemeral_gb AS instances_ephemeral_gb, instances.ephemeral_key_uuid AS instances_ephemeral_key_uuid, instances.host AS instances_host, instances.node AS instances_node,
instances.instance_type_id AS instances_instance_type_id, instances.user_data AS instances_user_data, instances.reservation_id AS instances_reservation_id, instances.launched_at AS instances_launched_at,
instances.terminated_at AS instances_terminated_at, instances.availability_zone AS instances_availability_zone, instances.display_name AS instances_display_name, instances.display_description AS instances
_display_description, instances.launched_on AS instances_launched_on, instances.locked AS instances_locked, instances.locked_by AS instances_locked_by, instances.os_type AS instances_os_type, instances.architecture AS instances_architecture, instances.vm_mode AS instances_vm_mode, instances.uuid AS instances_uuid, instances.root_device_name AS instances_root_device_name, instances.default_ephemeral_device AS instances_default_ephemeral_device, instances.default_swap_device AS instances_default_swap_device, instances.config_drive AS instances_config_drive, instances.access_ip_v4 AS instances_access_ip_v4, instances.access_ip_v6 AS instances_access_ip_v6, instances.auto_disk_config AS instances_auto_disk_config, instances.progress AS instances_progress, instances.shutdown_terminate AS instances_shutdown_terminate, instances.disable_terminate AS instances_disable_terminate, instances.cell_name AS instances_cell_name, instances.internal_id AS instances_internal_id, instances.cleaned AS instances_cleaned \nFROM instances \nWHERE instances.deleted = %(deleted_1)s AND (instances.vm_state != %(vm_state_1)s OR instances.vm_state IS NULL) AND instances.project_id = %(project_id_1)s AND (instances.display_name REGEXP %(display_name_1)s) ORDER BY instances.created_at DESC, instances.id DESC \n LIMIT %(param_1)s) AS anon_1 LEFT OUTER JOIN instance_info_caches AS instance_info_caches_1 ON instance_info_caches_1.instance_uuid = anon_1.instances_uuid LEFT OUTER JOIN (security_group_instance_association AS security_group_instance_association_1 INNER JOIN security_groups AS security_groups_1 ON security_groups_1.id = security_group_instance_association_1.security_group_id AND security_group_instance_association_1.deleted = %(deleted_2)s AND security_groups_1.deleted = %(deleted_3)s) ON security_group_instance_association_1.instance_uuid = anon_1.instances_uuid AND anon_1.instances_deleted = %(deleted_4)s ORDER BY anon_1.instances_created_at DESC, anon_1.instances_id DESC'] [parameters: {u'param_1': 1000, u'display_name_1': u'|', u'deleted_4': 0, u'deleted_3': 0, u'deleted_2': 0, u'deleted_1': 0, u'vm_state_1': 'soft-delete', u'project_id_1': u'3122784921764f0c8e2ca9feb5fc7424'}]
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters context)
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters cursor.execute(statement, parameters)
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 146, in execute
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters result = self._query(query)
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 296, in _query
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters conn.query(q)
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 819, in query2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1001, in _read_query_result2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters result.read()
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1285, in read2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters first_packet = self.connection._read_packet()
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 965, in _read_packet2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters packet.check_error()2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters err.raise_mysql_exception(self._data)2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 120, in raise_mysql_exception
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters _check_mysql_exception(errinfo)2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 115, in _check_mysql_exception2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters raise InternalError(errno, errorvalue)
2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters InternalError: (1139, u"Got error 'empty (sub)expression' from regexp")2016-02-16 20:47:29.225 TRACE oslo_db.sqlalchemy.exc_filters
2016-02-16 20:47:29.231 ERROR nova.api.openstack.extensions [req-eff95987-035d-48fe-8c3b-5b947167e72c admin admin] Unexpected exception in API method

[Sean Dague (sdague)]

What did your DELETE API call look like? Was it via a tool? We need the exact API call to help track this down.

[Prashant Shetty (prashantshetty)]

Sean,

No tools used to delete instances. Used below command to delete,

nova list --all_tenants | grep kvm | awk {'print $2'} | xargs -l nova delete

[Sean Dague (sdague)]

 Searching by: {'deleted': False, 'project_id': u'3122784921764f0c8e2ca9feb5fc7424', u'name': u'|'}

That's the crux of the situation here.

``nova list --all_tenants |`` is processing | as an argument to ``nova list``.

The API call that is failing is:

GET /v2.1/3122784921764f0c8e2ca9feb5fc7424/servers?name=%7C

Now, granted, this should not fail like this. However we're never even getting to the delete.

[Augustina Ragwitz (auggy)]

I'm not finding functional test coverage for servers?foo=bar that hits the sqlalchemy layer that would catch things like this. Part of fixing this bug should be adding that coverage.

[jichenjc (jichenjc)]

we can do validation at API layer but this would be a bigger topic
so I will submit a patch to catch the DB error then return a 400 error

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/282190

[jichenjc (jichenjc)]

I used '|' in test directly, seems ut use sqlite and it didn't generate the db error

[Sean Dague (sdague)]

Can we replicate it on mysql manually?

[Attila Fazekas (afazekas)]

(instances.display_name REGEXP %(display_name_1)s) is the faulty part.

The issue is also mariadb server version dependent.

I have checked this query.: select tab.id from (select 0 as id) as tab where tab.id REGEXP '|';

MariaDB [(none)]> SHOW VARIABLES LIKE "%version%";
+-------------------------+---------------------+
| Variable_name | Value |
+-------------------------+---------------------+
| innodb_version | 5.5.43-MariaDB-37.2 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.5.44-MariaDB |
| version_comment | MariaDB Server |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+---------------------+
7 rows in set (0.00 sec)

MariaDB [(none)]> select tab.id from (select 0 as id) as tab where tab.id REGEXP '|';
ERROR 1139 (42000): Got error 'empty (sub)expression' from regexp

On another server:
MariaDB [test]> SHOW VARIABLES LIKE "%version%";
+-------------------------+-----------------------------------+
| Variable_name | Value |
+-------------------------+-----------------------------------+
| innodb_version | 5.6.22-72.0 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 10.0.17-MariaDB-wsrep |
| version_comment | MariaDB Server, wsrep_25.10.r4144 |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
| version_malloc_library | system |
+-------------------------+-----------------------------------+
8 rows in set (0.00 sec)

MariaDB [test]> select tab.id from (select 0 as id) as tab where tab.id REGEXP '|';
+----+
| id |
+----+
| 0 |
+----+
1 row in set (0.00 sec)

[Attila Fazekas (afazekas)]

Do we really need to use REGEXP here ?

[Prashant Shetty (prashantshetty)]

Attila,

I am trying to find all vm's name with string 'x' and delete them. I thought this is best way to do it.
Do you know any better way to do it without using REGEXP?. Thanks.

[Attila Fazekas (afazekas)]

WHERE vm.name = 'x' ; # exact match.

It is expected to be an exact match, right ?

Regexp based search usually also slower, it should be avoided in most cases,
for doing exact match it is also confusing.

Nova API only expected to support regexp based search on listing (by name), otherwise regexp SHOULD NOT be used at all.

For ex.:
$ nova list --name '.*g.*'
$ openstack server list --name '[egy][azvy]'

The invalid regexp needs to be handled in this case anyway.

[Alex Xu (xuhj)]

This due to we use regex filter for name: https://github.com/openstack/nova/blob/master/nova/db/sqlalchemy/api.py#L2286

We should convert the '|' to '\\|', then the sql like this 'select * from instances where instances.display_name REGEXP "\\|"' will works

[jichenjc (jichenjc)]

yes, that will work by test

mysql> select * from instances where instances.display_name REGEXP 'a|b';
mysql> select * from instances where instances.display_name REGEXP '\\|b';

can work , but following can't, so maybe the solution is to change the | in special position

mysql> select * from instances where instances.display_name REGEXP 'a|';
ERROR 1139 (42000): Got error 'empty (sub)expression' from regexp
mysql> select * from instances where instances.display_name REGEXP '|b';
ERROR 1139 (42000): Got error 'empty (sub)expression' from regexp

Also

mysql> select * from instances where instances.display_name REGEXP 'a\\|b';
Empty set (0.00 sec)
mysql> select * from instances where instances.display_name REGEXP 'a|b';

has different output...

[jichenjc (jichenjc)]

also, this is for Mysql only , don't have an environment on other db such as postsql.... not sure the side effect to it

[Hao Li (haoli201410)]

Execute me, Does my bug is same with you talk ?

＃nova image-list │
ERROR (ClientException): Unexpected API Error. Please report this at http://bug│
s.launchpad.net/nova/ and attach the Nova API log if possible. │
<class 'glanceclient.exc.HTTPInternalServerError'> (HTTP 500) (Request-ID: req-│
e3ab228a-997d-420e-933f-6dfa269790e3)

# tail /var/log/nova/nova-api.log
2016-07-14 15:21:05.266 1267 ERROR nova.api.openstack.extensions return self._request('GET', url, **kwargs)
2016-07-14 15:21:05.266 1267 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/glanceclient/common/http.py", line 268, in _request
2016-07-14 15:21:05.266 1267 ERROR nova.api.openstack.extensions resp, body_iter = self._handle_response(resp)
2016-07-14 15:21:05.266 1267 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/site-packages/glanceclient/common/http.py", line 89, in _handle_response
2016-07-14 15:21:05.266 1267 ERROR nova.api.openstack.extensions raise exc.from_response(resp, resp.content)
2016-07-14 15:21:05.266 1267 ERROR nova.api.openstack.extensions HTTPInternalServerError: 500 Internal Server Error: The server has either erred or is incapable of performing the requested operation. (HTTP 500)
2016-07-14 15:21:05.266 1267 ERROR nova.api.openstack.extensions
2016-07-14 15:21:05.268 1267 INFO nova.api.openstack.wsgi [req-78b2ef76-8aa2-4c44-a361-51eaab71914d 80c338eef1234d29b229c5490bfad1b0 32672e60a5f842e0b88bde7aa26c2a89 - - -] HTTP exception thrown: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'glanceclient.exc.HTTPInternalServerError'>
2016-07-14 15:21:05.269 1267 INFO nova.osapi_compute.wsgi.server [req-78b2ef76-8aa2-4c44-a361-51eaab71914d 80c338eef1234d29b229c5490bfad1b0 32672e60a5f842e0b88bde7aa26c2a89 - - -] 10.0.0.4 "GET /v2/32672e60a5f842e0b88bde7aa26c2a89/images/detail HTTP/1.1" status: 500 len: 445 time: 0.2526889

[Prashant Shetty (prashantshetty)]

Hao, seems to be same issue..

[Attila Fazekas (afazekas)]

It looks like a different issue, and you should have a stack trace also in the glance api log, and your actual issue is likely in glance not in nova.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Michael Still (<email address hidden>) on branch: master
Review: https://review.openstack.org/282190
Reason: This patch has been sitting unchanged for more than 12 weeks. I am therefore going to abandon it to keep the nova review queue sane. Please feel free to restore the change if you're still working on it.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Michael Still (<email address hidden>) on branch: master
Review: https://review.openstack.org/293709
Reason: This patch has been sitting unchanged for more than 12 weeks. I am therefore going to abandon it to keep the nova review queue sane. Please feel free to restore the change if you're still working on it.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/282190
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=117fad897d5310d66cc2e690f3cd32e72614d8fd
Submitter: Jenkins
Branch: master

commit 117fad897d5310d66cc2e690f3cd32e72614d8fd
Author: jichenjc <email address hidden>
Date: Fri Feb 26 12:52:07 2016 +0800

    Refactor REGEX filters to eliminate 500 errors

    You can currently create a 500 error on mysql by passing | as the name
    filter because mysql assumes regex values are well crafted by the
    application layer.

    This puts in facilities to provide a safe regex filter per db engine.

    It also refactors some of the inline code from _regex_instance_filter
    into slightly more logical blocks, which will make it a little more
    straight forward about where we need to do something smarter about
    determining the dbtype in a cellsv2 world.

    Change-Id: Ice2e21666905fdb76c001195e8fca21b427ea737
    Closes-Bug: 1546396

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 15.0.0.0b2 development milestone.

[OpenStack Infra (hudson-openstack)]

Change abandoned by jichenjc (<email address hidden>) on branch: master
Review: https://review.openstack.org/293709