OpenStack の DBaaS（Trove）導入 - 問題解析編 2

2021-04-20

OpenStack の DBaaS（Trove）導入 - 問題解析編 2

記事をシェアする

[！] この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

この記事は、OpenStack の DBaaS（Trove）導入において、データベースサーバーが正常動作しなかった場合の解析・対処について説明します。問題解析編 1 の続きとなっていますので、読んでいない方はそちらからご覧ください。

PostgreSQL サーバーが正常に起動しない問題の解析（後半）

発生事象

本問題の前半部分にあたる解析・対処を行ったが、PostgreSQL データストアを指定して Trove インスタンスを起動してもまだ正常起動しない。
Dashboard 画面上で Trove インスタンスがしばらく「作成中」状態のままとなり、その後「失敗」状態となる。
Dashboard のコンピュートインスタンスの画面に同名のインスタンスができるが、こちらは「実行中」状態となっている。

問題の解析

Trove プロセスのログ調査

前半と同様に、まず OpenStack サーバーホスト上の各 Trove プロセスのログから確認していきます。

コントローラーノード：

/var/log/trove/trove.log

ログから、前半と同様の流れが見えてきます。 trove-api は、Create database instance 要求を受けて、trove-taskmanager に処理を渡しています。また、要求の受付は 200 OK で返しています。

POST リクエストは Trove の API 一覧 ⧉と比較して、Create database instance という要求であるとわかります。

《ログを開く／閉じる》

1
2021-01-14 17:23:24.304 18255 DEBUG trove.common.auth [-] Authorized tenant '8fe1955b5a8841bb8dbf92a2503f42e3' request: POST /v1.0/8fe1955b5a8841bb8dbf92a2503f42e3/instances HTTP/1.0
2
...
3

4
{"instance": {"name": "post2", "availability_zone": "nova", "nics": [{"net-id": "752e0534-80a7-40ca-a95b-80f23366de20", "v4-fixed-ip": ""}], "flavorRef": "6", "volume": {"size": 1}, "datastore": {"version": "postgresql-9.6-ng2", "type": "postgresql"}}} authorize /usr/lib/python2.7/site-packages/trove/common/auth.py:68

trove-taskmanager の API で create_instance という要求を出しています。

《ログを開く／閉じる》

1
2021-01-14 17:23:24.383 18255 INFO trove.instance.service [-] Creating a database instance for tenant '8fe1955b5a8841bb8dbf92a2503f42e3'
2
2021-01-14 17:23:24.384 18255 DEBUG trove.instance.service [-] req : 'POST /v1.0/8fe1955b5a8841bb8dbf92a2503f42e3/instances HTTP/1.0
3
...
4
2021-01-14 17:23:24.385 18255 DEBUG trove.instance.service [-] body : '{u'instance': {u'name': u'post2', u'availability_zone': u'nova', u'nics': [{u'net-id': u'752e0534-80a7-40ca-a95b-80f23366de20', u'v4-fixed-ip': u''}], u'flavorRef': u'6', u'volume': {u'size': 1}, u'datastore': {u'version': u'postgresql-9.6-ng2', u'type': u'postgresql'}}}'
5

6
 create /usr/lib/python2.7/site-packages/trove/instance/service.py:269
7
...
8
2021-01-14 17:23:25.150 18255 DEBUG trove.common.notification [-] Sending event: dbaas.instance_create.start, {'client_ip': '192.168.151.32', 'name': u'post2', 'server_type': 'api', 'tenant_id': u'8fe1955b5a8841bb8dbf92a2503f42e3', 'datastore_version': u'postgresql-9.6-ng2', 'image_id': u'bb0fce9e-0c2b-496d-81cc-17463725b493', 'nics': [{u'net-id': u'752e0534-80a7-40ca-a95b-80f23366de20', u'v4-fixed-ip': u''}], 'flavor_id': u'6', 'server_ip': 'controller:8779', 'request_id': 'req-60730b9a-ddb6-493d-b308-aec28959e63c', 'availability_zone': u'nova', 'datastore': u'postgresql', 'volume_size': 1, 'region_name': 'otm'} _notify /usr/lib/python2.7/site-packages/trove/common/notification.py:405
9
...
10
2021-01-14 17:23:25.302 18255 DEBUG trove.instance.models [-] Generated unique RPC encryption key for instance. key = 0CFH7uciEiUU21fxvCgw06z3HIb04Qki __init__ /usr/lib/python2.7/site-packages/trove/instance/models.py:1601
11
2021-01-14 17:23:25.303 18255 DEBUG trove.db.models [-] Saving DBInstance: {u'encrypted_key': '***', u'updated': datetime.datetime(2021, 1, 14, 8, 23, 25, 303272), '_sa_instance_state': <sqlalchemy.orm.state.InstanceState object at 0x7f716e7b2110>, u'name': u'post2', u'task_id': 5, u'created': datetime.datetime(2021, 1, 14, 8, 23, 25, 257370), u'deleted': False, u'tenant_id': u'8fe1955b5a8841bb8dbf92a2503f42e3', u'configuration_id': None, u'task_description': u'The instance is building.', u'volume_size': 1, 'errors': {}, u'cluster_id': None, u'flavor_id': u'6', u'shard_id': None, u'slave_of_id': None, u'type': None, u'id': u'1f3cc110-dd88-45ca-b9bd-a9c20ff24224', u'datastore_version_id': u'11cbc7b4-5d01-44d5-80ae-fc76c13aee01', u'region_id': u'otm'} save /usr/lib/python2.7/site-packages/trove/db/models.py:65
12
2021-01-14 17:23:25.330 18255 DEBUG trove.instance.models [-] Tenant 8fe1955b5a8841bb8dbf92a2503f42e3 created new Trove instance 1f3cc110-dd88-45ca-b9bd-a9c20ff24224 in region otm. _create_resources /usr/lib/python2.7/site-packages/trove/instance/models.py:1042
13
★ 2021-01-14 17:23:25.459 18255 DEBUG trove.taskmanager.api [-] Making async call to create instance 1f3cc110-dd88-45ca-b9bd-a9c20ff24224  create_instance /usr/lib/python2.7/site-packages/trove/taskmanager/api.py:198
14
★ 2021-01-14 17:23:25.461 18255 DEBUG trove.taskmanager.api [-] Casting create_instance _cast /usr/lib/python2.7/site-packages/trove/taskmanager/api.py:76

POST リクエストの受け付けは 200 OK となっています。

《ログを開く／閉じる》

1
2021-01-14 17:23:25.568 18255 DEBUG trove.instance.views [-] {'status': 'BUILD', 'name': u'post2', 'links': [{'href': u'https://controller:8779/v1.0/8fe1955b5a8841bb8dbf92a2503f42e3/instances/1f3cc110-dd88-45ca-b9bd-a9c20ff24224', 'rel': 'self'}, {'href': 'https://controller:8779/instances/1f3cc110-dd88-45ca-b9bd-a9c20ff24224', 'rel': 'bookmark'}], 'region': 'otm', 'id': '1f3cc110-dd88-45ca-b9bd-a9c20ff24224', 'volume': {'size': 1}, 'flavor': {'id': '6', 'links': [{'href': u'https://controller:8779/v1.0/8fe1955b5a8841bb8dbf92a2503f42e3/flavors/6', 'rel': 'self'}, {'href': 'https://controller:8779/flavors/6', 'rel': 'bookmark'}]}, 'datastore': {'version': u'postgresql-9.6-ng2', 'type': u'postgresql'}} data /usr/lib/python2.7/site-packages/trove/instance/views.py:59
2
2021-01-14 17:23:25.579 18255 INFO eventlet.wsgi [-] 192.168.151.32 - - [14/Jan/2021 17:23:25] "POST /v1.0/8fe1955b5a8841bb8dbf92a2503f42e3/instances HTTP/1.1" 200 858 1.276645

trove-taskmanager 側のログを確認していきます。

コントローラーノード：

/var/log/trove/trove-taskmanager.log

ログから、前半と同様に進んでいます。 trove-taskmanager は、Trove インスタンス用の仮想マシンを作成し、trove-guestagent に prepare 要求を出しますが、時間経過後にエラーとなっています。

まず、Trove インスタンスの作成が開始され、Neutron（ネットワーク）やボリュームの処理を呼び、その後、仮想マシンインスタンスを作成しています。

《ログを開く／閉じる》

