[focal][ussuri] Cinder Volume service fails to start (looks like mysql-innodb-server was updating when it volume-service gave up connecting).
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-
sqlite3.
[SQL: SELECT services.created_at AS services_
ices.cluster_name AS services_
rt_count AS services_
d_at AS services_
lication_status, services.
FROM services
WHERE services.deleted = 0 AND services.binary = ?]
[parameters: ('cinder-
(Background on this error at: http://
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/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume self.dialect.
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume cursor.
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume sqlite3.
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/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume server = service.
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
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/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume self.manager = manager_
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume super(VolumeMan
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume self.scheduler_
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume obj_version_cap = self.determine_
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume version_cap = objects.
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume return cls._get_
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume services = ServiceList.
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume services = db.service_
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume return IMPL.service_
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
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/
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/
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/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume return self._execute_
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume result = conn.execute(
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
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/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume return connection.
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume ret = self._execute_
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume self._handle_
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume util.raise_
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume reraise(
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume raise value.with_
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume self.dialect.
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume File "/usr/lib/
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume cursor.
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume oslo_db.
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume [SQL: SELECT services.created_at AS services_
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-
2021-12-14 08:56:12.583 15808 ERROR cinder.cmd.volume (Background on this error at: http://
```
Test run can be found at: https:/
Artifacts for this run can be found at: https:/
Openstack logs for this run: https:/
All occurrences of this bug can be tracked at: https:/
description: | updated |
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 |
The error you've pasted isn't actually relevant to the issue:
94e7-44ae- be8a-678a79450f 41 - - - - -] Volume service juju-23c5d3- 1-lxd-2@ lvm failed to start.: oslo_db. exception. DBNonExistentTa ble: ( OperationalErro r)
sqlite3.
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-f08334d326 06 - - - - -] Volume service juju-23c5d3- 1-lxd-2@ LVM failed to start.: sqlalchemy. exc.Operational Error: (pymysql. err.Operational Error) (1045, "Access denied for user 'cinder' @'192.168. 33.75' (using password: YES)") sqlalche. me/e/e3q8)
(Background on this error at: http://
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-0954a539ea bb - - - - -] 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 mysql-router/ 1.juju- log server.go:327 db-router:90: Updating configuration parameters mysql-router/ 1.juju- log server.go:327 db-router:90: Writing /var/lib/ mysql/cinder- mysql-router/ mysqlrouter. conf mysql-router/ 1.juju- log server.go:327 db-router:90: Proactively resetting ssl_ca
2021-12-14 09:20:31 DEBUG unit.cinder-
2021-12-14 09:20:31 INFO unit.cinder-
2021-12-14 09:20:31 DEBUG unit.cinder-
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 innodb- cluster/ 1.juju- log server.go:327 db-router:185: Grant exists for host '192.168.33.62' on db 'cinder' innodb- cluster/ 1.juju- log server.go:327 db-router:185: Grant does NOT exist for host '192.168.33.75' on db 'cinder' innodb- cluster/ 1.juju- log server.go:327 db-router:185: Grant does NOT exist for host '192.168.33.82' on db 'cinder' innodb- cluster/ 1.juju- log server.go:327 db-router:185: Proactively resetting ssl_ca innodb- cluster/ 1.juju- log server.go:327 db-router:185: Single hostname provided b...
2021-12-14 09:17:23 DEBUG unit.mysql-
2021-12-14 09:17:23 DEBUG unit.mysql-
2021-12-14 09:17:23 DEBUG unit.mysql-
2021-12-14 09:17:23 DEBUG unit.mysql-
2021-12-14 09:17:23 DEBUG unit.mysql-