Ironic Inspector DBAPIError

[Danilo Chilene]

After a fresh deploy of Kolla 3.0.1, I'm getting the errors below from ironic_inspector container:

5809eexc968d4d kolla/ubuntu-source-ironic-inspector:3.0.1 "kolla_start" 15 seconds ago Up 14 seconds ironic_inspector

root@openstack2:/usr/local/share/kolla/ansible# docker logs ironic_inspector
INFO:__main__:Kolla config strategy set to: COPY_ALWAYS
INFO:__main__:Loading config file at /var/lib/kolla/config_files/config.json
INFO:__main__:Validating config file
INFO:__main__:Copying service configuration files
INFO:__main__:Copying /var/lib/kolla/config_files/ironic.conf to /etc/ironic-inspector/ironic.conf
INFO:__main__:Setting permissions for /etc/ironic-inspector/ironic.conf
INFO:__main__:Writing out command to execute
Running command: 'ironic-inspector --config-file /etc/ironic-inspector/ironic.conf'
2016-12-15 12:58:09.600 7 WARNING oslo_config.cfg [-] Option "identity_uri" from group "ironic" is deprecated for removal. Its value may be silently ignored in the future.
2016-12-15 12:58:09.601 7 WARNING oslo_config.cfg [-] Option "os_auth_url" from group "ironic" is deprecated for removal. Its value may be silently ignored in the future.
2016-12-15 12:58:09.601 7 WARNING oslo_config.cfg [-] Option "os_password" from group "ironic" is deprecated for removal. Its value may be silently ignored in the future.
2016-12-15 12:58:09.602 7 WARNING oslo_config.cfg [-] Option "os_tenant_name" from group "ironic" is deprecated for removal. Its value may be silently ignored in the future.
2016-12-15 12:58:09.602 7 WARNING oslo_config.cfg [-] Option "os_username" from group "ironic" is deprecated for removal. Its value may be silently ignored in the future.
2016-12-15 12:58:10.019 7 WARNING ironic_inspector.main [-] Introspection data will not be stored. Change "[processing] store_data" option if this is not the desired behavior
2016-12-15 12:58:10.047 7 INFO ironic_inspector.main [-] Enabled processing hooks: ['ramdisk_error', 'root_disk_selection', 'scheduler', 'validate_interfaces', 'capabilities', 'pci_devices']
2016-12-15 12:58:11.567 7 INFO werkzeug [-] * Running on http://0.0.0.0:5050/ (Press CTRL+C to quit)
2016-12-15 12:58:26.564 7 WARNING ironic_inspector.common.keystone [-] Group [ironic]: Using legacy auth loader is deprecated. Consider specifying appropriate keystone auth plugin as 'auth_type' and corresponding plugin options.
2016-12-15 12:58:26.594 7 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'SELECT nodes.uuid AS nodes_uuid \nFROM nodes \nWHERE nodes.finished_at IS NULL \n LIMIT %(param_1)s'] [parameters: {u'param_1': 1}]
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2016-12-15 12:58:26.594 7 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-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters context)
2016-12-15 12:58:26.594 7 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-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters cursor.execute(statement, parameters)
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/cursors.py", line 167, in execute
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters result = self._query(query)
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/cursors.py", line 323, in _query
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters conn.query(q)
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 836, in query
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 1020, in _read_query_result
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters result.read()
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 1303, in read
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters first_packet = self.connection._read_packet()
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 982, in _read_packet
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters packet.check_error()
2016-12-15 12:58:26.594 7 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-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters err.raise_mysql_exception(self._data)
2016-12-15 12:58:26.594 7 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-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters _check_mysql_exception(errinfo)
2016-12-15 12:58:26.594 7 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-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters raise InternalError(errno, errorvalue)
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1054, u"Unknown column 'nodes.finished_at' in 'where clause'")
2016-12-15 12:58:26.594 7 ERROR oslo_db.sqlalchemy.exc_filters
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main [-] Periodic update of firewall rules failed
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main Traceback (most recent call last):
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/ironic_inspector/main.py", line 315, in periodic_update
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main firewall.update_filters()
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/ironic_inspector/firewall.py", line 182, in update_filters
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main if not _should_enable_dhcp():
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/ironic_inspector/firewall.py", line 113, in _should_enable_dhcp
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main return (node_cache.introspection_active() or
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/ironic_inspector/node_cache.py", line 441, in introspection_active
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main return (db.model_query(db.Node.uuid).filter_by(finished_at=None).first()
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2659, in first
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main ret = list(self[0:1])
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2457, in __getitem__
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main return list(res)
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2761, in __iter__
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main return self._execute_and_instances(context)
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2776, in _execute_and_instances
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main result = conn.execute(querycontext.statement, self._params)
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 914, in execute
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main return meth(self, multiparams, params)
2016-12-15 12:58:26.599 7 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-12-15 12:58:26.599 7 ERROR ironic_inspector.main return connection._execute_clauseelement(self, multiparams, params)
2016-12-15 12:58:26.599 7 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-12-15 12:58:26.599 7 ERROR ironic_inspector.main compiled_sql, distilled_params
2016-12-15 12:58:26.599 7 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-12-15 12:58:26.599 7 ERROR ironic_inspector.main context)
2016-12-15 12:58:26.599 7 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-12-15 12:58:26.599 7 ERROR ironic_inspector.main util.raise_from_cause(newraise, exc_info)
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 202, in raise_from_cause
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main reraise(type(exception), exception, tb=exc_tb, cause=cause)
2016-12-15 12:58:26.599 7 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-12-15 12:58:26.599 7 ERROR ironic_inspector.main context)
2016-12-15 12:58:26.599 7 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-12-15 12:58:26.599 7 ERROR ironic_inspector.main cursor.execute(statement, parameters)
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/cursors.py", line 167, in execute
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main result = self._query(query)
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/cursors.py", line 323, in _query
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main conn.query(q)
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 836, in query
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 1020, in _read_query_result
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main result.read()
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 1303, in read
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main first_packet = self.connection._read_packet()
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 982, in _read_packet
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main packet.check_error()
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/pymysql/connections.py", line 394, in check_error
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main err.raise_mysql_exception(self._data)
2016-12-15 12:58:26.599 7 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-12-15 12:58:26.599 7 ERROR ironic_inspector.main _check_mysql_exception(errinfo)
2016-12-15 12:58:26.599 7 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-12-15 12:58:26.599 7 ERROR ironic_inspector.main raise InternalError(errno, errorvalue)
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main DBError: (pymysql.err.InternalError) (1054, u"Unknown column 'nodes.finished_at' in 'where clause'") [SQL: u'SELECT nodes.uuid AS nodes_uuid \nFROM nodes \nWHERE nodes.finished_at IS NULL \n LIMIT %(param_1)s'] [parameters: {u'param_1': 1}]
2016-12-15 12:58:26.599 7 ERROR ironic_inspector.main