1
2021-01-14 17:23:25.553 16331 DEBUG trove.instance.models [-] Instance 1f3cc110-dd88-45ca-b9bd-a9c20ff24224 service status is new. load_instance /usr/lib/python2.7/site-packages/trove/instance/models.py:546
2
...
3
2021-01-14 17:23:25.608 16331 INFO trove.taskmanager.models [-] Creating instance 1f3cc110-dd88-45ca-b9bd-a9c20ff24224.
4
...
5
2021-01-14 17:23:26.433 16331 DEBUG neutronclient.client [-] POST call to neutron for http://controller:9696/v2.0/security-groups used request id req-6791f885-f3d1-4235-8b8c-1a7116474017 _cs_request /usr/lib/python2.7/site-packages/neutronclient/client.py:127
6
...
7
2021-01-14 17:23:26.830 16331 DEBUG neutronclient.client [-] POST call to neutron for http://controller:9696/v2.0/security-group-rules used request id req-04cdc7a2-40dc-4593-b3a4-563868d22ec2 _cs_request /usr/lib/python2.7/site-packages/neutronclient/client.py:127
8
...
9
2021-01-14 17:23:26.846 16331 DEBUG trove.taskmanager.models [-] Successfully created security group for instance: 1f3cc110-dd88-45ca-b9bd-a9c20ff24224 create_instance /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:482
10
2021-01-14 17:23:26.877 16331 DEBUG trove.taskmanager.models [-] Begin _create_server_volume_individually for id: 1f3cc110-dd88-45ca-b9bd-a9c20ff24224 _create_server_volume_individually /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:794
11
2021-01-14 17:23:26.877 16331 DEBUG trove.taskmanager.models [-] trove volume support = True _build_volume_info /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:824
12
2021-01-14 17:23:26.877 16331 DEBUG trove.taskmanager.models [-] Begin _create_volume for id: 1f3cc110-dd88-45ca-b9bd-a9c20ff24224 _create_volume /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:865
13
...
14
2021-01-14 17:23:39.973 16331 DEBUG trove.taskmanager.models [-] End _create_volume for id: 1f3cc110-dd88-45ca-b9bd-a9c20ff24224 _create_volume /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:885
15
2021-01-14 17:23:39.974 16331 DEBUG trove.taskmanager.models [-] Created volume <Volume: e25d1ef5-598c-4c0f-8e56-f5226136fc9d> _build_volume /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:889
16
2021-01-14 17:23:39.974 16331 DEBUG trove.taskmanager.models [-] block_device = {'vdb': u'e25d1ef5-598c-4c0f-8e56-f5226136fc9d::1:1'}
17
volume = [{'id': u'e25d1ef5-598c-4c0f-8e56-f5226136fc9d', 'size': 1}]
18
device_path = /dev/vdb
19
mount_point = /var/lib/postgresql _build_volume /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:909
20
...
21
2021-01-14 17:23:40.385 16331 DEBUG novaclient.v2.client [-] REQ: curl -g -i -X POST http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers -H "User-Agent: python-novaclient"
22
...
23
2021-01-14 17:23:47.952 16331 DEBUG novaclient.v2.client [-] POST call to compute for http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers used request id req-3f85434f-c719-4604-a718-f62f07cbf67a request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:722
24
2021-01-14 17:23:47.952 16331 DEBUG trove.taskmanager.models [-] Created new compute instance 390252a0-12d1-4a7a-92a5-999fcc346869 for instance 1f3cc110-dd88-45ca-b9bd-a9c20ff24224 _create_server /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:942

新規インスタンス上にいる、trove-guestagent の API で prepare を要求しています。

《ログを開く／閉じる》

1
2021-01-14 17:23:47.974 16331 DEBUG trove.taskmanager.models [-] End _create_server_volume_individually for id: 1f3cc110-dd88-45ca-b9bd-a9c20ff24224 _create_server_volume_individually /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:815
2
2021-01-14 17:23:47.979 16331 DEBUG trove.taskmanager.models [-] Entering guest_prepare _guest_prepare /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:950
3
★ 2021-01-14 17:23:47.979 16331 DEBUG trove.guestagent.api [-] Sending the call to prepare the Guest. prepare /usr/lib/python2.7/site-packages/trove/guestagent/api.py:321
4
★ 2021-01-14 17:23:48.477 16331 DEBUG trove.guestagent.api [-] Casting prepare _cast /usr/lib/python2.7/site-packages/trove/guestagent/api.py:104
5
2021-01-14 17:23:48.494 16331 INFO trove.instance.models [-] Resetting task status to NONE on instance 1f3cc110-dd88-45ca-b9bd-a9c20ff24224.

このあたりから処理の完了待ちです。

《ログを開く／閉じる》

