"Unknown column 'nodes.finished_at' in 'where clause'"

[Waldemar Znoinski]

stable/mitaka setup using kolla stable/mitaka

pip freeze | grep -i inspector
ironic-inspector==3.2.2

 ironic-conductor --version
5.1.0

keep getting the below in ironic_inspector log

2016-08-23 13:30:12.140 1 DEBUG futurist.periodics [-] Submitting periodic function 'ironic_inspector.main.periodic_clean_up' _process_scheduled /var/lib/kolla/venv/local/lib/python2.7/site-packages/futurist/periodics.py:611
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters [-] DBAPIError exception wrapped from (pymysql.err.InternalError) (1054, u"Unknown column 'nodes.finished_at' in 'where clause'") [SQL: u'DELETE FROM nodes WHERE nodes.finished_at IS NOT NULL AND nodes.finish
ed_at < %(finished_at_1)s'] [parameters: {u'finished_at_1': 1471350612.140855}]
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters context)
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters cursor.execute(statement, parameters)
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/cursors.py", line 158, in execute
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters result = self._query(query)
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/cursors.py", line 308, in _query
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters conn.query(q)
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 820, in query
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 1002, in _read_query_result
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters result.read()
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 1285, in read
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters first_packet = self.connection._read_packet()
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 966, in _read_packet
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters packet.check_error()
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 394, in check_error
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters err.raise_mysql_exception(self._data)
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/err.py", line 120, in raise_mysql_exception
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters _check_mysql_exception(errinfo)
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/err.py", line 115, in _check_mysql_exception
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters raise InternalError(errno, errorvalue)
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1054, u"Unknown column 'nodes.finished_at' in 'where clause'")
2016-08-23 13:30:12.144 1 ERROR oslo_db.sqlalchemy.exc_filters

2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main [-] Periodic clean up of node cache failed
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main Traceback (most recent call last):
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/ironic_inspector/main.py", line 299, in periodic_clean_up
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main if node_cache.clean_up():
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/ironic_inspector/node_cache.py", line 548, in clean_up
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main db.Node.finished_at < status_keep_threshold).delete()
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3048, in delete
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main delete_op.exec_()
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 1127, in exec_
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main self._do_exec()
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 1311, in _do_exec
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main mapper=self.mapper)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1034, in execute
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main bind, close_with_result=True).execute(clause, params or {})
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 914, in execute
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main return meth(self, multiparams, params)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main return connection._execute_clauseelement(self, multiparams, params)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main compiled_sql, distilled_params
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main context)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main util.raise_from_cause(newraise, exc_info)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main reraise(type(exception), exception, tb=exc_tb, cause=cause)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main context)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main cursor.execute(statement, parameters)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/cursors.py", line 158, in execute
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main result = self._query(query)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/cursors.py", line 308, in _query
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main conn.query(q)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 820, in query
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 1002, in _read_query_result
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main result.read()
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 1285, in read
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main first_packet = self.connection._read_packet()
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 966, in _read_packet
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main packet.check_error()
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 394, in check_error
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main err.raise_mysql_exception(self._data)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/err.py", line 120, in raise_mysql_exception
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main _check_mysql_exception(errinfo)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/err.py", line 115, in _check_mysql_exception
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main raise InternalError(errno, errorvalue)
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main DBError: (pymysql.err.InternalError) (1054, u"Unknown column 'nodes.finished_at' in 'where clause'") [SQL: u'DELETE FROM nodes WHERE nodes.finished_at IS NOT NULL AND nodes.finished_at < %(finished_at_1)s'] [parameter
s: {u'finished_at_1': 1471350612.140855}]
2016-08-23 13:30:12.146 1 ERROR ironic_inspector.main

[Jay Faulkner (jason-oldos)]

That column is added in the initial DB setup: https://github.com/openstack/ironic-inspector/blob/master/ironic_inspector/migrations/versions/578f84f38d_inital_db_schema.py

Can you add more information about how/when you see this? As it is I can't see how this is possible.

[milan k (vetrisko)]

Seems this needs confirming from the reporter

[kimbarbel (kimbarbel)]

Hi,
I had the same error, my nodes table look like this:

MariaDB [ironic]> describe nodes;
+------------------------+--------------+------+-----+---------+----------------+
| Field | Type | Null | Key | Default | Extra |
+------------------------+--------------+------+-----+---------+----------------+
| created_at | datetime | YES | | NULL | |
| updated_at | datetime | YES | | NULL | |
| id | int(11) | NO | PRI | NULL | auto_increment |
| uuid | varchar(36) | YES | UNI | NULL | |
| instance_uuid | varchar(36) | YES | UNI | NULL | |
| name | varchar(255) | YES | UNI | NULL | |
| chassis_id | int(11) | YES | MUL | NULL | |
| power_state | varchar(15) | YES | | NULL | |
| target_power_state | varchar(15) | YES | | NULL | |
| provision_state | varchar(15) | YES | | NULL | |
| target_provision_state | varchar(15) | YES | | NULL | |
| provision_updated_at | datetime | YES | | NULL | |
| last_error | text | YES | | NULL | |
| instance_info | text | YES | | NULL | |
| properties | text | YES | | NULL | |
| driver | varchar(255) | YES | | NULL | |
| driver_info | text | YES | | NULL | |
| driver_internal_info | text | YES | | NULL | |
| clean_step | text | YES | | NULL | |
| resource_class | varchar(80) | YES | | NULL | |
| raid_config | text | YES | | NULL | |
| target_raid_config | text | YES | | NULL | |
| reservation | varchar(255) | YES | | NULL | |
| conductor_affinity | int(11) | YES | MUL | NULL | |
| maintenance | tinyint(1) | YES | | NULL | |
| maintenance_reason | text | YES | | NULL | |
| console_enabled | tinyint(1) | YES | | NULL | |
| inspection_finished_at | datetime | YES | | NULL | |
| inspection_started_at | datetime | YES | | NULL | |
| extra | text | YES | | NULL | |
| boot_interface | varchar(255) | YES | | NULL | |
| console_interface | varchar(255) | YES | | NULL | |
| deploy_interface | varchar(255) | YES | | NUL...

[Julia Kreger (juliaashleykreger)]

A point of clarification, the ironic nodes table is not the same as the inspector nodes table.

I think this is an incorrect configuration as opposed to a bug. I.e. pointing inspector at ironic's nodes DB. I also just can't see how this is happening.

Given the age, I'm going to close this item out as invalid.