glance registry makes invalid SQL query

[Stephen Gran]

I have been trying to use glance-replicator in a havana install, and getting apparent failures from the registry. This was compounded by the lack of error logging in the registry. This is also reproducible with 'glance index'

I had to apply https://review.openstack.org/#/c/55787/ to get any debug output, but once I did, I see this:

2014-01-22 16:09:00.975 9845 INFO glance.wsgi.server [ca16cb8b-b04d-4ed5-ae77-e9ea3e89b007 cd6229ee1fcc4295a55eb3f67f8e633c 5a50556cfd74416b96806932d1743e1e] Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 384, in handle_one_response
    result = self.application(self.environ, start_response)
  File "/usr/lib/python2.7/dist-packages/keystoneclient/middleware/auth_token.py", line 539, in __call__
    return self.app(env, start_response)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/glance/common/wsgi.py", line 365, in __call__
    response = req.get_response(self.application)
  File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1296, in send
    application, catch_exc_info=False)
  File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1260, in call_application
    app_iter = application(self.environ, start_response)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
    return resp(environ, start_response)
  File "/usr/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
    response = self.app(environ, start_response)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
    return resp(environ, start_response)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/glance/common/wsgi.py", line 597, in __call__
    request, **action_args)
  File "/usr/lib/python2.7/dist-packages/glance/common/wsgi.py", line 616, in dispatch
    return method(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/glance/registry/api/v1/images.py", line 161, in detail
    images = self._get_images(req.context, **params)
  File "/usr/lib/python2.7/dist-packages/glance/registry/api/v1/images.py", line 109, in _get_images
    **params)
  File "/usr/lib/python2.7/dist-packages/glance/db/sqlalchemy/api.py", line 678, in image_get_all
    return [_normalize_locations(image.to_dict()) for image in query.all()]
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2237, in all
    return list(self)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2349, in __iter__
    return self._execute_and_instances(context)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2364, in _execute_and_instances
    result = conn.execute(querycontext.statement, self._params)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 662, in execute
    params)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 761, in _execute_clauseelement
    compiled_sql, distilled_params
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 874, in _execute_context
    context)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1024, in _handle_dbapi_exception
    exc_info
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 195, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 867, in _execute_context
    context)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 324, in do_execute
    cursor.execute(statement, parameters)
DataError: (DataError) invalid input syntax for type timestamp: ""
LINE 8: ...t IS NOT NULL) THEN anon_2.images_created_at ELSE '' END < '...