1
2021-01-14 17:23:48.518 16331 DEBUG trove.taskmanager.models [-] trove dns support = False _create_dns_entry /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:964
2
2021-01-14 17:23:48.518 16331 DEBUG trove.taskmanager.models [-] <greenlet.greenlet object at 0x7f55444b7050>: DNS not enabled for instance: 1f3cc110-dd88-45ca-b9bd-a9c20ff24224 _create_dns_entry /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:1005
3
...
4
2021-01-14 17:23:48.912 16331 DEBUG novaclient.v2.client [-] RESP: [200] Content-Length: 1291 Content-Type: application/json X-Openstack-Request-Id: req-d1167116-c573-4028-be5f-2f3fa9e654b8 X-Compute-Request-Id: req-d1167116-c573-4028-be5f-2f3fa9e654b8 Date: Thu, 14 Jan 2021 08:23:48 GMT Connection: keep-alive
5
RESP BODY: {"server": {"OS-EXT-STS:task_state": "scheduling", "addresses": {}, "links": [{"href": "http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/390252a0-12d1-4a7a-92a5-999fcc346869", "rel": "self"}, {"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/servers/390252a0-12d1-4a7a-92a5-999fcc346869", "rel": "bookmark"}], "image": {"id": "bb0fce9e-0c2b-496d-81cc-17463725b493", "links": [{"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/images/bb0fce9e-0c2b-496d-81cc-17463725b493", "rel": "bookmark"}]}, "OS-EXT-STS:vm_state": "building", "OS-SRV-USG:launched_at": null, "flavor": {"id": "6", "links": [{"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/flavors/6", "rel": "bookmark"}]}, "id": "390252a0-12d1-4a7a-92a5-999fcc346869", "user_id": "0efa122c24aa4784b241e0eb08e15edd", "OS-DCF:diskConfig": "MANUAL", "accessIPv4": "", "accessIPv6": "", "progress": 0, "OS-EXT-STS:power_state": 0, "OS-EXT-AZ:availability_zone": "nova", "config_drive": "True", "status": "BUILD", "updated": "2021-01-14T08:23:48Z", "hostId": "", "OS-SRV-USG:terminated_at": null, "key_name": null, "name": "post2", "created": "2021-01-14T08:23:47Z", "tenant_id": "8fe1955b5a8841bb8dbf92a2503f42e3", "os-extended-volumes:volumes_attached": [], "metadata": {}}}
6
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:419
7
2021-01-14 17:23:48.912 16331 DEBUG novaclient.v2.client [-] GET call to compute for http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/390252a0-12d1-4a7a-92a5-999fcc346869 used request id req-d1167116-c573-4028-be5f-2f3fa9e654b8 request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:722
8
...
9
2021-01-14 17:23:57.519 16331 DEBUG novaclient.v2.client [-] RESP: [200] Content-Length: 1471 Content-Type: application/json X-Openstack-Request-Id: req-24120790-6ffd-4cba-8ebc-71ca18dc6c75 X-Compute-Request-Id: req-24120790-6ffd-4cba-8ebc-71ca18dc6c75 Date: Thu, 14 Jan 2021 08:23:57 GMT Connection: keep-alive
10
RESP BODY: {"server": {"OS-EXT-STS:task_state": "spawning", "addresses": {}, "links": [{"href": "http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/390252a0-12d1-4a7a-92a5-999fcc346869", "rel": "self"}, {"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/servers/390252a0-12d1-4a7a-92a5-999fcc346869", "rel": "bookmark"}], "image": {"id": "bb0fce9e-0c2b-496d-81cc-17463725b493", "links": [{"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/images/bb0fce9e-0c2b-496d-81cc-17463725b493", "rel": "bookmark"}]}, "OS-EXT-STS:vm_state": "building", "OS-SRV-USG:launched_at": null, "flavor": {"id": "6", "links": [{"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/flavors/6", "rel": "bookmark"}]}, "id": "390252a0-12d1-4a7a-92a5-999fcc346869", "security_groups": [{"name": "SecGroup_1f3cc110-dd88-45ca-b9bd-a9c20ff24224"}], "user_id": "0efa122c24aa4784b241e0eb08e15edd", "OS-DCF:diskConfig": "MANUAL", "accessIPv4": "", "accessIPv6": "", "progress": 0, "OS-EXT-STS:power_state": 0, "OS-EXT-AZ:availability_zone": "nova", "config_drive": "True", "status": "BUILD", "updated": "2021-01-14T08:23:54Z", "hostId": "1ff933a0770f3ab36aea075aa3be79a262fd0daf080b50359e679444", "OS-SRV-USG:terminated_at": null, "key_name": null, "name": "post2", "created": "2021-01-14T08:23:47Z", "tenant_id": "8fe1955b5a8841bb8dbf92a2503f42e3", "os-extended-volumes:volumes_attached": [{"id": "e25d1ef5-598c-4c0f-8e56-f5226136fc9d"}], "metadata": {}}}
11
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:419
12
2021-01-14 17:23:57.520 16331 DEBUG novaclient.v2.client [-] GET call to compute for http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/390252a0-12d1-4a7a-92a5-999fcc346869 used request id req-24120790-6ffd-4cba-8ebc-71ca18dc6c75 request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:722
13
...
14
2021-01-14 17:24:10.014 16331 DEBUG novaclient.v2.client [-] RESP: [200] Content-Length: 1619 Content-Type: application/json X-Openstack-Request-Id: req-6ade50a6-b05c-4b8a-aa76-012ac0b1bdda X-Compute-Request-Id: req-6ade50a6-b05c-4b8a-aa76-012ac0b1bdda Date: Thu, 14 Jan 2021 08:24:10 GMT Connection: keep-alive
15
RESP BODY: {"server": {"OS-EXT-STS:task_state": null, "addresses": {"trove-test-net": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:e5:d0:86", "version": 4, "addr": "10.6.2.19", "OS-EXT-IPS:type": "fixed"}]}, "links": [{"href": "http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/390252a0-12d1-4a7a-92a5-999fcc346869", "rel": "self"}, {"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/servers/390252a0-12d1-4a7a-92a5-999fcc346869", "rel": "bookmark"}], "image": {"id": "bb0fce9e-0c2b-496d-81cc-17463725b493", "links": [{"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/images/bb0fce9e-0c2b-496d-81cc-17463725b493", "rel": "bookmark"}]}, "OS-EXT-STS:vm_state": "active", "OS-SRV-USG:launched_at": "2021-01-14T08:23:58.000000", "flavor": {"id": "6", "links": [{"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/flavors/6", "rel": "bookmark"}]}, "id": "390252a0-12d1-4a7a-92a5-999fcc346869", "security_groups": [{"name": "SecGroup_1f3cc110-dd88-45ca-b9bd-a9c20ff24224"}], "user_id": "0efa122c24aa4784b241e0eb08e15edd", "OS-DCF:diskConfig": "MANUAL", "accessIPv4": "", "accessIPv6": "", "progress": 0, "OS-EXT-STS:power_state": 1, "OS-EXT-AZ:availability_zone": "nova", "config_drive": "True", "status": "ACTIVE", "updated": "2021-01-14T08:23:58Z", "hostId": "1ff933a0770f3ab36aea075aa3be79a262fd0daf080b50359e679444", "OS-SRV-USG:terminated_at": null, "key_name": null, "name": "post2", "created": "2021-01-14T08:23:47Z", "tenant_id": "8fe1955b5a8841bb8dbf92a2503f42e3", "os-extended-volumes:volumes_attached": [{"id": "e25d1ef5-598c-4c0f-8e56-f5226136fc9d"}], "metadata": {}}}
16
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:419
17
2021-01-14 17:24:10.015 16331 DEBUG novaclient.v2.client [-] GET call to compute for http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/390252a0-12d1-4a7a-92a5-999fcc346869 used request id req-6ade50a6-b05c-4b8a-aa76-012ac0b1bdda request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:722
18
...

約 11 分経過後、前半と同様に、エラーになっています。他のログの調査も必要です。

《ログを開く／閉じる》

1
2021-01-14 17:34:45.406 16331 ERROR oslo.service.loopingcall [-] Dynamic backoff interval looping call 'trove.common.utils.poll_and_check' failed: TroveError: Service not active, status: failed to spawn
2
2021-01-14 17:34:45.406 16331 ERROR oslo.service.loopingcall Traceback (most recent call last):
3
2021-01-14 17:34:45.406 16331 ERROR oslo.service.loopingcall   File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 137, in _run_loop
4
2021-01-14 17:34:45.406 16331 ERROR oslo.service.loopingcall     result = func(*self.args, **self.kw)
5
2021-01-14 17:34:45.406 16331 ERROR oslo.service.loopingcall   File "/usr/lib/python2.7/site-packages/trove/common/utils.py", line 192, in poll_and_check
6
2021-01-14 17:34:45.406 16331 ERROR oslo.service.loopingcall     obj = retriever()
7
2021-01-14 17:34:45.406 16331 ERROR oslo.service.loopingcall   File "/usr/lib/python2.7/site-packages/trove/taskmanager/models.py", line 714, in _service_is_active
8
2021-01-14 17:34:45.406 16331 ERROR oslo.service.loopingcall     raise TroveError(_("Service not active, status: %s") % status)
9
2021-01-14 17:34:45.406 16331 ERROR oslo.service.loopingcall TroveError: Service not active, status: failed to spawn
10
2021-01-14 17:34:45.406 16331 ERROR oslo.service.loopingcall
11
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models [-] Failed to send usage create-event for instance 1f3cc110-dd88-45ca-b9bd-a9c20ff24224.: TroveError: Service not active, status: failed to spawn
12
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models Traceback (most recent call last):
13
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models   File "/usr/lib/python2.7/site-packages/trove/taskmanager/models.py", line 438, in wait_for_instance
14
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models     time_out=timeout)
15
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models   File "/usr/lib/python2.7/site-packages/trove/common/utils.py", line 214, in poll_until
16
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models     sleep_time=sleep_time, time_out=time_out).wait()
17
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models   File "/usr/lib/python2.7/site-packages/eventlet/event.py", line 121, in wait
18
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models     return hubs.get_hub().switch()
19
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models   File "/usr/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 294, in switch
20
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models     return self.greenlet.switch()
21
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models   File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 137, in _run_loop
22
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models     result = func(*self.args, **self.kw)
23
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models   File "/usr/lib/python2.7/site-packages/trove/common/utils.py", line 192, in poll_and_check
24
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models     obj = retriever()
25
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models   File "/usr/lib/python2.7/site-packages/trove/taskmanager/models.py", line 714, in _service_is_active
26
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models     raise TroveError(_("Service not active, status: %s") % status)
27
★ 2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models TroveError: Service not active, status: failed to spawn
28
2021-01-14 17:34:45.406 16331 ERROR trove.taskmanager.models
29
2021-01-14 17:34:45.419 16331 DEBUG trove.db.models [-] Saving DBInstanceFault: {u'updated': datetime.datetime(2021, 1, 14, 8, 34, 45, 419436), '_sa_instance_state': <sqlalchemy.orm.state.InstanceState object at 0x7f55440f0dd0>, u'created': datetime.datetime(2021, 1, 14, 8, 34, 31), u'deleted': 0, u'instance_id': u'1f3cc110-dd88-45ca-b9bd-a9c20ff24224', 'errors': {}, u'details': u'Traceback (most recent call last):\n  File "/usr/lib/python2.7/site-packages/trove/taskmanager/models.py", line 438, in wait_for_instance\n    time_out=timeout)\n  File "/usr/lib/python2.7/site-packages/trove/common/utils.py", line 214, in poll_until\n    sleep_time=sleep_time, time_out=time_out).wait()\n  File "/usr/lib/python2.7/site-packages/eventlet/event.py", line 121, in wait\n    return hubs.get_hub().switch()\n  File "/usr/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 294, in switch\n    return self.greenlet.switch()\n  File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 137, in _run_loop\n    result = func(*self.args, **self.kw)\n  File "/usr/lib/python2.7/site-packages/trove/common/utils.py", line 192, in poll_and_check\n    obj = retriever()\n  File "/usr/lib/python2.7/site-packages/trove/taskmanager/models.py", line 714, in _service_is_active\n    raise TroveError(_("Service not active, status: %s") % status)\nTroveError: Service not active, status: failed to spawn\n', u'message': u'Service not active, status: failed to spawn', u'deleted_at': None, u'id': u'b0ed68d6-6018-4183-b5e3-2aa3f6513d4f'} save /usr/lib/python2.7/site-packages/trove/db/models.py:65

trove-conductor のログを確認します。

コントローラーノード：

/var/log/trove/trove-conductor.log

ログから、最終的にやはり failed to spawn 状態の通知を受けています。

はじめに、building 状態の通知です。

《ログを開く／閉じる》

1
2021-01-14 17:24:29.516 17487 DEBUG trove.conductor.manager [-] Instance ID: 1f3cc110-dd88-45ca-b9bd-a9c20ff24224, Payload: {u'service_status': u'building'} heartbeat /usr/lib/python2.7/site-packages/trove/conductor/manager.py:86

failed to spawn 状態の通知です。また、Database failed to stop. のメッセージが見えています。

《ログを開く／閉じる》

1
2021-01-14 17:34:31.107 17202 DEBUG trove.conductor.manager [-] Instance ID: 1f3cc110-dd88-45ca-b9bd-a9c20ff24224, Payload: {u'service_status': u'failed to spawn'} heartbeat /usr/lib/python2.7/site-packages/trove/conductor/manager.py:86
2
...
3
2021-01-14 17:34:31.183 17207 ERROR trove.conductor.manager [-] Guest exception on request req-60730b9a-ddb6-493d-b308-aec28959e63c:
4
[u'Traceback (most recent call last):\n', u'  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/manager.py", line 270, in prepare\n    cluster_config, snapshot, modules)\n', u'  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/manager.py", line 285, in _prepare\n    cluster_config, snapshot)\n', u'  File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 158, in wrapper\n    result = f(*args, **kwargs)\n', u'  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/manager.py", line 219, in do_prepare\n    self.app.stop_db()\n', u'  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/service.py", line 396, in stop_db\n    disable_on_boot=do_not_start_on_reboot, update_db=update_db)\n', u'  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/service.py", line 297, in stop_db_service\n    raise RuntimeError(_("Database failed to stop."))\n', u'RuntimeError: Database failed to stop.\n']
5
...
6
2021-01-14 17:34:31.184 17207 DEBUG trove.common.notification [-] Sending event: dbaas.instance_create.error, {'client_ip': u'192.168.151.32', 'server_type': u'guest', 'tenant_id': u'8fe1955b5a8841bb8dbf92a2503f42e3', 'exception': [u'Traceback (most recent call last):\n', u'  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/manager.py", line 270, in prepare\n    cluster_config, snapshot, modules)\n', u'  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/manager.py", line 285, in _prepare\n    cluster_config, snapshot)\n', u'  File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 158, in wrapper\n    result = f(*args, **kwargs)\n', u'  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/manager.py", line 219, in do_prepare\n    self.app.stop_db()\n', u'  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/service.py", line 396, in stop_db\n    disable_on_boot=do_not_start_on_reboot, update_db=update_db)\n', u'  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/service.py", line 297, in stop_db_service\n    raise RuntimeError(_("Database failed to stop."))\n', u'RuntimeError: Database failed to stop.\n'], 'instance_id': u'1f3cc110-dd88-45ca-b9bd-a9c20ff24224', 'server_ip': u'controller:8779', 'request_id': u'req-60730b9a-ddb6-493d-b308-aec28959e63c', 'message': u'Database failed to stop.'} _notify /usr/lib/python2.7/site-packages/trove/common/notification.py:405
7
...
8
2021-01-14 17:34:31.207 17207 DEBUG trove.db.models [-] Saving DBInstanceFault: {u'updated': datetime.datetime(2021, 1, 14, 8, 34, 31, 199721), '_sa_instance_state': <sqlalchemy.orm.state.InstanceState object at 0x7f8570fa6fd0>, u'created': datetime.datetime(2021, 1, 14, 8, 34, 31, 199512), u'deleted': False, u'instance_id': u'1f3cc110-dd88-45ca-b9bd-a9c20ff24224', 'errors': {}, u'details': u'Server type: guest\nTraceback (most recent call last):\n  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/manager.py", line 270, in prepare\n    cluster_config, snapshot, modules)\n  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/manager.py", line 285, in _prepare\n    cluster_config, snapshot)\n  File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 158, in wrapper\n    result = f(*args, **kwargs)\n  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/manager.py", line 219, in do_prepare\n    self.app.stop_db()\n  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/service.py", line 396, in stop_db\n    disable_on_boot=do_not_start_on_reboot, update_db=update_db)\n  File "/home/XXXXXXXX/trove/trove/guestagent/datastore/service.py", line 297, in stop_db_service\n    raise RuntimeError(_("Database failed to stop."))\nRuntimeError: Database failed to stop.\n', u'message': u'Database failed to stop.', u'id': u'b0ed68d6-6018-4183-b5e3-2aa3f6513d4f'} save /usr/lib/python2.7/site-packages/trove/db/models.py:65

データベース操作の詳細は trove-guestagent が担当しているため、Trove インスタンスに入って確認していきます。

Trove インスタンスの調査

Trove インスタンスにログインし、状況を確認していきます。

trove-guestagent のログ確認

Trove インスタンス：

/var/log/trove/logfile.txt

ログから、エラーの発生は前半と同様になっているように見えます。

trove-guestagent は prepare 処理を開始し、設定変更のため一旦 PostgreSQL サーバーを停止して状態監視を行いますが、10 分後にタイムアウトして停止の失敗としてエラーになっています。

まずは、prepare 処理の開始です。

《ログを開く／閉じる》

1
2021-01-14 08:24:29.330 1240 INFO trove.guestagent.datastore.manager [-] Starting datastore prepare for 'postgresql'.
2
2021-01-14 08:24:29.331 1240 DEBUG trove.guestagent.datastore.service [-] Casting set_status message to conductor (status is 'building'). set_status /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:166
3
2021-01-14 08:24:29.332 1240 DEBUG trove.conductor.api [-] Making async call to cast heartbeat for instance: 1f3cc110-dd88-45ca-b9bd-a9c20ff24224 heartbeat /home/XXXXXXXX/trove/trove/conductor/api.py:73
4
2021-01-14 08:24:29.369 1240 DEBUG trove.guestagent.datastore.service [-] Successfully cast set_status. set_status /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:173
5
2021-01-14 08:24:29.369 1240 DEBUG trove.guestagent.datastore.experimental.postgresql.service [-] 1f3cc110-dd88-45ca-b9bd-a9c20ff24224: Beginning PgSql package installation. install /home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/service.py:317

設定変更のためにデータベースサービスを停止しています。

《ログを開く／閉じる》

1
2021-01-14 08:24:29.482 1240 DEBUG trove.guestagent.datastore.experimental.postgresql.manager [-] Stopping database prior to initial configuration. do_prepare /home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/manager.py:218
2
2021-01-14 08:24:29.483 1240 INFO trove.guestagent.datastore.service [-] Stopping database service.
3
2021-01-14 08:24:29.483 1240 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): sudo service postgresql stop execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
4
2021-01-14 08:24:30.151 1240 DEBUG oslo_concurrency.processutils [-] CMD "sudo service postgresql stop" returned: 0 in 0.668s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
5
2021-01-14 08:24:30.152 1240 DEBUG trove.guestagent.datastore.service [-] Waiting for database to shutdown. stop_db_service /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:294