[Jeffrey Zhang (jeffrey4l)]

ironic-inspector do not work at all, even on master branch. I have a patch to fix this.https://review.openstack.org/380774

[Danilo Chilene (bicofino)]

Tried Jeffrey's patch with 3.0.1, logs below:

TASK [ironic : Running Ironic Inspector bootstrap container] *******************
fatal: [localhost -> localhost]: FAILED! => {"changed": true, "failed": true, "msg": "Container exited with non-zero return code"}

NO MORE HOSTS LEFT *************************************************************
  to retry, use: --limit @/usr/local/share/kolla/ansible/site.retry

root@openstack2:~# docker logs -f bootstrap_ironic_inspector
INFO:__main__:Kolla config strategy set to: COPY_ALWAYS
INFO:__main__:Loading config file at /var/lib/kolla/config_files/config.json
INFO:__main__:Validating config file
INFO:__main__:Copying service configuration files
INFO:__main__:Copying /var/lib/kolla/config_files/inspector.conf to /etc/ironic-inspector/inspector.conf
INFO:__main__:Setting permissions for /etc/ironic-inspector/inspector.conf
INFO:__main__:Writing out command to execute
Running command: 'ironic-inspector --config-file /etc/ironic-inspector/inspector.conf'
2016-12-16 13:23:09.274 7 WARNING ironic_inspector.main [-] Introspection data will not be stored. Change "[processing] store_data" option if this is not the desired behavior
2016-12-16 13:23:09.302 7 INFO ironic_inspector.main [-] Enabled processing hooks: ['ramdisk_error', 'root_disk_selection', 'scheduler', 'validate_interfaces', 'capabilities', 'pci_devices']
2016-12-16 13:23:10.952 7 ERROR ironic_inspector.firewall [-] iptables ('-N', 'ironic-inspector') failed: iptables v1.6.0: can't initialize iptables table `filter': Permission denied (you must be root). Perhaps iptables or your kernel needs to be upgraded..
2016-12-16 13:23:10.953 7 CRITICAL ironic_inspector [-] CalledProcessError: Command '('sudo', 'ironic-inspector-rootwrap', '/etc/ironic-inspector/rootwrap.conf', 'iptables', '-w', '-N', 'ironic-inspector')' returned non-zero exit status 3
2016-12-16 13:23:10.953 7 ERROR ironic_inspector Traceback (most recent call last):
2016-12-16 13:23:10.953 7 ERROR ironic_inspector File "/var/lib/kolla/venv/bin/ironic-inspector", line 10, in <module>
2016-12-16 13:23:10.953 7 ERROR ironic_inspector sys.exit(main())
2016-12-16 13:23:10.953 7 ERROR ironic_inspector File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/ironic_inspector/main.py", line 465, in main
2016-12-16 13:23:10.953 7 ERROR ironic_inspector service.run(args, app)
2016-12-16 13:23:10.953 7 ERROR ironic_inspector File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/ironic_inspector/main.py", line 456, in run
2016-12-16 13:23:10.953 7 ERROR ironic_inspector self.init()
2016-12-16 13:23:10.953 7 ERROR ironic_inspector File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/ironic_inspector/main.py", line 423, in init
2016-12-16 13:23:10.953 7 ERROR ironic_inspector firewall.init()
2016-12-16 13:23:10.953 7 ERROR ironic_inspector File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/ironic_inspector/firewall.py", line 87, in init
2016-12-16 13:23:10.953 7 ERROR ironic_inspector _iptables('-N', CHAIN)
2016-12-16 13:23:10.953 7 ERROR ironic_inspector File "/var/lib/kolla/venv/local/lib/python2.7/site-packages/ironic_inspector/firewall.py", line...