'SELECT anon_1.anon_2_images_created_at AS anon_1_anon_2_images_created_at, anon_1.anon_2_images_updated_at AS anon_1_anon_2_images_updated_at, anon_1.anon_2_images_deleted_at AS anon_1_anon_2_images_deleted_at, anon_1.anon_2_images_deleted AS anon_1_anon_2_images_deleted, anon_1.anon_2_images_id AS anon_1_anon_2_images_id, anon_1.anon_2_images_name AS anon_1_anon_2_images_name, anon_1.anon_2_images_disk_format AS anon_1_anon_2_images_disk_format, anon_1.anon_2_images_container_format AS anon_1_anon_2_images_container_format, anon_1.anon_2_images_size AS anon_1_anon_2_images_size, anon_1.anon_2_images_status AS anon_1_anon_2_images_status, anon_1.anon_2_images_is_public AS anon_1_anon_2_images_is_public, anon_1.anon_2_images_checksum AS anon_1_anon_2_images_checksum, anon_1.anon_2_images_min_disk AS anon_1_anon_2_images_min_disk, anon_1.anon_2_images_min_ram AS anon_1_anon_2_images_min_ram, anon_1.anon_2_images_owner AS anon_1_anon_2_images_owner, anon_1.anon_2_images_protected AS anon_1_anon_2_images_protected, image_properties_1.created_at AS image_properties_1_created_at, image_properties_1.updated_at AS image_properties_1_updated_at, image_properties_1.deleted_at AS image_properties_1_deleted_at, image_properties_1.deleted AS image_properties_1_deleted, image_properties_1.id AS image_properties_1_id, image_properties_1.image_id AS image_properties_1_image_id, image_properties_1.name AS image_properties_1_name, image_properties_1.value AS image_properties_1_value, image_locations_1.created_at AS image_locations_1_created_at, image_locations_1.updated_at AS image_locations_1_updated_at, image_locations_1.deleted_at AS image_locations_1_deleted_at, image_locations_1.deleted AS image_locations_1_deleted, image_locations_1.id AS image_locations_1_id, image_locations_1.image_id AS image_locations_1_image_id, image_locations_1.value AS image_locations_1_value, image_locations_1.meta_data AS image_locations_1_meta_data \nFROM (SELECT anon_2.images_created_at AS anon_2_images_created_at, anon_2.images_updated_at AS anon_2_images_updated_at, anon_2.images_deleted_at AS anon_2_images_deleted_at, anon_2.images_deleted AS anon_2_images_deleted, anon_2.images_id AS anon_2_images_id, anon_2.images_name AS anon_2_images_name, anon_2.images_disk_format AS anon_2_images_disk_format, anon_2.images_container_format AS anon_2_images_container_format, anon_2.images_size AS anon_2_images_size, anon_2.images_status AS anon_2_images_status, anon_2.images_is_public AS anon_2_images_is_public, anon_2.images_checksum AS anon_2_images_checksum, anon_2.images_min_disk AS anon_2_images_min_disk, anon_2.images_min_ram AS anon_2_images_min_ram, anon_2.images_owner AS anon_2_images_owner, anon_2.images_protected AS anon_2_images_protected \nFROM (SELECT images.created_at AS images_created_at, images.updated_at AS images_updated_at, images.deleted_at AS images_deleted_at, images.deleted AS images_deleted, images.id AS images_id, images.name AS images_name, images.disk_format AS images_disk_format, images.container_format AS images_container_format, images.size AS images_size, images.status AS images_status, images.is_public AS images_is_public, images.checksum AS images_checksum, images.min_disk AS images_min_disk, images.min_ram AS images_min_ram, images.owner AS images_owner, images.protected AS images_protected \nFROM images \nWHERE images.is_public = true OR images.owner = %(owner_1)s UNION SELECT images.created_at AS images_created_at, images.updated_at AS images_updated_at, images.deleted_at AS images_deleted_at, images.deleted AS images_deleted, images.id AS images_id, images.name AS images_name, images.disk_format AS images_disk_format, images.container_format AS images_container_format, images.size AS images_size, images.status AS images_status, images.is_public AS images_is_public, images.checksum AS images_checksum, images.min_disk AS images_min_disk, images.min_ram AS images_min_ram, images.owner AS images_owner, images.protected AS images_protected \nFROM images JOIN image_members ON images.id = image_members.image_id \nWHERE image_members.deleted = false AND image_members.member = %(member_1)s) AS anon_2 \nWHERE anon_2.images_deleted = false AND anon_2.images_status != %(status_1)s AND (CASE WHEN (anon_2.images_created_at IS NOT NULL) THEN anon_2.images_created_at ELSE %(param_1)s END < %(param_2)s OR CASE WHEN (anon_2.images_created_at IS NOT NULL) THEN anon_2.images_created_at ELSE %(param_3)s END = %(param_4)s AND CASE WHEN (anon_2.images_id IS NOT NULL) THEN anon_2.images_id ELSE %(param_5)s END < %(param_6)s) ORDER BY anon_2.images_created_at DESC, anon_2.images_id DESC \n LIMIT %(param_7)s) AS anon_1 LEFT OUTER JOIN image_properties AS image_properties_1 ON anon_1.anon_2_images_id = image_properties_1.image_id LEFT OUTER JOIN image_locations AS image_locations_1 ON anon_1.anon_2_images_id = image_locations_1.image_id ORDER BY anon_1.anon_2_images_created_at DESC, anon_1.anon_2_images_id DESC' {'param_5': '', 'param_4': datetime.datetime(2014, 1, 15, 13, 39, 39, 614259), 'param_7': 10, 'param_6': u'c1d688da-b999-467f-a5ae-e9d342effb48', 'param_1': '', 'param_3': '', 'param_2': datetime.datetime(2014, 1, 15, 13, 39, 39, 614259), 'member_1': u'5a50556cfd74416b96806932d1743e1e', 'owner_1': u'5a50556cfd74416b96806932d1743e1e', 'status_1': 'killed'}

So it seems that cd7bbc30175e90661baa90fff02232013b49dd06 introduced brokenness on at least postgres, since we don't see this in a Folsom install - 'glance index' works fine there.

Let me know if I can provide any additional information.

Cheers,

[Stuart McLaren (stuart-mclaren)]

> DataError: (DataError) invalid input syntax for type timestamp: ""

I wonder if this is being caused by a NULL timestamp being converted to an empty string?

when using mysql, timestamps are stored as an integer '0', perphaps in postgres they are stored as a NULL?

here's a view of a mysql table with an integer '0' timestamp (deleted_at):

$ mysql -e 'select * from images;'
id name size status is_public created_at updated_at deleted_at deleted disk_format container_format checksum owner min_disk min_ram protected
8ae1d947-03ae-4997-a9d9-875c2ddf63b1 NULL 1048576 active 0 2014-01-22 17:14:51 2014-01-22 17:15:02 NULL 0 raw bare e9592522e721b1a65d57ee481958de34 3582065107 0 0 0

Can you tell if postgres stores timestamps as NULLs?

Would it be possible to create a clean test database with just one image and try to figure out if removing any NULL timestamps helps? eg for the example above deleting the image would replace the timestamp 'NULL' with a real value.

[Stephen Gran (sgran)]

The problem is not with the data already in the database, the problem is with the query being constructed in _paginate_query that contains the an empty string where it should contain a timestamp. It's arguably a bug in mysql that it allows you to compare a string and an integer and a date in this way.

This environment is not in any real use yet - I'm tracking down the last few issues before go-live now, so I can do some database debugging. When I get home, I'll paste the output of some SQL queries here.

Cheers,

[Stephen Gran (sgran)]

Hi,

Now that I know the issue, I've had an easier time finding things out about it. My report seems to be a duplicate of 1245947. Any chance of getting a havana backport for it? I see one was started but then abandoned.

Cheers,