pg_isready コマンドで PostgreSQL サーバーの状態を確認し、shutdown 状態になるのを待っています。

《ログを開く／閉じる》

1
2021-01-14 08:24:30.152 1240 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): /usr/lib/postgresql/9.6/bin/pg_isready -h localhost execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2
2021-01-14 08:24:30.177 1240 DEBUG oslo_concurrency.processutils [-] CMD "/usr/lib/postgresql/9.6/bin/pg_isready -h localhost" returned: 0 in 0.025s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
3
2021-01-14 08:24:30.178 1240 DEBUG trove.guestagent.datastore.service [-] Waiting for DB status to change from running to shutdown. wait_for_real_status_to_change_to /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:366
4
...
5
2021-01-14 08:24:33.179 1240 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): /usr/lib/postgresql/9.6/bin/pg_isready -h localhost execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
6
2021-01-14 08:24:33.205 1240 DEBUG oslo_concurrency.processutils [-] CMD "/usr/lib/postgresql/9.6/bin/pg_isready -h localhost" returned: 0 in 0.026s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
7
2021-01-14 08:24:33.206 1240 DEBUG trove.guestagent.datastore.service [-] Waiting for DB status to change from running to shutdown. wait_for_real_status_to_change_to /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:366
8
...

約 10 分後にエラーとなりました。running 状態から shutdown 状態に変わるのを待っていたがタイムアウトしたと出ています。

《ログを開く／閉じる》

1
2021-01-14 08:34:31.028 1240 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): /usr/lib/postgresql/9.6/bin/pg_isready -h localhost execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2
2021-01-14 08:34:31.059 1240 DEBUG oslo_concurrency.processutils [-] CMD "/usr/lib/postgresql/9.6/bin/pg_isready -h localhost" returned: 0 in 0.031s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
3
★ 2021-01-14 08:34:31.060 1240 ERROR trove.guestagent.datastore.service [-] Timeout while waiting for database status to change.Expected state shutdown, current state is running
4
★ 2021-01-14 08:34:31.060 1240 INFO trove.guestagent.datastore.service [-] Service status did not change to shutdown within the given timeout: 600s
5
2021-01-14 08:34:31.060 1240 DEBUG trove.guestagent.datastore.service [-] Attempting to cleanup stalled services. _wait_for_database_service_status /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:324
6
2021-01-14 08:34:31.061 1240 DEBUG trove.guestagent.datastore.service [-] No cleanup action specified for this datastore. cleanup_stalled_db_services /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:380
7
★ 2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager [-] An error occurred preparing datastore: Database failed to stop.: RuntimeError: Database failed to stop.