[Jeffrey Zhang (jeffrey4l)]

I have a patch almost done please check https://review.openstack.org/380774

[Danilo Chilene (bicofino)]

Hi,

I don't have access to a server this week, going test it next week.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/380774
Committed: https://git.openstack.org/cgit/openstack/kolla/commit/?id=040ff6ea037357a84a6450c944648b83eb833454
Submitter: Jenkins
Branch: master

commit 040ff6ea037357a84a6450c944648b83eb833454
Author: Mauricio Lima <email address hidden>
Date: Fri Jan 13 15:32:35 2017 -0300

    Fix ironic inspector

    Co-Authored-By: Jeffrey Zhang <email address hidden>
    Closes-Bug: #1650345
    Change-Id: Id03619b4e26a0a77c2a39e2de21efd13be0e9200

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/420122
Committed: https://git.openstack.org/cgit/openstack/kolla-ansible/commit/?id=57365f16e3c8a0312114ff84b0d1ba7b07404abc
Submitter: Jenkins
Branch: master

commit 57365f16e3c8a0312114ff84b0d1ba7b07404abc
Author: Mauricio Lima <email address hidden>
Date: Fri Jan 13 15:19:20 2017 -0300

    Fix ironic inspector

    Co-Authored-By: Jeffrey Zhang <email address hidden>
    Depends-On: Id03619b4e26a0a77c2a39e2de21efd13be0e9200
    Change-Id: I723345c1b23cb92ad94cefd965f07b94095ebb41
    Closes-Bug: #1650345

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/kolla 4.0.0.0b3 development milestone.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/kolla-ansible 4.0.0.0b3 development milestone.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/newton
Review: https://review.openstack.org/439913

[OpenStack Infra (hudson-openstack)]

Change abandoned by Serguei Bezverkhi (<email address hidden>) on branch: stable/newton
Review: https://review.openstack.org/439913
Reason: Against stable policy

[Steven Dake (sdake)]

comment #10 is invalid. It is not against the stable policy to backport bug fixes.

[Steven Dake (sdake)]

This is in ocata branch, ignore the noise in the bug changing states.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/439913
Committed: https://git.openstack.org/cgit/openstack/kolla/commit/?id=608769bf99ef60be18c1dc9f6fd04578c9bcdf51
Submitter: Jenkins
Branch: stable/newton

commit 608769bf99ef60be18c1dc9f6fd04578c9bcdf51
Author: Mauricio Lima <email address hidden>
Date: Fri Jan 13 15:32:35 2017 -0300

    Fix ironic inspector

    Co-Authored-By: Jeffrey Zhang <email address hidden>
    Closes-Bug: #1650345
    Change-Id: Id03619b4e26a0a77c2a39e2de21efd13be0e9200
    (cherry picked from commit 040ff6ea037357a84a6450c944648b83eb833454)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/kolla 3.0.3 release.