[focal][ussuri] Cinder Volume service fails to start (looks like mysql-innodb-server was updating when it volume-service gave up connecting).

Bug #1954809 reported by Moises Emilio Benzan Mora
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Cinder Charm
Triaged
High
Unassigned

Bug Description

Cinder volume service fails to start due to `credentials` table not existing.

```
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume [req-ec766653-94e7-44ae-be8a-678a79450f41 - - - - -] Volume service juju-23c5d3-1-lxd-2@lvm failed to start.: oslo_db.exception.DBNonExistentTable: (
sqlite3.OperationalError) no such table: services
[SQL: SELECT services.created_at AS services_created_at, services.deleted_at AS services_deleted_at, services.deleted AS services_deleted, services.id AS services_id, services.uuid AS services_uuid, serv
ices.cluster_name AS services_cluster_name, services.host AS services_host, services.binary AS services_binary, services.updated_at AS services_updated_at, services.topic AS services_topic, services.repo
rt_count AS services_report_count, services.disabled AS services_disabled, services.availability_zone AS services_availability_zone, services.disabled_reason AS services_disabled_reason, services.modifie
d_at AS services_modified_at, services.rpc_current_version AS services_rpc_current_version, services.object_current_version AS services_object_current_version, services.replication_status AS services_rep
lication_status, services.active_backend_id AS services_active_backend_id, services.frozen AS services_frozen
FROM services
WHERE services.deleted = 0 AND services.binary = ?]
[parameters: ('cinder-scheduler',)]
(Background on this error at: http://sqlalche.me/e/e3q8)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume Traceback (most recent call last):
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1245, in _execute_context
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume self.dialect.do_execute(
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/engine/default.py", line 581, in do_execute
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume cursor.execute(statement, parameters)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume sqlite3.OperationalError: no such table: services
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume The above exception was the direct cause of the following exception:
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume Traceback (most recent call last):
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/cmd/volume.py", line 100, in _launch_service
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume server = service.Service.create(host=host,
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/service.py", line 394, in create
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume service_obj = cls(host, binary, topic, manager,
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/service.py", line 152, in __init__
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume self.manager = manager_class(host=self.host,
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/volume/manager.py", line 214, in __init__
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume super(VolumeManager, self).__init__(service_name='volume',
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/manager.py", line 180, in __init__
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume self.scheduler_rpcapi = scheduler_rpcapi.SchedulerAPI()
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/rpc.py", line 210, in __init__
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume obj_version_cap = self.determine_obj_version_cap()
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/rpc.py", line 262, in determine_obj_version_cap
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume version_cap = objects.Service.get_minimum_obj_version(
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/objects/service.py", line 221, in get_minimum_obj_version
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume return cls._get_minimum_version('object_current_version', context,
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/objects/service.py", line 192, in _get_minimum_version
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume services = ServiceList.get_all_by_binary(context, binary)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/objects/service.py", line 255, in get_all_by_binary
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume services = db.service_get_all(context, binary=binary,
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/db/api.py", line 133, in service_get_all
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume return IMPL.service_get_all(context, backend_match_level, **filters)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/db/sqlalchemy/api.py", line 165, in wrapper
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume return f(*args, **kwargs)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/cinder/db/sqlalchemy/api.py", line 547, in service_get_all
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume return [] if not query else query.all()
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/orm/query.py", line 3211, in all
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume return list(self)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/orm/query.py", line 3367, in __iter__
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume return self._execute_and_instances(context)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/orm/query.py", line 3392, in _execute_and_instances
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume result = conn.execute(querycontext.statement, self._params)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 982, in execute
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume return meth(self, multiparams, params)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume return connection._execute_clauseelement(self, multiparams, params)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1095, in _execute_clauseelement
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume ret = self._execute_context(
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1249, in _execute_context
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume self._handle_dbapi_exception(
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1474, in _handle_dbapi_exception
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume util.raise_from_cause(newraise, exc_info)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume reraise(type(exception), exception, tb=exc_tb, cause=cause)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/util/compat.py", line 152, in reraise
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume raise value.with_traceback(tb)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/engine/base.py", line 1245, in _execute_context
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume self.dialect.do_execute(
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/python3/dist-packages/sqlalchemy/engine/default.py", line 581, in do_execute
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume cursor.execute(statement, parameters)
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume oslo_db.exception.DBNonExistentTable: (sqlite3.OperationalError) no such table: services
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume [SQL: SELECT services.created_at AS services_created_at, services.deleted_at AS services_deleted_at, services.deleted AS services_deleted, services.id AS services_id, services.uuid AS services_uuid, services.cluster_name AS services_cluster_name, services.host AS services_host, services.binary AS services_binary, services.updated_at AS services_updated_at, services.topic AS services_topic, services.report_count AS services_report_count, services.disabled AS services_disabled, services.availability_zone AS services_availability_zone, services.disabled_reason AS services_disabled_reason, services.modified_at AS services_modified_at, services.rpc_current_version AS services_rpc_current_version, services.object_current_version AS services_object_current_version, services.replication_status AS services_replication_status, services.active_backend_id AS services_active_backend_id, services.frozen AS services_frozen
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume FROM services
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume WHERE services.deleted = 0 AND services.binary = ?]
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume [parameters: ('cinder-scheduler',)]
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume (Background on this error at: http://sqlalche.me/e/e3q8)
```

