datetime used for string column query crashed postgresql driver

[Wenhao Xu]

branch: master
testing commit: cd4093e0f2a7d07fa81915dc4866f4ac7324a028

The sql database is postgresql 9.1. The driver is psycopg2.

You can easily reproduce it by enabling instance_usage_audit in nova.conf and run nova-compute.

This bug should influence released version too if it is there for a long time.

The trace is here:
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager Traceback (most recent call last):
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "/home/wenhao/workspace/openstack/nova/nova/manager.py", line 230, in periodic_tasks
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager task(self, context)
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "/home/wenhao/workspace/openstack/nova/nova/compute/manager.py", line 3086, in _instance_usage_audit
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager if not compute_utils.has_audit_been_run(context, self.host):
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "/home/wenhao/workspace/openstack/nova/nova/compute/utils.py", line 219, in has_audit_been_run
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager begin, end, host)
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "/home/wenhao/workspace/openstack/nova/nova/db/api.py", line 1746, in task_log_get
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager period_ending, host, state, session)
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "/home/wenhao/workspace/openstack/nova/nova/db/sqlalchemy/api.py", line 115, in wrapper
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager return f(*args, **kwargs)
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "/home/wenhao/workspace/openstack/nova/nova/db/sqlalchemy/api.py", line 4727, in task_log_get
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager return query.first()
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "build/bdist.linux-x86_64/egg/sqlalchemy/orm/query.py", line 2156, in first
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager ret = list(self[0:1])
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "build/bdist.linux-x86_64/egg/sqlalchemy/orm/query.py", line 2023, in __getitem__
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager return list(res)
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "build/bdist.linux-x86_64/egg/sqlalchemy/orm/query.py", line 2227, in __iter__
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager return self._execute_and_instances(context)
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "build/bdist.linux-x86_64/egg/sqlalchemy/orm/query.py", line 2242, in _execute_and_instances
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager result = conn.execute(querycontext.statement, self._params)
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 1449, in execute
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager params)
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 1584, in _execute_clauseelement
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager compiled_sql, distilled_params
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 1698, in _execute_context
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager context)
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager File "build/bdist.linux-x86_64/egg/sqlalchemy/engine/base.py", line 1850, in _handle_dbapi_exception
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager None, sys.exc_info()[2]
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager ProgrammingError: (ProgrammingError) operator does not exist: character varying = timestamp without time zone
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager LINE 3: ...stance_usage_audit' AND task_log.period_beginning = '2013-01...
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager ^
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager HINT: No operator matches the given name and argument type(s). You might need to add explicit type casts.
2013-01-22 00:39:54,100.100 30323 TRACE nova.manager 'SELECT task_log.created_at AS task_log_created_at, task_log.updated_at AS task_log_updated_at, task_log.deleted_at AS task_log_deleted_at, task_log.deleted AS task_log_deleted, task_log.id AS task_log_id, task_log.task_name AS task_log_task_name, task_log.state AS task_log_state, task_log.host AS task_log_host, task_log.period_beginning AS task_log_period_beginning, task_log.period_ending AS task_log_period_ending, task_log.message AS task_log_message, task_log.task_items AS task_log_task_items, task_log.errors AS task_log_errors \nFROM task_log \nWHERE task_log.deleted = %(deleted_1)s AND task_log.task_name = %(task_name_1)s AND task_log.period_beginning = %(period_beginning_1)s AND task_log.period_ending = %(period_ending_1)s AND task_log.host = %(host_1)s \n LIMIT %(param_1)s' {'host_1': 'localhost', 'param_1': 1, 'deleted_1': False, 'period_ending_1': datetime.datetime(2013, 1, 21, 16, 0), 'task_name_1': 'instance_usage_audit', 'period_beginning_1': datetime.datetime(2013, 1, 21, 15, 0)}

[Wenhao Xu (wenhao-x)]

The period_beginning and period_ending is string type defined in the model. But the query passing in is datetime. So postgresql is confused about this type mismatch, I guess.

class TaskLog(BASE, NovaBase):
    """Audit log for background periodic tasks."""
    __tablename__ = 'task_log'
    id = Column(Integer, primary_key=True, nullable=False, autoincrement=True)
    task_name = Column(String(255), nullable=False)
    state = Column(String(255), nullable=False)
    host = Column(String(255))
    period_beginning = Column(String(255), default=timeutils.utcnow)
    period_ending = Column(String(255), default=timeutils.utcnow)
    message = Column(String(255), nullable=False)
    task_items = Column(Integer(), default=0)
    errors = Column(Integer(), default=0)

By converting the datetime to str before the SQLAlchemy query should fix the problem.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/20156
Committed: http://github.com/openstack/nova/commit/84e5e69e5b19272fe32aa587bc5d8552dbc4797e
Submitter: Jenkins
Branch: master

commit 84e5e69e5b19272fe32aa587bc5d8552dbc4797e
Author: Wenhao Xu <email address hidden>
Date: Tue Jan 22 01:34:44 2013 +0800

    Fix the wrong datatype in task_log table.

        Change period_begining and period_ending to Datetime type.
        Add the migration script.

    Change-Id: Ic5d61d6e7e847a1943825a0cb342b0b015bc0b70
    Fixes: bug #1102477