Error when using nova client - Unknown Error (HTTP 500)

[Martin Kalcok]

Unfortunately I did not get totally to the bottom of this issue and I don't have steps to reproduce either, but here's a summary of what happened.

I deployed focal-ussuri Openstack bundle [1] on the Openstack-backed juju (2.9.12) and everything worked fine. When I returned to the cloud the next day, I noticed that "nova" client fails with message

"ERROR (ClientException): Unknown Error (HTTP 500)"

Looking into the nova-related logs (compute/conductor/scheduler) I found following stacktrace:

2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task Traceback (most recent call last):
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task File "/usr/lib/python3/dist-packages/oslo_service/periodic_task.py", line 222, in run_periodic_tasks
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task task(self, context)
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task File "/usr/lib/python3/dist-packages/nova/compute/manager.py", line 10564, in _cleanup_expired_console_auth_tokens
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task objects.ConsoleAuthToken.clean_expired_console_auths(context)
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task File "/usr/lib/python3/dist-packages/oslo_versionedobjects/base.py", line 175, in wrapper
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task result = cls.indirection_api.object_class_action_versions(
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task File "/usr/lib/python3/dist-packages/nova/conductor/rpcapi.py", line 240, in object_class_action_versions
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task return cctxt.call(context, 'object_class_action_versions',
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task File "/usr/lib/python3/dist-packages/oslo_messaging/rpc/client.py", line 177, in call
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task self.transport._send(self.target, msg_ctxt, msg,
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task File "/usr/lib/python3/dist-packages/oslo_messaging/transport.py", line 124, in _send
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task return self._driver.send(target, ctxt, message,
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task File "/usr/lib/python3/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 652, in send
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task return self._send(target, ctxt, message, wait_for_reply, timeout,
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task File "/usr/lib/python3/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 644, in _send
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task raise result
2021-11-11 08:50:29.385 136452 ERROR oslo_service.periodic_task oslo_messaging.rpc.client.RemoteError: Remote error: DBError (pymysql.err.InternalError) (1129, 'Too many connection errors from 127.0.0.1:52190’)

I then noticed that "nova-mysql-router" unit was in the blocked state with message:

"Failed to connect to MySQL"

To resolve this, I tried to flush the hosts table in mysql [2] and restart services on the blocked "nova-mysql-router" unit. This helped me solve the problems with database and the unit got into active/idle state again. However problem with nova client persisted. I traced to problem to the "nova-api” apache vhost running on nova-cloud-controller unit. Error log of this vhost contained following (pretty cryptic) stacktrace:

2021-11-11 13:03:25.018270 Traceback (most recent call last):
2021-11-11 13:03:25.018595 File "/usr/bin/nova-api-wsgi", line 52, in <module>
2021-11-11 13:03:25.018704 application = init_application()
2021-11-11 13:03:25.018862 File "/usr/lib/python3/dist-packages/nova/api/openstack/compute/wsgi.py", line 20, in init_application
2021-11-11 13:03:25.018959 return wsgi_app.init_application(NAME)
2021-11-11 13:03:25.019093 File "/usr/lib/python3/dist-packages/nova/api/openstack/wsgi_app.py", line 83, in init_application
2021-11-11 13:03:25.019279 config.parse_args([], default_config_files=conf_files)
2021-11-11 13:03:25.019507 File "/usr/lib/python3/dist-packages/nova/config.py", line 42, in parse_args
2021-11-11 13:03:25.019650 log.register_options(CONF)
2021-11-11 13:03:25.019826 File "/usr/lib/python3/dist-packages/oslo_log/log.py", line 259, in register_options
2021-11-11 13:03:25.019991 conf.register_cli_opts(_options.common_cli_opts)
2021-11-11 13:03:25.020109 File "/usr/lib/python3/dist-packages/oslo_config/cfg.py", line 2055, in __inner
2021-11-11 13:03:25.020225 result = f(self, *args, **kwargs)
2021-11-11 13:03:25.020336 File "/usr/lib/python3/dist-packages/oslo_config/cfg.py", line 2341, in register_cli_opts
2021-11-11 13:03:25.020516 self.register_cli_opt(opt, group, clear_cache=False)
2021-11-11 13:03:25.020675 File "/usr/lib/python3/dist-packages/oslo_config/cfg.py", line 2059, in __inner
2021-11-11 13:03:25.020781 return f(self, *args, **kwargs)
2021-11-11 13:03:25.020916 File "/usr/lib/python3/dist-packages/oslo_config/cfg.py", line 2333, in register_cli_opt
2021-11-11 13:03:25.021025 raise ArgsAlreadyParsedError("cannot register CLI option")
2021-11-11 13:03:25.021231 oslo_config.cfg.ArgsAlreadyParsedError: arguments already parsed: cannot register CLI option

I tried to poke around a bit and I ended up restarting the apache2 service which ultimately solved my issue with nova client. So while I don't have cause of this issue or reproducible steps, here's my workaround:

* Flush mysql “hosts” DB [2]
* Restart services on blocked mysql-router units (using juju actions)
* Restart apache2 service on nova-cloud-controller leader.

---

[1] https://github.com/openstack-charmers/openstack-bundles/tree/master/development/openstack-base-focal-ussuri-ovn
[2] https://dev.mysql.com/doc/refman/8.0/en/flush.html#flush-hosts