1
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager Traceback (most recent call last):
2
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager   File "/home/XXXXXXXX/trove/trove/guestagent/datastore/manager.py", line 285, in _prepare
3
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager     cluster_config, snapshot)
4
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager   File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 158, in wrapper
5
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager     result = f(*args, **kwargs)
6
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager   File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/manager.py", line 219, in do_prepare
7
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager     self.app.stop_db()
8
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager   File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/service.py", line 396, in stop_db
9
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager     disable_on_boot=do_not_start_on_reboot, update_db=update_db)
10
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager   File "/home/XXXXXXXX/trove/trove/guestagent/datastore/service.py", line 297, in stop_db_service
11
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager     raise RuntimeError(_("Database failed to stop."))
12
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager RuntimeError: Database failed to stop.
13
2021-01-14 08:34:31.061 1240 ERROR trove.guestagent.datastore.manager
14
2021-01-14 08:34:31.073 1240 INFO trove.guestagent.datastore.manager [-] Ending datastore prepare for 'postgresql'.
15
2021-01-14 08:34:31.073 1240 INFO trove.guestagent.datastore.service [-] Set final status to failed to spawn.
16
2021-01-14 08:34:31.074 1240 DEBUG trove.guestagent.datastore.service [-] Casting set_status message to conductor (status is 'failed to spawn'). set_status /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:166
17
2021-01-14 08:34:31.074 1240 DEBUG trove.conductor.api [-] Making async call to cast heartbeat for instance: 1f3cc110-dd88-45ca-b9bd-a9c20ff24224 heartbeat /home/XXXXXXXX/trove/trove/conductor/api.py:73
18
2021-01-14 08:34:31.082 1240 DEBUG trove.guestagent.datastore.service [-] Successfully cast set_status. set_status /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:173
19
2021-01-14 08:34:31.083 1240 DEBUG trove.conductor.api [-] Making async call to cast error notification notify_exc_info /home/XXXXXXXX/trove/trove/conductor/api.py:116
20
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server [-] Exception during message handling: RuntimeError: Database failed to stop.
21
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
22
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 163, in _process_incoming
23
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server     res = self.dispatcher.dispatch(message)
24
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 220, in dispatch
25
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server     return self._do_dispatch(endpoint, method, ctxt, args)
26
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 190, in _do_dispatch
27
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server     result = func(ctxt, **new_args)
28
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 158, in wrapper
29
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server     result = f(*args, **kwargs)
30
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server   File "/home/XXXXXXXX/trove/trove/guestagent/datastore/manager.py", line 270, in prepare
31
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server     cluster_config, snapshot, modules)
32
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server   File "/home/XXXXXXXX/trove/trove/guestagent/datastore/manager.py", line 285, in _prepare
33
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server     cluster_config, snapshot)
34
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server   File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 158, in wrapper
35
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server     result = f(*args, **kwargs)
36
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server   File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/manager.py", line 219, in do_prepare
37
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server     self.app.stop_db()
38
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server   File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/service.py", line 396, in stop_db
39
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server     disable_on_boot=do_not_start_on_reboot, update_db=update_db)
40
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server   File "/home/XXXXXXXX/trove/trove/guestagent/datastore/service.py", line 297, in stop_db_service
41
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server     raise RuntimeError(_("Database failed to stop."))
42
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server RuntimeError: Database failed to stop.
43
2021-01-14 08:34:31.093 1240 ERROR oslo_messaging.rpc.server

前半で実施した PostgreSQL サーバー停止に関する修正が効かなかったのかどうかを調べていきます。

postgresql / postgresql@9.6-main サービス状態確認

systemctl コマンドで、PostgreSQL サービスの状態を確認します。

1
root@post2:~# systemctl status postgresql.service
2
● postgresql.service - PostgreSQL RDBMS
3
   Loaded: loaded (/lib/systemd/system/postgresql.service; enabled; vendor preset: enabled)
4
   Active: inactive (dead) since Thu 2021-01-14 08:24:30 UTC; 3 days ago
5
  Process: 1251 ExecStart=/bin/true (code=exited, status=0/SUCCESS)
6
 Main PID: 1251 (code=exited, status=0/SUCCESS)
7

8
Jan 14 08:24:19 post2 systemd[1]: Starting PostgreSQL RDBMS...
9
Jan 14 08:24:19 post2 systemd[1]: Started PostgreSQL RDBMS.
10
Jan 14 08:24:30 post2 systemd[1]: Stopped PostgreSQL RDBMS.

1
root@post2:~# systemctl status postgresql@9.6-main.service
2
● postgresql@9.6-main.service - PostgreSQL Cluster 9.6-main
3
   Loaded: loaded (/lib/systemd/system/postgresql@.service; disabled; vendor preset: enabled)
4
   Active: active (running) since Thu 2021-01-14 08:24:19 UTC; 3 days ago
5
  Process: 1059 ExecStart=/usr/bin/pg_ctlcluster --skip-systemctl-redirect %i start (code=exited, status=0/SUCCESS)
6
 Main PID: 1211 (postgres)
7
   CGroup: /system.slice/system-postgresql.slice/postgresql@9.6-main.service
8
           tq1211 /usr/lib/postgresql/9.6/bin/postgres -D /var/lib/postgresql/9.6/main -c config_file=/etc/postgresql/9.6/main/postgresql.conf
9
           tq1215 postgres: 9.6/main: checkpointer process
10
           tq1216 postgres: 9.6/main: writer process
11
           tq1217 postgres: 9.6/main: wal writer process
12
           tq1218 postgres: 9.6/main: autovacuum launcher process
13
           mq1219 postgres: 9.6/main: stats collector process
14

15
Jan 14 08:24:15 post2 systemd[1]: Starting PostgreSQL Cluster 9.6-main...
16
Jan 14 08:24:19 post2 systemd[1]: Started PostgreSQL Cluster 9.6-main.

postgresql.service は停止、postgresql@9.6-main.service は動作中の状態です。

PostgreSQL 応答確認

ログに出力されていたコマンドで PostgreSQL サーバーの生存を確認してみます。

1
root@post2:~# /usr/lib/postgresql/9.6/bin/pg_isready -h localhost
2
localhost:5432 - accepting connections
3
root@post2:~# echo $?
4
0

PostgreSQL サーバーは動作中に見えます。

PostgreSQL プロセス確認

PostgreSQL のプロセスを確認します。

1
root@post2:~# ps -elfww
2
F S UID        PID  PPID  C PRI  NI ADDR SZ WCHAN  STIME TTY          TIME CMD
3
4 S root         1     0  0  80   0 -  9382 ep_pol Jan14 ?        00:00:04 /sbin/init
4
1 S root         2     0  0  80   0 -     0 kthrea Jan14 ?        00:00:00 [kthreadd]
5
...
6
5 S ntp       1163     1  0  80   0 - 27508 poll_s Jan14 ?        00:00:37 /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 109:116
7
0 S postgres  1211     1  0  80   0 - 76736 poll_s Jan14 ?        00:00:04 /usr/lib/postgresql/9.6/bin/postgres -D /var/lib/postgresql/9.6/main -c config_file=/etc/postgresql/9.6/main/postgresql.conf
8
1 S postgres  1215  1211  0  80   0 - 76736 ep_pol Jan14 ?        00:00:00 postgres: 9.6/main: checkpointer process
9
1 S postgres  1216  1211  0  80   0 - 76736 ep_pol Jan14 ?        00:00:08 postgres: 9.6/main: writer process
10
1 S postgres  1217  1211  0  80   0 - 76736 ep_pol Jan14 ?        00:00:08 postgres: 9.6/main: wal writer process
11
1 S postgres  1218  1211  0  80   0 - 76837 ep_pol Jan14 ?        00:00:03 postgres: 9.6/main: autovacuum launcher process
12
1 S postgres  1219  1211  0  80   0 - 40484 ep_pol Jan14 ?        00:00:02 postgres: 9.6/main: stats collector process
13
4 S XXXXXXXX  1240     1  0  80   0 - 49288 ep_pol Jan14 ?        00:01:52 /usr/bin/python /home/XXXXXXXX/trove/contrib/trove-guestagent --config-dir=/etc/trove/conf.d
14
4 S XXXXXXXX  1471  1148  0  80   0 -  5327 wait   Jan14 tty1     00:00:00 -bash
15
4 S root      1493  1471  0  80   0 - 12070 poll_s Jan14 tty1     00:00:00 sudo su -
16
4 S root      1494  1493  0  80   0 - 12482 wait   Jan14 tty1     00:00:00 su -
17
4 S root      1495  1494  0  80   0 -  5327 wait_w Jan14 tty1     00:00:00 -su
18
1 S root      7115     2  0  80   0 -     0 worker Jan17 ?        00:00:56 [kworker/0:1]
19
1 S root      9000     2  0  80   0 -     0 worker 04:22 ?        00:00:00 [kworker/0:2]
20
1 S root      9123     2  0  80   0 -     0 worker 06:05 ?        00:00:00 [kworker/u2:0]
21
4 S XXXXXXXX  9153  1147  0  80   0 -  5315 wait   06:08 ttyS0    00:00:00 -bash
22
4 S root      9169  9153  0  80   0 - 12070 poll_s 06:10 ttyS0    00:00:00 sudo -s
23
4 S root      9170  9169  0  80   0 -  5293 wait   06:10 ttyS0    00:00:00 /bin/bash
24
1 S root      9186     2  0  80   0 -     0 worker 06:11 ?        00:00:00 [kworker/u2:1]
25
4 R root      9207  9170  0  80   0 -  9340 -      06:16 ttyS0    00:00:00 ps -elfww