Test run can be found at: https://solutions.qa.canonical.com/testruns/testRun/5083ad9c-328e-4967-9211-51e33ba14f53

Artifacts for this run can be found at: https://oil-jenkins.canonical.com/artifacts/5083ad9c-328e-4967-9211-51e33ba14f53/index.html

Openstack logs for this run: https://oil-jenkins.canonical.com/artifacts/5083ad9c-328e-4967-9211-51e33ba14f53/generated/generated/openstack/juju-crashdump-openstack-2021-12-14-12.35.19.tar.gz

All occurrences of this bug can be tracked at: https://solutions.qa.canonical.com/bugs/bugs/bug/1954809

Tags: cdo-qa
description: updated
Revision history for this message
Alex Kavanagh (ajkavanagh) wrote :
Download full text (4.5 KiB)

The error you've pasted isn't actually relevant to the issue:

94e7-44ae-be8a-678a79450f41 - - - - -] Volume service juju-23c5d3-1-lxd-2@lvm failed to start.: oslo_db.exception.DBNonExistentTable: (
sqlite3.OperationalError)

The key part here is that is says "sqlite3..."; this means this log occurred before the cinder charm had related to the database and got database credentials. It's confusing because it looks like an error (and is), but only because the service gets started by the package before the charm has had a chance to configure it. Later in the log you see: (for cinder_0):

2021-12-14 09:16:10.178 68477 ERROR cinder.cmd.volume [req-5fae39cd-c7d2-4c92-8ada-f08334d32606 - - - - -] Volume service juju-23c5d3-1-lxd-2@LVM failed to start.: sqlalchemy.exc.OperationalError: (pymysql.err.OperationalError) (1045, "Access denied for user 'cinder'@'192.168.33.75' (using password: YES)")
(Background on this error at: http://sqlalche.me/e/e3q8)

The "pymysql.err" indicates that this is occurring after the database relation is made, but that the unit can't access the database.

cinder-volume gave up connecting at:

2021-12-14 09:17:27.828 72799 ERROR cinder.cmd.volume [req-e9bc0b92-1efa-4edd-a6b7-0954a539eabb - - - - -] No volume service(s) started successfully, terminating.

However, it looks like the mysql-router for cinder_0 was still chatting to the server (relation changed) at around 9:20 (from machine-lock)

2021-12-14 09:20:32 unit-cinder-mysql-router-1: cinder-mysql-router/1 uniter (run relation-changed (90; unit: mysql-innodb-cluster/1) hook), waited 0s, held 3
s

And it looked like it was switching to ssl/certificates at the time, which possibly means that the mysql-innodb-server was out during that time: (from the cinder-mysql-router/1 log):

2021-12-14 09:20:31 DEBUG unit.cinder-mysql-router/1.juju-log server.go:327 db-router:90: TLS mode PREFERRED
2021-12-14 09:20:31 DEBUG unit.cinder-mysql-router/1.juju-log server.go:327 db-router:90: Updating configuration parameters
2021-12-14 09:20:31 INFO unit.cinder-mysql-router/1.juju-log server.go:327 db-router:90: Writing /var/lib/mysql/cinder-mysql-router/mysqlrouter.conf
2021-12-14 09:20:31 DEBUG unit.cinder-mysql-router/1.juju-log server.go:327 db-router:90: Proactively resetting ssl_ca

On the mysql-innodb-server, that cinder unit didn't have a grant at 09:17:10:

2021-12-14 09:17:23 DEBUG unit.mysql-innodb-cluster/1.juju-log server.go:327 db-router:185: Single hostname provided by relation: 192.168.33.62
2021-12-14 09:17:23 DEBUG unit.mysql-innodb-cluster/1.juju-log server.go:327 db-router:185: Grant exists for host '192.168.33.62' on db 'cinder'
2021-12-14 09:17:23 DEBUG unit.mysql-innodb-cluster/1.juju-log server.go:327 db-router:185: Grant does NOT exist for host '192.168.33.75' on db 'cinder'
2021-12-14 09:17:23 DEBUG unit.mysql-innodb-cluster/1.juju-log server.go:327 db-router:185: Grant does NOT exist for host '192.168.33.82' on db 'cinder'
2021-12-14 09:17:23 DEBUG unit.mysql-innodb-cluster/1.juju-log server.go:327 db-router:185: Proactively resetting ssl_ca
2021-12-14 09:17:23 DEBUG unit.mysql-innodb-cluster/1.juju-log server.go:327 db-router:185: Single hostname provided b...

Read more...

summary: - [focal][ussuri] Cinder Volume service fails to start due to missing
- Credentials table
+ [focal][ussuri] Cinder Volume service fails to start (looks like mysql-
+ innodb-server was updating when it volume-service gave up connecting).
Changed in charm-cinder:
status: New → Triaged
importance: Undecided → High
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.