PID 1211 の postgres プロセスが実行中です。

syslog 確認

念のため確認すると、/var/log/syslog には、前半で修正前に出ていたエラーメッセージ postgresql@9.6-main.service: Can't open PID file /run/postgresql/9.6-main.pid (yet?) after start: No such file or directory は出ていません。

1
root@post2:~# ls -l /run/postgresql
2
total 4
3
drwxr-s--- 2 postgres postgres 100 Jan 18 06:32 9.6-main.pg_stat_tmp
4
-rw-r--r-- 1 postgres postgres   5 Jan 14 08:24 postgresql.pid
5
root@post2:~# cat /run/postgresql/postgresql.pid
6
1211

PID file は /run/postgresql/postgresql.pid で、中身のプロセス ID も合っています。

systemd の PostgreSQL 用設定確認

前半で確認したように、PostgreSQL のサービスは postgresql.service と postgresql@9.6-main.service に分かれています。

/lib/systemd/system/postgresql.service

1
# systemd service for managing all PostgreSQL clusters on the system. This
2
# service is actually a systemd target, but we are using a service since
3
# targets cannot be reloaded.
4

5
[Unit]
6
Description=PostgreSQL RDBMS
7

8
[Service]
9
Type=oneshot
10
ExecStart=/bin/true
11
ExecReload=/bin/true
12
RemainAfterExit=on
13

14
[Install]
15
WantedBy=multi-user.target

/lib/systemd/system/postgresql@.service

1
# systemd service template for PostgreSQL clusters. The actual instances will
2
# be called "postgresql@version-cluster", e.g. "postgresql@9.3-main". The
3
# variable %i expands to "version-cluster", %I expands to "version/cluster".
4
# (%I breaks for cluster names containing dashes.)
5

6
[Unit]
7
Description=PostgreSQL Cluster %i
8
AssertPathExists=/etc/postgresql/%I/postgresql.conf
9
RequiresMountsFor=/etc/postgresql/%I /var/lib/postgresql/%I
10
PartOf=postgresql.service
11
ReloadPropagatedFrom=postgresql.service
12
Before=postgresql.service
13
# stop server before networking goes down on shutdown
14
After=network.target
15

16
[Service]
17
...
18
PIDFile=/var/run/postgresql/postgresql.pid
19
...

/lib/systemd/system/postgresql@.service ファイルの PIDFile 設定行は、前半での対処により、PIDFile=/var/run/postgresql/postgresql.pid に正しく修正されています。

Trove guest agent 処理の調査

前半で PostgreSQL サービス停止時の不具合に関する最初の問題対処をしたものの、/var/log/syslog ファイルのエラーが消えた以外に大きな変化は見られず、ログからはこれ以上確認できない方法で制御にまだ失敗しているようなので、PostgreSQL サービス停止部分の処理について詳しく調べてみます。

走行コードの抽出・トレース

trove-guestagent のログで、

1
2021-01-14 08:24:29.482 1240 DEBUG trove.guestagent.datastore.experimental.postgresql.manager [-] Stopping database prior to initial configuration. do_prepare /home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/manager.py:218
2
2021-01-14 08:24:29.483 1240 INFO trove.guestagent.datastore.service [-] Stopping database service.
3
2021-01-14 08:24:29.483 1240 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): sudo service postgresql stop execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
4
2021-01-14 08:24:30.151 1240 DEBUG oslo_concurrency.processutils [-] CMD "sudo service postgresql stop" returned: 0 in 0.668s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
5
2021-01-14 08:24:30.152 1240 DEBUG trove.guestagent.datastore.service [-] Waiting for database to shutdown. stop_db_service /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:294
6
...
7
2021-01-14 08:34:31.060 1240 ERROR trove.guestagent.datastore.service [-] Timeout while waiting for database status to change.Expected state shutdown, current state is running
8
2021-01-14 08:34:31.060 1240 INFO trove.guestagent.datastore.service [-] Service status did not change to shutdown within the given timeout: 600s

の部分が実際にうまく停止制御できていなかった部分のログにあたりますが、タイムアウト以外のエラーは特に出ていませんでした。

また、前半で修正した systemd 管理用の /lib/systemd/system/postgresql@.service ファイルについては、修正の結果エラーが出なくなったことを確認できましたが、上記ログでは sudo service postgresql stop コマンドで停止を実施したような出力になっており、systemd ではない別のサービス管理手段で行っているように見えるため少し違和感を感じます。二者に何か関連があるのでしょうか？

ここからは、Trove インスタンス中の ~/trove/、またはコントローラー上の Trove guest agent ファイル格納場所にあるソースを参照し調べていきます。

Trove のログには、基本的にはログ出力したコードのソースの場所と行番号が付加されているので、ソースを参照しメッセージ出力行を確認しつつ、追っていけばよいでしょう。ログのメッセージから離れてトレースしていくときは、共通処理部分のコードまたは PostgreSQL 専用の処理コードという条件で絞って探していきます。

例えば、

1
2021-01-14 08:24:29.482 1240 DEBUG trove.guestagent.datastore.experimental.postgresql.manager [-] Stopping database prior to initial configuration. do_prepare /home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/manager.py:218

については、以下のコードが見つかります。

trove/guestagent/datastore/experimental/postgresql/manager.py

1
class Manager(manager.Manager):
2
...
3
    def do_prepare(self, context, packages, databases, memory_mb, users,
4
                   device_path, mount_point, backup_info, config_contents,
5
                   root_password, overrides, cluster_config, snapshot):
6
        self.app.install(context, packages)
7
        LOG.debug("Waiting for database first boot.")
8
        if (self.app.status.wait_for_real_status_to_change_to(
9
                trove_instance.ServiceStatuses.RUNNING,
10
                CONF.state_change_wait_time,
11
                False)):
12
            LOG.debug("Stopping database prior to initial configuration.")      ★★★←※
13
            self.app.stop_db()
14
        ....
15
...

《ソース詳細を開く／閉じる》

上記最後の処理にある self.app は、以下コードにより初期化され、PgSqlApp のインスタンスとなっています。

1
...
2
from trove.guestagent.datastore.experimental.postgresql.service import PgSqlApp
3
...
4

5
class Manager(manager.Manager):
6
...
7
    @property
8
    def app(self):
9
        if self._app is None:
10
            self._app = self.build_app()
11
        return self._app
12

13
    def build_app(self):
14
        return PgSqlApp()

trove.guestagent.datastore.experimental.postgresql.service の PgSqlApp クラスは以下に見つかります。

trove/guestagent/datastore/experimental/postgresql/service.py

1
...
2
from trove.guestagent.datastore import service
3
...
4

5
class PgSqlApp(object):
6
...
7
    def __init__(self):
8
        super(PgSqlApp, self).__init__()
9

10
        self._current_admin_user = None
11
        self.status = PgSqlAppStatus(self.pgsql_extra_bin_dir)
12
        ...
13
...
14
    @property
15
    def service_candidates(self):
16
        return ['postgresql']
17
...
18
    def stop_db(self, do_not_start_on_reboot=False, update_db=False):
19
        self.status.stop_db_service(
20
            self.service_candidates, CONF.state_change_wait_time,
21
            disable_on_boot=do_not_start_on_reboot, update_db=update_db)
22
...
23

24
class PgSqlAppStatus(service.BaseDbStatus):
25
...

stop_db から PgSqlAppStatus の stop_db_service を呼んでいますが、PgSqlAppStatus クラスのコードに stop_db_service メソッドは無く、ベースクラスの BaseDbStatus に見つかります。

trove/guestagent/datastore/service.py

1
...
2
from trove.guestagent.common import operating_system
3
...
4

5
class BaseDbStatus(object):
6
...
7
    def stop_db_service(self, service_candidates, timeout,
8
                        disable_on_boot=False, update_db=False):
9
...
10
        LOG.info("Stopping database service.")                    ★★★←※
11
        operating_system.stop_service(service_candidates, timeout=timeout)
12

13
        LOG.debug("Waiting for database to shutdown.")                ★★★←※
14
        if not self._wait_for_database_service_status(
15
                instance.ServiceStatuses.SHUTDOWN, timeout, update_db):
16
            raise RuntimeError(_("Database failed to stop."))            ■■■←※
17
        ...
18
...

ここでも、ログに記録されているメッセージ出力が見つかります。

ここで先に、サービス停止の完了判定方法を見ておくと、以下のように、サービスが目的の状態に変化するか、タイムアウトするまで監視する処理が入っています。

trove/guestagent/datastore/service.py

1
class BaseDbStatus(object):
2
...
3
    def _wait_for_database_service_status(self, status, timeout, update_db):
4
    ...
5
        if not self.wait_for_real_status_to_change_to(
6
                status, timeout, update_db):
7
            LOG.info("Service status did not change to %(status)s "
8
                     "within the given timeout: %(timeout)ds",
9
                     {'status': status, 'timeout': timeout})
10
            LOG.debug("Attempting to cleanup stalled services.")
11
            try:
12
                self.cleanup_stalled_db_services()
13
            except Exception:
14
                LOG.debug("Cleanup failed.", exc_info=True)
15
            return False
16

17
        return True
18
...
19

20
    def wait_for_real_status_to_change_to(self, status, max_time,
21
                                          update_db=False):
22
...
23
        loop = True
24

25
        while loop:
26
            self.status = self._get_actual_db_status()
27
            if self.status == status:
28
                if update_db:
29
                    self.set_status(self.status)
30
                return True
31

32
            # should we remain in this loop? this is the thing
33
            # that emulates the do-while construct.
34
            loop = (time.time() < end_time)
35
            ...
36

37
        LOG.error("Timeout while waiting for database status to change."
38
                  "Expected state %(status)s, "
39
                  "current state is %(actual_status)s",
40
                  {"status": status, "actual_status": self.status})          ★★★←※
41
        return False
42
...

PostgreSQL の状態は、以下のように pg_isready コマンドの実行結果で判定しています。

trove/guestagent/datastore/experimental/postgresql/service.py

1
...
2
from trove.common import utils
3
...
4
from trove.guestagent.common import guestagent_utils
5
...
6

7
class PgSqlAppStatus(service.BaseDbStatus):
8

9
    HOST = 'localhost'
10

11
    def __init__(self, tools_dir):
12
        super(PgSqlAppStatus, self).__init__()
13
        self._cmd = guestagent_utils.build_file_path(tools_dir, 'pg_isready')
14

15
    def _get_actual_db_status(self):
16
        try:
17
            utils.execute_with_timeout(
18
                self._cmd, '-h', self.HOST, log_output_on_error=True)
19
            return instance.ServiceStatuses.RUNNING
20
        except exception.ProcessExecutionError:
21
            return instance.ServiceStatuses.SHUTDOWN
22
        except utils.Timeout:
23
            return instance.ServiceStatuses.BLOCKED
24
        except Exception:
25
            LOG.exception("Error getting Postgres status.")
26
            return instance.ServiceStatuses.CRASHED
27

28
        return instance.ServiceStatuses.SHUTDOWN
29
...

pg_isready を使って状態を判定しましたが、動作中（RUNNING）で返っていたため、タイムアウトするまで停止を待ちました。生存中の postgres プロセスが、ps コマンドでも見えていました。

次に、問題のサービス停止処理を確認します。

《ソース詳細を開く／閉じる》

trove/guestagent/common/operating_system.py

1
...
2
def stop_service(service_candidates, **kwargs):
3
    _execute_service_command(service_candidates, 'cmd_stop', **kwargs)
4
...
5

6
def _execute_service_command(service_candidates, command_key, **kwargs):
7
...
8
    exec_args = {}
9
    if 'timeout' in kwargs:
10
        exec_args['timeout'] = kwargs.pop('timeout')
11

12
    if kwargs:
13
        raise UnknownArgumentError(_("Got unknown keyword args: %r") % kwargs)
14

15
    if service_candidates:
16
        service = service_discovery(service_candidates)
17
        if command_key in service:
18
            utils.execute_with_timeout(service[command_key], shell=True,
19
                                       **exec_args)
20
        else:
21
            raise RuntimeError(_("Service control command not available: %s")
22
                               % command_key)
23
    else:
24
        raise exception.UnprocessableEntity(_("Candidate service names not "
25
                                              "specified."))
26
...
27

28
def service_discovery(service_candidates):
29
...
30
    result = {}
31
    for service in service_candidates:
32
        result['service'] = service
33
        # check upstart
34
        if os.path.isfile("/etc/init/%s.conf" % service):
35
            result['type'] = 'upstart'
36
            ...
37
            break
38
        # check sysvinit
39
        if os.path.isfile("/etc/init.d/%s" % service):
40
            result['type'] = 'sysvinit'
41
            ...
42
            break
43
        # check systemd
44
        service_path = "/lib/systemd/system/%s.service" % service
45
        if os.path.isfile(service_path):
46
            result['type'] = 'systemd'
47
            ...
48
            break
49

50
    return result
51
...

service = service_discovery(service_candidates) の結果で見つかったサービス管理方法を使い、service_candidates （ここでは 'postgresql'）のサービスを操作（停止）しています。

service_discovery の処理を見ると、システムに特徴的なファイルが存在しているかどうかにより、どのサービス管理用コマンドを利用できるのかを決定していることがわかります。実際にファイルを確認してみると、以下のように sysvinit と systemd の判定で確認しているファイルがそれぞれ見つかりますが、ソースでの処理順上先にチェックしている sysvinit の方が採用されていると思います。

1
# ls -l /etc/init/postgresql.conf
2
ls: cannot access '/etc/init/postgresql.conf': No such file or directory
3

4
# ls -l /etc/init.d/postgresql
5
-rwxr-xr-x. 1 root root 1490 Feb 21  2016 /etc/init.d/postgresql
6

7
# ls -l /lib/systemd/system/postgresql.service
8
-rw-r--r--. 1 root root 337 Nov 12 11:42 /lib/systemd/system/postgresql.service

sysvinit が選ばれた場合、sudo systemctl stop postgresql コマンドではなく、以下コードにしたがい、ログにあったように sudo service postgresql stop コマンドでサービス停止が行われることとなっています。

trove/guestagent/common/operating_system.py

1
...
2
def service_discovery(service_candidates):
3
...
4
    result = {}
5
    for service in service_candidates:
6
        result['service'] = service
7
...
8
        # check sysvinit
9
        if os.path.isfile("/etc/init.d/%s" % service):
10
            result['type'] = 'sysvinit'
11
            result['cmd_start'] = "sudo service %s start" % service
12
            result['cmd_stop'] = "sudo service %s stop" % service
13
            if os.path.isfile("/usr/sbin/update-rc.d"):
14
                result['cmd_enable'] = "sudo update-rc.d %s defaults; sudo " \
15
                                       "update-rc.d %s enable" % (service,
16
                                                                  service)
17
                result['cmd_disable'] = "sudo update-rc.d %s defaults; sudo " \
18
                                        "update-rc.d %s disable" % (service,
19
                                                                    service)
20
            elif os.path.isfile("/sbin/chkconfig"):
21
                result['cmd_enable'] = "sudo chkconfig %s on" % service
22
                result['cmd_disable'] = "sudo chkconfig %s off" % service
23
            break
24
...
25
        # check systemd
26
        service_path = "/lib/systemd/system/%s.service" % service
27
        if os.path.isfile(service_path):
28
            result['type'] = 'systemd'
29
            result['cmd_start'] = "sudo systemctl start %s" % service
30
            result['cmd_stop'] = "sudo systemctl stop %s" % service
31
            ...
32
...
33
    return result
34
...

service コマンドの調査

使用されているのが systemctl でなく service コマンドでよいのか、という疑問を持ちつつ、service コマンドの詳細を確認していきます。

1
# which service
2
/usr/sbin/service

service コマンドは上記にあるシェルスクリプトとなっています。

《ソース詳細を開く／閉じる》

/usr/sbin/service

1
#!/bin/sh
2
...
3
if [ -d /run/systemd/system ]; then
4
   is_systemd=1
5
fi
6
...

と、いきなり冒頭で systemd のチェックをしており、systemd を考慮に入れた処理になっているようです。

以降のコードは、

1
cd /
2
while [ $# -gt 0 ]; do
3
...
4
    *)
5
       if ...
6
...
7
       elif [ -z "${SERVICE}" ]; then
8
         SERVICE="${1}"
9
       elif [ -z "${ACTION}" ]; then
10
         ACTION="${1}"
11
       else
12
         OPTIONS="${OPTIONS} ${1}"
13
       fi
14
       shift
15
       ;;
16
   esac
17
done
18
...

と続き、さらに

1
...
2

3
# When this machine is running systemd, standard service calls are turned into
4
# systemctl calls.
5
if [ -n "$is_systemd" ]
6
then
7
   UNIT="${SERVICE%.sh}.service"
8
   # avoid deadlocks during bootup and shutdown from units/hooks
9
   # which call "invoke-rc.d service reload" and similar, since
10
   # the synchronous wait plus systemd's normal behaviour of
11
   # transactionally processing all dependencies first easily
12
   # causes dependency loops
13
   if ! systemctl --quiet is-active multi-user.target; then
14
       sctl_args="--job-mode=ignore-dependencies"
15
   fi
16

17
   case "${ACTION}" in
18
...
19
      start|stop)
20
         # Follow the principle of least surprise for SysV people:
21
         # When running "service foo stop" and foo happens to be a service that
22
         # has one or more .socket files, we also stop the .socket units.
23
         # Users who need more control will use systemctl directly.
24
         for unit in $(systemctl list-unit-files --full --type=socket 2>/dev/null | sed -ne 's/\.socket\s*[a-z]*\s*$/.socket/p'); do
25
             if [ "$(systemctl -p Triggers show $unit)" = "Triggers=${UNIT}" ]; then
26
                systemctl $sctl_args ${ACTION} $unit
27
             fi
28
         done
29
         exec systemctl $sctl_args ${ACTION} ${UNIT}
30
      ;;
31
...
32
   esac
33
fi
34
...

と、結局 systemctl コマンドによる停止方法を選択して実行するルートを通るようです。

ただし、上記コードで重要な注意点が 1 つありました。

1
   # avoid deadlocks during bootup and shutdown from units/hooks
2
   # which call "invoke-rc.d service reload" and similar, since
3
   # the synchronous wait plus systemd's normal behaviour of
4
   # transactionally processing all dependencies first easily
5
   # causes dependency loops
6
   if ! systemctl --quiet is-active multi-user.target; then
7
       sctl_args="--job-mode=ignore-dependencies"
8
   fi

コードをよく見ると、システムの立ち上げ／シャットダウン時のような、multi-user.target が ACTIVE でないタイミングでは、systemctl コマンドに --job-mode=ignore-dependencies パラメータが追加されて実行されるようになっていました。このパラメータの効果により、systemd による制御が行われる際に、ユニットの依存関係が無視されて実行されるということです。これが、PostgreSQL サービスの制御にとって致命的な問題を引き起こしていました。

《問題原因》

既に見たように、postgresql.service は postgresql@.service と依存関係があり、postgresql.service の中身はほとんど空で、postgresql@.service 側に実際のプロセス停止などの有効な処理が全て定義されていました。

systemctl の --job-mode=ignore-dependencies オプション付きで postgresql.service に対し stop を行うと、postgresql.service 自体に定義された処理は正常に完了するものの、ユニットの依存関係は無視されるため、postgresql@.service 側の処理が実行されず、その結果 PostgreSQL のプロセスを停止する実処理も起動されないため正しい停止状態にならないようです。

解析結果のまとめ

注目すべき原因と結果の対応がいくつかあるため、注意してまとめてみます。

まず Trove guest agent コードから PostgreSQL サービスを停止するために、システムに存在しうる特徴的なファイルの有無を判定して、使用可能なサービス管理手段を判断しますが、候補として upstart、sysvinit、systemd があるうちの sysvinit、systemd が該当しますが、判定処理の順番により、sysvinit が選択され、service コマンドによるサービス停止が決定されます。

service コマンドによる PostgreSQL の停止では、service コマンドに systemd 管理の存在を考慮するコードがあり、systemctl が利用できると判断されるため、最終的には service コマンドの中から systemctl コマンドを使って PostgreSQL を停止するルートの処理が走ります。ただしシステム立ち上げ時やシャットダウン時には --job-mode=ignore-dependencies オプションが自動的に systemctl に追加され、ユニットの依存関係を無視する動作モードで実行されます。

systemd の PostgreSQL 関係のサービス定義については、直接制御される postgresql.service と、その依存サービスの定義である postgresql@.service があり、postgresql.service の中身はほとんど空で、postgresql@.service の中にすべての実処理が定義されるというかたちになっています。ユニットの依存関係を無視して postgresql.service に対する停止を行うと、postgresql.service 自体は正常に完了するがほとんど何も処理が発生せず、本来 postgresql@.service 側で実行されるはずだった実際のプロセスの停止処理は動かないため、全体として正しい停止状態とはならず、PostgreSQL のプロセスは動作したままとなります。

問題の対処

対処案 1 - Trove guest agent コードを修正し systemd 管理を選択させる

trove/guestagent/common/operating_system.py の service_discovery コードを修正し、使用できるサービスの判定を現状の upstart、sysvinit、systemd の順にするのではなく、sysvinit より先に systemd を判定するコードにします。これにより、悪影響のあった --job-mode=ignore-dependencies オプションを使用せずに systemctl コマンドを実行できるようになります。

懸念事項として、service_discovery は Ubuntu や PostgreSQL 等での利用時以外にも、Trove のデータベースサーバー起動イメージ作成時に選択できる各種 OS やデータストアからも利用される共通コードとなっており、他に影響がある可能性が考えられます。そのためできれば変更したくないコードです。

対処案 2 - service コマンドコードを変更して --job-mode=ignore-dependencies を追加しない処理とする

/usr/sbin/service のコードを変更し、systemctl コマンドを起動時に --job-mode=ignore-dependencies を自動的に追加しないための変更を行う。

懸念事項として、service コマンドが PostgreSQL 以外のサービス管理時にも利用されることがあるかもしれず、その場合に影響がある可能性が考えられます。そのためできれば変更したくないコードです。

対処案 3 - service_discovery の判定結果が変わるような状態にイメージの環境を変更する

service_discovery では、/etc/init.d/postgresql ファイルが環境にあることにより sysvinit を使用可能と判定しているため、PostgreSQL サーバー起動イメージ内の /etc/init.d/postgresql を隠すことにより、sysvinit を使用可能と判定させず、代わりに systemd のみが使用可能と判定させるようにします。

この変更は PostgreSQL 用の起動イメージ内のみに影響が限定され、他のデータストア使用時の動作には影響しません。既に動作確認済のデータストア用イメージがある場合にも、修正の影響を与えないため安心して適用できます。

対処案の選択

他への影響が少ない対処方法として、対処案 3 の、PostgreSQL サーバー起動イメージ内で /etc/init.d/postgresql ファイルを隠す方法を選択しました。

Diskimage-builder による PostgreSQL サーバー起動イメージビルド時のログを参考に、 Trove 用の elements で PostgreSQL 環境の作成に大きく関わっていると思われる部分のみ取り出してみると、それらは以下の順番でコードが実行されていることが分かります。

extra-data.d フェーズ
（省略）
pre-install.d フェーズ

:
- pre-install.d/10-postgresql-repo (elements: ubuntu-postgresql)
  ※ PostgreSQL のリポジトリを登録
  :
install.d フェーズ

:
- install.d/30-postgresql (elements: ubuntu-postgresql)
  ※ PostgreSQL をインストール
- install.d/31-fix-init-script (elements: ubuntu-xenial-postgresql)
  ※ PostgreSQL 用の初期化ファイル（systemd ユニットファイル）を修正
  :
post-install.d フェーズ
（省略）

上記より、ubuntu-postgresql/install.d/30-postgresql で postgresql-9.6 のインストール後に ubuntu-xenial-postgresql/install.d/31-fix-init-script で関連ファイルの変更を行うタイミングがあることが分かるので、ここに対処となる処理を追加すればよいと思われます。

イメージビルド環境にて、対処を以下のように行います。

ubuntu-xenial-postgresql/install.d/31-fix-init-script

1
# 最後に追加する
2
rm -f /etc/init.d/postgresql

対処が完了したら、PostgreSQL サーバー起動イメージを再ビルドして Trove に登録・設定し、再度 PostgreSQL を使用した Trove インスタンスを起動してみます。

対処結果

対処の結果、PostgreSQL を使用した Trove インスタンスは無事、起動に成功しました。

おわりに

全 4 回にわたり、OpenStack Trove 導入のポイントについて見てきました。

今回は OpenStack Queens 版の環境を使用して説明を行いました。最新版の Trove では、細かい部分が変わっていたり、改善されている部分があるかもしれませんが、Trove による処理の流れや、イメージ作成時の elements の見方、問題の解析手段など、参考にできる部分があると思います。

Trove に興味を持たれた方、Trove 導入の必要がある方などに、この記事が少しでもお役に立てればと願います。

記事をシェアする