[！] この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。
OSS として仮想マシンや仮想ネットワークなどのクラウド環境を提供する OpenStack ですが、ここに Trove というサービスを加えることにより、データベースを簡単に構築、管理し、仮想マシンから利用できるようになります。
Trove が提供する各種データベースのサーバーは、該当の起動イメージをもとに作成される、仮想マシンインスタンス上で動作します。 この記事では、Trove の紹介から始め、OpenStack（Queens 版）環境に Trove を導入する際の要の作業となる、起動イメージの作成と、無事動作できるためのポイントまでを複数回にわたって説明します。
導入入門編では、Troveについて紹介し、導入作業の流れ、および登場する Trove のプロセスについて説明しました。
イメージ作成編では、データストアとして MySQL を選択し、Trove のデータベースサーバー起動イメージ作成について説明しました。
今回の問題解析編では、データベースサーバー起動イメージを作成・登録して Trove からデータベースサーバーを起動しようとしたときに、正常動作しなかった場合の解析・対処について 1 つの例を示して説明します。
なお今回の例では、データベースが利用できるまでに 2 箇所で問題が発生し対処しているので、それらを前半・後半に分けて、2 回の記事で説明していきます。
PostgreSQL データストア
前回のイメージ作成編では MySQL データストアを使用しましたが、今回の問題解析編では PostgreSQL データストアを使用します。これは単に、PostgreSQL の方が、説明に利用するためのちょうどよい問題が得られやすかったためです。
PostgreSQL 起動イメージ作成用パラメータ／コマンド
Trove で PostgreSQL データストアを使用するためには、導入入門編・イメージ作成編でやっていたように、専用の起動イメージの作成と登録が必要となります。
前回 MySQL を準備した時は、MySQL サーバー起動イメージ作成用のパラメータを設定してイメージを作成しましたが、PostgreSQL を準備するために、同様のことを PostgreSQL サーバー起動イメージ作成用のパラメータを使用して、事前に行う必要があります。
Trove の PostgreSQL サーバー起動イメージ作成用パラメータと実行コマンドの設定例を以下に示します。
export CONTROLLER_IP=XX.XX.XX.XX
export HOST_SCP_USERNAME=troveimage
export PATH_TROVE=/home/troveimage/queens/trove
export ESCAPED_PATH_TROVE=`echo $PATH_TROVE | sed 's|/|\\\/|g'`
export RELEASE=xenial
export DIB_RELEASE=ubuntu-16.04
export DIB_CLOUD_IMAGES=http://cloud-images.ubuntu.com/releases/xenial/release-20200129
export HOST_USERNAME=root
export TROVESTACK_SCRIPTS=/XXXXXXXXXXXX/integration/scripts
export SSH_DIR=$TROVESTACK_SCRIPTS/files/keys
export DIB_CLOUD_INIT_DATASOURCES="ConfigDrive"
export GUEST_USERNAME=XXXXXXXX
export ELEMENTS_PATH=$TROVESTACK_SCRIPTS/files/elements
export ELEMENTS_PATH+=:/XXXXXXXXXXXX/diskimage_builder/elements/
export DEST=/XXXXXXXXX/UC
export GUEST_LOGDIR=/var/log/trove
export ESCAPED_GUEST_LOGDIR=`echo $GUEST_LOGDIR | sed 's|/|\\\/|g'`
export DIB_CLOUD_INIT_ETC_HOSTS=true
disk-image-create -a amd64 -o ImageName ubuntu vm \
cloud-init-datasources ubuntu-xenial-guest ubuntu-xenial-postgresql解析の準備
解析・デバッグ時に有効な Trove の設定について説明します。
他の OpenStack のコンポーネントについてもそうですが、Trove には問題発生時の解析・デバッグに有効な設定オプションがあります。 オプションは Trove の設定ファイルで指定し、Trove のプロセスを再起動すれば有効になるため、事前に実行しておくとよいでしょう。
デバッグログ有効化
Trove は動作時のログを出力していますが、OpenStack の公式導入手順によるデフォルトインストール状態では、デバッグログまでは出力されていないかもしれません（実際は、一部プロセスでは出力されており、他のプロセスでは出力されていない）。もしデバッグログが有効になっていない場合、設定ファイルで有効化することで、より詳細な動作時のログが出力されるようになり、解析の助けとなります。
OpenStack ホスト上 の Trove プロセスでデバッグログ有効化
導入入門編の説明で見たように、OpenStack ホスト上の Trove プロセスには、trove-api、trove-taskmanager、trove-conductor がありますが、この 3 つとも以下の設定ファイルでの指定でデバッグログを有効化できます。
/etc/trove/trove.conf
[DEFAULT]
debug = True設定変更後は、各 Trove プロセスを再起動して反映させます。
# systemctl restart openstack-trove-api.service openstack-trove-taskmanager.service openstack-trove-conductor.servicetrove-guestagent プロセスでデバッグログ有効化
trove-guestagent のデバッグログは、Trove インスタンス起動前に、OpenStack ホスト上の以下設定ファイルで指定しておくことにより有効化できます。
/etc/trove/trove-guestagent.conf
[DEFAULT]
debug = TrueTrove プロセスのログ分離
OpenStack ホスト上の各 Trove プロセスが出力するログは、OpenStack 公式導入手順によるデフォルトインストール状態では、1 つのログファイル（/var/log/trove/trove.log）にまとめて出力されます。そのため、どのプロセスで出力されたログかを判別するのに手間取り、解析・デバッグに支障が出るという可能性があります。これを防止するため、以下のようにして各プロセスのログファイルを分ける設定にし、再起動しておくとよいでしょう。
trove-api プロセス用ログファイル設定
/etc/trove/trove.conf
[DEFAULT]
log_file = /var/log/trove/trove.logtrove-taskmanager プロセス用ログファイル設定
/etc/trove/trove-taskmanager.conf
[DEFAULT]
log_dir = /var/log/trove
log_file = trove-taskmanager.logtrove-conductor プロセス用ログファイル設定
/etc/trove/trove-conductor.conf
[DEFAULT]
log_dir = /var/log/trove
log_file = trove-conductor.logPostgreSQL サーバーが正常に起動しない問題の解析（前半）
発生事象
- PostgreSQL データストアを登録して、OpenStack の Dashboard から Trove インスタンス起動をしようとしたところ、正常起動状態に至らず失敗する。
- Dashboard 画面上では Trove インスタンスがしばらく「作成中」状態のままとなり、その後「失敗」状態となる。
- Dashboard のコンピュートインスタンスの画面に同名のインスタンスができるが、こちらは「実行中」状態となっている。
問題の解析
Trove プロセスのログ調査
まず OpenStack サーバーホスト上の Trove プロセスのログから確認していきます。 これらプロセスは trove-api、trove-taskmanager、trove-conductor になります。 外部からの Trove へのリクエストは trove-api が受け、trove-taskmanager が引き継いでメインの処理の流れを実行することが多いため、この順番で確認していきます。 trove-conductor は非同期で状態通知を受けるため、最後に確認します。
コントローラーノード：
/var/log/trove/trove.log
ログから、trove-api は、Create database instance 要求を受けて、trove-taskmanager に処理を渡していることがわかります。 また、要求の受付は 200 OK で返しています。
まず、以下ログのあたりから POST でリクエストを受け始めているように見えます。 Trove の API 一覧 ⧉と比較して、Create database instance という要求であるとわかります。
《ログを開く／閉じる》
2021-01-14 14:20:33.626 18255 DEBUG trove.common.auth [-] Authorized tenant '8fe1955b5a8841bb8dbf92a2503f42e3' request: POST /v1.0/8fe1955b5a8841bb8dbf92a2503f42e3/instances HTTP/1.0
...
{"instance": {"name": "post", "availability_zone": "nova", "nics": [{"net-id": "752e0534-80a7-40ca-a95b-80f23366de20", "v4-fixed-ip": ""}], "flavorRef": "6", "volume": {"size": 1}, "datastore": {"version": "postgresql-9.6-ng", "type": "postgresql"}}} authorize /usr/lib/python2.7/site-packages/trove/common/auth.py:68次に、trove-taskmanager の API を使って要求を渡しているようです。 create_instance という要求です。
《ログを開く／閉じる》
2021-01-14 14:20:33.641 18255 INFO trove.instance.service [-] Creating a database instance for tenant '8fe1955b5a8841bb8dbf92a2503f42e3'
2021-01-14 14:20:33.642 18255 DEBUG trove.instance.service [-] req : 'POST /v1.0/8fe1955b5a8841bb8dbf92a2503f42e3/instances HTTP/1.0
...
2021-01-14 14:20:33.642 18255 DEBUG trove.instance.service [-] body : '{u'instance': {u'name': u'post', 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-ng', u'type': u'postgresql'}}}'
create /usr/lib/python2.7/site-packages/trove/instance/service.py:269
...
2021-01-14 14:20:34.630 18255 DEBUG trove.common.notification [-] Sending event: dbaas.instance_create.start, {'client_ip': '192.168.151.32', 'name': u'post', 'server_type': 'api', 'tenant_id': u'8fe1955b5a8841bb8dbf92a2503f42e3', 'datastore_version': u'postgresql-9.6-ng', 'image_id': u'48c62c8d-fc29-429b-82b1-9eaf9aa8d2a4', '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-77df6c0d-25fe-4ffc-b649-fb97039b16fd', '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
...
2021-01-14 14:20:35.133 18255 DEBUG trove.instance.models [-] Generated unique RPC encryption key for instance. key = GW1LKbEBKLLpj477BBmIFya5273koZWp __init__ /usr/lib/python2.7/site-packages/trove/instance/models.py:1601
2021-01-14 14:20:35.134 18255 DEBUG trove.db.models [-] Saving DBInstance: {u'encrypted_key': '***', u'updated': datetime.datetime(2021, 1, 14, 5, 20, 35, 134026), '_sa_instance_state': <sqlalchemy.orm.state.InstanceState object at 0x7f716e91c250>, u'name': u'post', u'task_id': 5, u'created': datetime.datetime(2021, 1, 14, 5, 20, 34, 873437), 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'd19a1fad-431c-4581-8314-00fc4a9635c4', u'datastore_version_id': u'7bef1f0a-db90-4e84-9fab-eb6704638f1a', u'region_id': u'otm'} save /usr/lib/python2.7/site-packages/trove/db/models.py:65
2021-01-14 14:20:35.189 18255 DEBUG trove.instance.models [-] Tenant 8fe1955b5a8841bb8dbf92a2503f42e3 created new Trove instance d19a1fad-431c-4581-8314-00fc4a9635c4 in region otm. _create_resources /usr/lib/python2.7/site-packages/trove/instance/models.py:1042
★ 2021-01-14 14:20:35.323 18255 DEBUG trove.taskmanager.api [-] Making async call to create instance d19a1fad-431c-4581-8314-00fc4a9635c4 create_instance /usr/lib/python2.7/site-packages/trove/taskmanager/api.py:198
★ 2021-01-14 14:20:35.324 18255 DEBUG trove.taskmanager.api [-] Casting create_instance _cast /usr/lib/python2.7/site-packages/trove/taskmanager/api.py:76最終的にこの POST リクエストの受け付けは 200 OK となっています。
《ログを開く／閉じる》
2021-01-14 14:20:36.763 18255 DEBUG trove.instance.views [-] {'status': 'BUILD', 'name': u'post', 'links': [{'href': u'https://controller:8779/v1.0/8fe1955b5a8841bb8dbf92a2503f42e3/instances/d19a1fad-431c-4581-8314-00fc4a9635c4', 'rel': 'self'}, {'href': 'https://controller:8779/instances/d19a1fad-431c-4581-8314-00fc4a9635c4', 'rel': 'bookmark'}], 'region': 'otm', 'id': 'd19a1fad-431c-4581-8314-00fc4a9635c4', '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-ng', 'type': u'postgresql'}} data /usr/lib/python2.7/site-packages/trove/instance/views.py:59
...
2021-01-14 14:20:36.784 18255 INFO eventlet.wsgi [-] 192.168.151.32 - - [14/Jan/2021 14:20:36] "POST /v1.0/8fe1955b5a8841bb8dbf92a2503f42e3/instances HTTP/1.1" 200 856 3.160239次に、trove-taskmanager のログを確認していきます。
コントローラーノード：
/var/log/trove/trove-taskmanager.log
ログから、trove-taskmanager は、Trove インスタンス用の仮想マシンを作成し、trove-guestagent に prepare 要求を出していますが、 時間経過後にエラーとなっているようです。
まず、このあたりから Trove インスタンスの作成が開始されているように見えます。
《ログを開く／閉じる》
2021-01-14 14:21:08.545 16266 DEBUG trove.instance.models [-] Instance d19a1fad-431c-4581-8314-00fc4a9635c4 service status is new. load_instance /usr/lib/python2.7/site-packages/trove/instance/models.py:546
2021-01-14 14:21:09.386 16266 INFO trove.taskmanager.models [-] Creating instance d19a1fad-431c-4581-8314-00fc4a9635c4.Neutron（ネットワーク）やボリュームの処理を呼んでいます。
《ログを開く／閉じる》
2021-01-14 14:21:37.618 16266 DEBUG neutronclient.client [-] POST call to neutron for http://controller:9696/v2.0/security-groups used request id req-cc7f5268-b8f7-461b-ad64-204e19f83a62 _cs_request /usr/lib/python2.7/site-packages/neutronclient/client.py:127
...
2021-01-14 14:21:47.566 16266 DEBUG neutronclient.client [-] POST call to neutron for http://controller:9696/v2.0/security-group-rules used request id req-ee25491c-8991-4f0c-a0d4-1bbb54c9aa50 _cs_request /usr/lib/python2.7/site-packages/neutronclient/client.py:127
...
2021-01-14 14:21:47.617 16266 DEBUG trove.taskmanager.models [-] Successfully created security group for instance: d19a1fad-431c-4581-8314-00fc4a9635c4 create_instance /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:482
2021-01-14 14:21:47.883 16266 DEBUG trove.taskmanager.models [-] Begin _create_server_volume_individually for id: d19a1fad-431c-4581-8314-00fc4a9635c4 _create_server_volume_individually /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:794
2021-01-14 14:21:47.909 16266 DEBUG trove.taskmanager.models [-] trove volume support = True _build_volume_info /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:824
2021-01-14 14:21:47.909 16266 DEBUG trove.taskmanager.models [-] Begin _create_volume for id: d19a1fad-431c-4581-8314-00fc4a9635c4 _create_volume /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:865
...
2021-01-14 14:23:01.533 16266 DEBUG trove.taskmanager.models [-] End _create_volume for id: d19a1fad-431c-4581-8314-00fc4a9635c4 _create_volume /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:885
2021-01-14 14:23:01.567 16266 DEBUG trove.taskmanager.models [-] Created volume <Volume: f93463a6-d776-4704-a8a9-aa939b2c7b8f> _build_volume /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:889
2021-01-14 14:23:01.567 16266 DEBUG trove.taskmanager.models [-] block_device = {'vdb': u'f93463a6-d776-4704-a8a9-aa939b2c7b8f::1:1'}
volume = [{'id': u'f93463a6-d776-4704-a8a9-aa939b2c7b8f', 'size': 1}]
device_path = /dev/vdb
mount_point = /var/lib/postgresql _build_volume /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:909
2021-01-14 14:23:04.864 16266 DEBUG novaclient.v2.client [-] REQ: curl -g -i -X POST http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers -H "User-Agent: python-novaclient
...仮想マシンインスタンスを作成しています。
《ログを開く／閉じる》
2021-01-14 14:23:51.589 16266 DEBUG novaclient.v2.client [-] POST call to compute for http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers used request id req-ee12b8ff-850f-474f-8a3d-253982b1ba96 request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:722
2021-01-14 14:23:51.622 16266 DEBUG trove.taskmanager.models [-] Created new compute instance 2e0b3700-5f49-4a2c-b755-eb92692f5b17 for instance d19a1fad-431c-4581-8314-00fc4a9635c4 _create_server /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:942新たにできたインスタンス上にいる、trove-guestagent の API を呼んでいます。 prepare という要求です。
《ログを開く／閉じる》
2021-01-14 14:23:51.664 16266 DEBUG trove.taskmanager.models [-] End _create_server_volume_individually for id: d19a1fad-431c-4581-8314-00fc4a9635c4 _create_server_volume_individually /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:815
2021-01-14 14:23:53.741 16266 DEBUG trove.taskmanager.models [-] Entering guest_prepare _guest_prepare /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:950
★ 2021-01-14 14:23:54.412 16266 DEBUG trove.guestagent.api [-] Sending the call to prepare the Guest. prepare /usr/lib/python2.7/site-packages/trove/guestagent/api.py:321
★ 2021-01-14 14:23:58.303 16266 DEBUG trove.guestagent.api [-] Casting prepare _cast /usr/lib/python2.7/site-packages/trove/guestagent/api.py:104
2021-01-14 14:23:59.062 16266 INFO trove.instance.models [-] Resetting task status to NONE on instance d19a1fad-431c-4581-8314-00fc4a9635c4.このあたりから、処理の完了待ちになっているようです。
《ログを開く／閉じる》
2021-01-14 14:23:59.116 16266 DEBUG trove.taskmanager.models [-] trove dns support = False _create_dns_entry /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:964
2021-01-14 14:23:59.117 16266 DEBUG trove.taskmanager.models [-] <greenlet.greenlet object at 0x7f8c5831f050>: DNS not enabled for instance: d19a1fad-431c-4581-8314-00fc4a9635c4 _create_dns_entry /usr/lib/python2.7/site-packages/trove/taskmanager/models.py:1005
...
2021-01-14 14:23:59.517 16266 DEBUG novaclient.v2.client [-] RESP: [200] Content-Length: 1290 Content-Type: application/json X-Openstack-Request-Id: req-e48167f2-58e2-4f37-99ff-a830d4b0b5c0 X-Compute-Request-Id: req-e48167f2-58e2-4f37-99ff-a830d4b0b5c0 Date: Thu, 14 Jan 2021 05:23:59 GMT Connection: keep-alive
RESP BODY: {"server": {"OS-EXT-STS:task_state": "scheduling", "addresses": {}, "links": [{"href": "http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/2e0b3700-5f49-4a2c-b755-eb92692f5b17", "rel": "self"}, {"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/servers/2e0b3700-5f49-4a2c-b755-eb92692f5b17", "rel": "bookmark"}], "image": {"id": "48c62c8d-fc29-429b-82b1-9eaf9aa8d2a4", "links": [{"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/images/48c62c8d-fc29-429b-82b1-9eaf9aa8d2a4", "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": "2e0b3700-5f49-4a2c-b755-eb92692f5b17", "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-14T05:23:59Z", "hostId": "", "OS-SRV-USG:terminated_at": null, "key_name": null, "name": "post", "created": "2021-01-14T05:23:50Z", "tenant_id": "8fe1955b5a8841bb8dbf92a2503f42e3", "os-extended-volumes:volumes_attached": [], "metadata": {}}}
_http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:419
2021-01-14 14:23:59.518 16266 DEBUG novaclient.v2.client [-] GET call to compute for http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/2e0b3700-5f49-4a2c-b755-eb92692f5b17 used request id req-e48167f2-58e2-4f37-99ff-a830d4b0b5c0 request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:722
...
2021-01-14 14:24:51.282 16266 DEBUG novaclient.v2.client [-] RESP: [200] Content-Length: 1402 Content-Type: application/json X-Openstack-Request-Id: req-865e0c25-8cec-4226-988d-9cbdc8978411 X-Compute-Request-Id: req-865e0c25-8cec-4226-988d-9cbdc8978411 Date: Thu, 14 Jan 2021 05:24:51 GMT Connection: keep-alive
RESP BODY: {"server": {"OS-EXT-STS:task_state": "block_device_mapping", "addresses": {}, "links": [{"href": "http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/2e0b3700-5f49-4a2c-b755-eb92692f5b17", "rel": "self"}, {"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/servers/2e0b3700-5f49-4a2c-b755-eb92692f5b17", "rel": "bookmark"}], "image": {"id": "48c62c8d-fc29-429b-82b1-9eaf9aa8d2a4", "links": [{"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/images/48c62c8d-fc29-429b-82b1-9eaf9aa8d2a4", "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": "2e0b3700-5f49-4a2c-b755-eb92692f5b17", "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-14T05:24:38Z", "hostId": "1ff933a0770f3ab36aea075aa3be79a262fd0daf080b50359e679444", "OS-SRV-USG:terminated_at": null, "key_name": null, "name": "post", "created": "2021-01-14T05:23:50Z", "tenant_id": "8fe1955b5a8841bb8dbf92a2503f42e3", "os-extended-volumes:volumes_attached": [{"id": "f93463a6-d776-4704-a8a9-aa939b2c7b8f"}], "metadata": {}}}
_http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:419
2021-01-14 14:24:51.282 16266 DEBUG novaclient.v2.client [-] GET call to compute for http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/2e0b3700-5f49-4a2c-b755-eb92692f5b17 used request id req-865e0c25-8cec-4226-988d-9cbdc8978411 request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:722
...
2021-01-14 14:25:51.936 16266 DEBUG novaclient.v2.client [-] RESP: [200] Content-Length: 1470 Content-Type: application/json X-Openstack-Request-Id: req-bcc5245f-beac-4161-aa07-262530729618 X-Compute-Request-Id: req-bcc5245f-beac-4161-aa07-262530729618 Date: Thu, 14 Jan 2021 05:25:51 GMT Connection: keep-alive
RESP BODY: {"server": {"OS-EXT-STS:task_state": "spawning", "addresses": {}, "links": [{"href": "http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/2e0b3700-5f49-4a2c-b755-eb92692f5b17", "rel": "self"}, {"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/servers/2e0b3700-5f49-4a2c-b755-eb92692f5b17", "rel": "bookmark"}], "image": {"id": "48c62c8d-fc29-429b-82b1-9eaf9aa8d2a4", "links": [{"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/images/48c62c8d-fc29-429b-82b1-9eaf9aa8d2a4", "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": "2e0b3700-5f49-4a2c-b755-eb92692f5b17", "security_groups": [{"name": "SecGroup_d19a1fad-431c-4581-8314-00fc4a9635c4"}], "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-14T05:25:30Z", "hostId": "1ff933a0770f3ab36aea075aa3be79a262fd0daf080b50359e679444", "OS-SRV-USG:terminated_at": null, "key_name": null, "name": "post", "created": "2021-01-14T05:23:50Z", "tenant_id": "8fe1955b5a8841bb8dbf92a2503f42e3", "os-extended-volumes:volumes_attached": [{"id": "f93463a6-d776-4704-a8a9-aa939b2c7b8f"}], "metadata": {}}}
_http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:419
2021-01-14 14:25:51.937 16266 DEBUG novaclient.v2.client [-] GET call to compute for http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/2e0b3700-5f49-4a2c-b755-eb92692f5b17 used request id req-bcc5245f-beac-4161-aa07-262530729618 request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:722
...
2021-01-14 14:27:22.895 16266 DEBUG novaclient.v2.client [-] RESP: [200] Content-Length: 1618 Content-Type: application/json X-Openstack-Request-Id: req-e46a2a0c-9a20-48c1-8c48-8731441df3f1 X-Compute-Request-Id: req-e46a2a0c-9a20-48c1-8c48-8731441df3f1 Date: Thu, 14 Jan 2021 05:27:22 GMT Connection: keep-alive
RESP BODY: {"server": {"OS-EXT-STS:task_state": null, "addresses": {"trove-test-net": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:a7:b5:b3", "version": 4, "addr": "10.6.2.14", "OS-EXT-IPS:type": "fixed"}]}, "links": [{"href": "http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/2e0b3700-5f49-4a2c-b755-eb92692f5b17", "rel": "self"}, {"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/servers/2e0b3700-5f49-4a2c-b755-eb92692f5b17", "rel": "bookmark"}], "image": {"id": "48c62c8d-fc29-429b-82b1-9eaf9aa8d2a4", "links": [{"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/images/48c62c8d-fc29-429b-82b1-9eaf9aa8d2a4", "rel": "bookmark"}]}, "OS-EXT-STS:vm_state": "active", "OS-SRV-USG:launched_at": "2021-01-14T05:26:59.000000", "flavor": {"id": "6", "links": [{"href": "http://controller:8774/8fe1955b5a8841bb8dbf92a2503f42e3/flavors/6", "rel": "bookmark"}]}, "id": "2e0b3700-5f49-4a2c-b755-eb92692f5b17", "security_groups": [{"name": "SecGroup_d19a1fad-431c-4581-8314-00fc4a9635c4"}], "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-14T05:26:59Z", "hostId": "1ff933a0770f3ab36aea075aa3be79a262fd0daf080b50359e679444", "OS-SRV-USG:terminated_at": null, "key_name": null, "name": "post", "created": "2021-01-14T05:23:50Z", "tenant_id": "8fe1955b5a8841bb8dbf92a2503f42e3", "os-extended-volumes:volumes_attached": [{"id": "f93463a6-d776-4704-a8a9-aa939b2c7b8f"}], "metadata": {}}}
_http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:419
2021-01-14 14:27:22.895 16266 DEBUG novaclient.v2.client [-] GET call to compute for http://controller:8774/v2/8fe1955b5a8841bb8dbf92a2503f42e3/servers/2e0b3700-5f49-4a2c-b755-eb92692f5b17 used request id req-e46a2a0c-9a20-48c1-8c48-8731441df3f1 request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:722
...約 14 分後にエラーになっています。
failed to spawn と出ていますが、これだけでは解決できないので他のログも見る必要があります。
《ログを開く／閉じる》
2021-01-14 14:38:00.324 16266 ERROR oslo.service.loopingcall [-] Dynamic backoff interval looping call 'trove.common.utils.poll_and_check' failed: TroveError: Service not active, status: failed to spawn
2021-01-14 14:38:00.324 16266 ERROR oslo.service.loopingcall Traceback (most recent call last):
2021-01-14 14:38:00.324 16266 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 137, in _run_loop
2021-01-14 14:38:00.324 16266 ERROR oslo.service.loopingcall result = func(*self.args, **self.kw)
2021-01-14 14:38:00.324 16266 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/trove/common/utils.py", line 192, in poll_and_check
2021-01-14 14:38:00.324 16266 ERROR oslo.service.loopingcall obj = retriever()
2021-01-14 14:38:00.324 16266 ERROR oslo.service.loopingcall File "/usr/lib/python2.7/site-packages/trove/taskmanager/models.py", line 714, in _service_is_active
2021-01-14 14:38:00.324 16266 ERROR oslo.service.loopingcall raise TroveError(_("Service not active, status: %s") % status)
2021-01-14 14:38:00.324 16266 ERROR oslo.service.loopingcall TroveError: Service not active, status: failed to spawn
2021-01-14 14:38:00.324 16266 ERROR oslo.service.loopingcall
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models [-] Failed to send usage create-event for instance d19a1fad-431c-4581-8314-00fc4a9635c4.: TroveError: Service not active, status: failed to spawn
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models Traceback (most recent call last):
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models File "/usr/lib/python2.7/site-packages/trove/taskmanager/models.py", line 438, in wait_for_instance
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models time_out=timeout)
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models File "/usr/lib/python2.7/site-packages/trove/common/utils.py", line 214, in poll_until
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models sleep_time=sleep_time, time_out=time_out).wait()
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models File "/usr/lib/python2.7/site-packages/eventlet/event.py", line 121, in wait
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models return hubs.get_hub().switch()
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models File "/usr/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 294, in switch
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models return self.greenlet.switch()
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models File "/usr/lib/python2.7/site-packages/oslo_service/loopingcall.py", line 137, in _run_loop
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models result = func(*self.args, **self.kw)
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models File "/usr/lib/python2.7/site-packages/trove/common/utils.py", line 192, in poll_and_check
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models obj = retriever()
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models File "/usr/lib/python2.7/site-packages/trove/taskmanager/models.py", line 714, in _service_is_active
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models raise TroveError(_("Service not active, status: %s") % status)
★ 2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models TroveError: Service not active, status: failed to spawn
2021-01-14 14:38:00.477 16266 ERROR trove.taskmanager.models
2021-01-14 14:38:00.568 16266 DEBUG trove.db.models [-] Saving DBInstanceFault: {u'updated': datetime.datetime(2021, 1, 14, 5, 38, 0, 568131), '_sa_instance_state': <sqlalchemy.orm.state.InstanceState object at 0x7f8c57efcbd0>, u'created': datetime.datetime(2021, 1, 14, 5, 37, 37), u'deleted': 0, u'instance_id': u'd19a1fad-431c-4581-8314-00fc4a9635c4', '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'69f8be28-785f-4c75-a375-35984feb87b7'} save /usr/lib/python2.7/site-packages/trove/db/models.py:65次に trove-conductor のログを確認してみます。
コントローラーノード：
/var/log/trove/trove-conductor.log
ログから、trove-conductor は、最終的に failed to spawn 状態になったとの通知を受けていました。
はじめに、building 状態になったとの状態通知がありました。
《ログを開く／閉じる》
2021-01-14 14:27:46.183 17487 DEBUG trove.conductor.manager [-] Instance ID: d19a1fad-431c-4581-8314-00fc4a9635c4, 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. のメッセージも見えます。
《ログを開く／閉じる》
2021-01-14 14:37:36.848 17207 ERROR trove.conductor.manager [-] Guest exception on request req-77df6c0d-25fe-4ffc-b649-fb97039b16fd:
[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']
...
2021-01-14 14:37:36.777 17202 DEBUG trove.conductor.manager [-] Instance ID: d19a1fad-431c-4581-8314-00fc4a9635c4, Payload: {u'service_status': u'failed to spawn'} heartbeat /usr/lib/python2.7/site-packages/trove/conductor/manager.py:86
...
2021-01-14 14:37:36.984 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'd19a1fad-431c-4581-8314-00fc4a9635c4', 'server_ip': u'controller:8779', 'request_id': u'req-77df6c0d-25fe-4ffc-b649-fb97039b16fd', 'message': u'Database failed to stop.'} _notify /usr/lib/python2.7/site-packages/trove/common/notification.py:405
...
2021-01-14 14:37:37.551 17207 DEBUG trove.db.models [-] Saving DBInstanceFault: {u'updated': datetime.datetime(2021, 1, 14, 5, 37, 37, 526627), '_sa_instance_state': <sqlalchemy.orm.state.InstanceState object at 0x7f8570fa6e10>, u'created': datetime.datetime(2021, 1, 14, 5, 37, 37, 526444), u'deleted': False, u'instance_id': u'd19a1fad-431c-4581-8314-00fc4a9635c4', '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'69f8be28-785f-4c75-a375-35984feb87b7'} save /usr/lib/python2.7/site-packages/trove/db/models.py:65データベース操作の詳細は trove-guestagent が担当しているため、Trove インスタンスに入って確認していきます。
Trove インスタンスの調査
Trove インスタンスへのログイン
Trove インスタンスにも、基本的にはログインアカウントとパスワードを入力することによりログインができます。ですが、誰でもどこからでも簡単にログインできるようになっているわけではありません。
Trove インスタンスは、デフォルトでは SSH 通信が遮断されています。また、sshd でパスワード認証によるログインも許可されていない状態です。そのため、仮にログインアカウントとパスワードが分かっても、すぐに外部からネットワーク経由でログインできるわけではありません。
ではどうするかというと、OpenStack Dashboard で該当の仮想マシンインスタンスのコンソール画面からログインするか、または仮想マシンが実行されているホストの該当インスタンスに対し、仮想化管理ツールの virsh console コマンドで接続してログインすることができます。
OpenStack Dashboard のコンソールでは、入力文字のコピー・ペーストが使えなかったり、キーコードがずれて意図しない文字が入力されたりという不便／トラブルが起こりやすいため、virsh console の方が使いやすいかもしれません。
virsh list コマンドで見えるどのマシンがログインすべき該当インスタンスかは、OpenStack 管理ユーザーによる、openstack server show コマンドの出力内容と比較すればわかるようになっているようです（| OS-EXT-SRV-ATTR:instance_name | instance-00000508 | 等の表示内容があります）。
ログインアカウントは、ビルド設定で GUEST_USERNAME として定義しているものです。パスワードは、外部からログインアクセスしにくいとは言っても、直接ここに書くのは差し控えておきます。ただ、Trove の起動イメージビルド時の elements コード ubuntu-guest/install.d/50-user を見れば確認できます。
trove-guestagent のログ確認
Trove インスタンス：
/var/log/trove/logfile.txt
ログから、trove-guestagent は prepare 処理を開始し、設定変更のため一旦 PostgreSQL サーバーを停止して状態監視を行いますが、10 分後にタイムアウトして停止の失敗としてエラーになっています。
まず、このあたりから prepare の処理が始まっています。
《ログを開く／閉じる》
2021-01-14 05:27:31.137 1262 INFO trove.guestagent.datastore.manager [-] Starting datastore prepare for 'postgresql'.
2021-01-14 05:27:31.138 1262 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
2021-01-14 05:27:31.138 1262 DEBUG trove.conductor.api [-] Making async call to cast heartbeat for instance: d19a1fad-431c-4581-8314-00fc4a9635c4 heartbeat /home/XXXXXXXX/trove/trove/conductor/api.py:73
2021-01-14 05:27:31.344 1262 DEBUG trove.guestagent.datastore.service [-] Successfully cast set_status. set_status /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:173
2021-01-14 05:27:31.345 1262 DEBUG trove.guestagent.datastore.experimental.postgresql.service [-] d19a1fad-431c-4581-8314-00fc4a9635c4: Beginning PgSql package installation. install /home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/service.py:317ここで、設定変更のために一旦データベースサービスを停止しているようです。
《ログを開く／閉じる》
2021-01-14 05:27:31.444 1262 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
2021-01-14 05:27:31.444 1262 INFO trove.guestagent.datastore.service [-] Stopping database service.
2021-01-14 05:27:31.445 1262 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): sudo service postgresql stop execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:372
2021-01-14 05:27:31.936 1262 DEBUG oslo_concurrency.processutils [-] CMD "sudo service postgresql stop" returned: 0 in 0.491s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2021-01-14 05:27:31.937 1262 DEBUG trove.guestagent.datastore.service [-] Waiting for database to shutdown. stop_db_service /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:294pg_isready コマンドを使用して、PostgreSQL サーバーの状態を確認しているようです。shutdown 状態になるのを待っています。
《ログを開く／閉じる》
2021-01-14 05:27:31.937 1262 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
2021-01-14 05:27:31.963 1262 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
2021-01-14 05:27:31.963 1262 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
...
2021-01-14 05:28:32.570 1262 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
2021-01-14 05:28:32.606 1262 DEBUG oslo_concurrency.processutils [-] CMD "/usr/lib/postgresql/9.6/bin/pg_isready -h localhost" returned: 0 in 0.036s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
2021-01-14 05:28:32.607 1262 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
...約 10 分後にエラーになってしまいました。Database failed to stop. のメッセージです。
running 状態から shutdown 状態に変わるのを待っていたがタイムアウトしたと出ています。
《ログを開く／閉じる》
2021-01-14 05:37:32.611 1262 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
2021-01-14 05:37:32.638 1262 DEBUG oslo_concurrency.processutils [-] CMD "/usr/lib/postgresql/9.6/bin/pg_isready -h localhost" returned: 0 in 0.027s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409
★ 2021-01-14 05:37:32.638 1262 ERROR trove.guestagent.datastore.service [-] Timeout while waiting for database status to change.Expected state shutdown, current state is running
★ 2021-01-14 05:37:32.639 1262 INFO trove.guestagent.datastore.service [-] Service status did not change to shutdown within the given timeout: 600s
2021-01-14 05:37:32.639 1262 DEBUG trove.guestagent.datastore.service [-] Attempting to cleanup stalled services. _wait_for_database_service_status /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:324
2021-01-14 05:37:32.639 1262 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
★ 2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager [-] An error occurred preparing datastore: Database failed to stop.: RuntimeError: Database failed to stop.2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager Traceback (most recent call last):
2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager File "/home/XXXXXXXX/trove/trove/guestagent/datastore/manager.py", line 285, in _prepare
2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager cluster_config, snapshot)
2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 158, in wrapper
2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager result = f(*args, **kwargs)
2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/manager.py", line 219, in do_prepare
2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager self.app.stop_db()
2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/service.py", line 396, in stop_db
2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager disable_on_boot=do_not_start_on_reboot, update_db=update_db)
2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager File "/home/XXXXXXXX/trove/trove/guestagent/datastore/service.py", line 297, in stop_db_service
2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager raise RuntimeError(_("Database failed to stop."))
2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager RuntimeError: Database failed to stop.
2021-01-14 05:37:32.639 1262 ERROR trove.guestagent.datastore.manager
2021-01-14 05:37:32.644 1262 INFO trove.guestagent.datastore.manager [-] Ending datastore prepare for 'postgresql'.
2021-01-14 05:37:32.644 1262 INFO trove.guestagent.datastore.service [-] Set final status to failed to spawn.
2021-01-14 05:37:32.644 1262 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
2021-01-14 05:37:32.645 1262 DEBUG trove.conductor.api [-] Making async call to cast heartbeat for instance: d19a1fad-431c-4581-8314-00fc4a9635c4 heartbeat /home/XXXXXXXX/trove/trove/conductor/api.py:73
2021-01-14 05:37:32.652 1262 DEBUG trove.guestagent.datastore.service [-] Successfully cast set_status. set_status /home/XXXXXXXX/trove/trove/guestagent/datastore/service.py:173
2021-01-14 05:37:32.652 1262 DEBUG trove.conductor.api [-] Making async call to cast error notification notify_exc_info /home/XXXXXXXX/trove/trove/conductor/api.py:116
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server [-] Exception during message handling: RuntimeError: Database failed to stop.
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server Traceback (most recent call last):
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 163, in _process_incoming
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 220, in dispatch
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 190, in _do_dispatch
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args)
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 158, in wrapper
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server result = f(*args, **kwargs)
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server File "/home/XXXXXXXX/trove/trove/guestagent/datastore/manager.py", line 270, in prepare
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server cluster_config, snapshot, modules)
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server File "/home/XXXXXXXX/trove/trove/guestagent/datastore/manager.py", line 285, in _prepare
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server cluster_config, snapshot)
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 158, in wrapper
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server result = f(*args, **kwargs)
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/manager.py", line 219, in do_prepare
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server self.app.stop_db()
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server File "/home/XXXXXXXX/trove/trove/guestagent/datastore/experimental/postgresql/service.py", line 396, in stop_db
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server disable_on_boot=do_not_start_on_reboot, update_db=update_db)
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server File "/home/XXXXXXXX/trove/trove/guestagent/datastore/service.py", line 297, in stop_db_service
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server raise RuntimeError(_("Database failed to stop."))
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server RuntimeError: Database failed to stop.
2021-01-14 05:37:32.666 1262 ERROR oslo_messaging.rpc.server PostgreSQL サーバーが停止に失敗したことに対する調査が必要です。
PostgreSQL サービス状態確認
systemctl コマンドで、PostgreSQL サービスの状態を確認します。
root@post:~# systemctl status postgresql.service
● postgresql.service - PostgreSQL RDBMS
Loaded: loaded (/lib/systemd/system/postgresql.service; enabled; vendor preset: enabled)
Active: inactive (dead)
Jan 14 05:27:31 post systemd[1]: Stopped PostgreSQL RDBMS.サービスは停止していると出ています。
PostgreSQL 応答確認
以下のログに出力されていた生存確認用コマンドを使用し、PostgreSQL サーバーの生存を確認してみます。
/var/log/trove/logfile.txt
2021-01-14 05:37:29.610 1262 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
2021-01-14 05:37:32.611 1262 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
2021-01-14 05:37:32.638 1262 DEBUG oslo_concurrency.processutils [-] CMD "/usr/lib/postgresql/9.6/bin/pg_isready -h localhost" returned: 0 in 0.027s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:409pg_isready を実行します。
root@post:~# /usr/lib/postgresql/9.6/bin/pg_isready -h localhost
localhost:5432 - accepting connections
root@post:~# echo $?
0サービスは停止しているのに、PostgreSQL サーバーは動作中に見えます。
PostgreSQL プロセス確認
PostgreSQL のプロセスが残っているか、確認してみます。
root@post:~# ps -elfww
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
4 S root 1 0 0 80 0 - 9374 ep_pol Jan14 ? 00:02:06 /sbin/init
1 S root 2 0 0 80 0 - 0 kthrea Jan14 ? 00:00:00 [kthreadd]
...
4 S root 1136 1 0 80 0 - 16377 poll_s Jan14 ? 00:00:00 /usr/sbin/sshd -D
5 S ntp 1150 1 0 80 0 - 27508 poll_s Jan14 ? 00:00:52 /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 109:116
0 S postgres 1195 1 0 80 0 - 76736 poll_s Jan14 ? 00:00:06 /usr/lib/postgresql/9.6/bin/postgres -D /var/lib/postgresql/9.6/main -c config_file=/etc/postgresql/9.6/main/postgresql.conf
1 S postgres 1200 1195 0 80 0 - 76736 ep_pol Jan14 ? 00:00:00 postgres: 9.6/main: checkpointer process
1 S postgres 1201 1195 0 80 0 - 76736 ep_pol Jan14 ? 00:00:12 postgres: 9.6/main: writer process
1 S postgres 1202 1195 0 80 0 - 76736 ep_pol Jan14 ? 00:00:12 postgres: 9.6/main: wal writer process
1 S postgres 1203 1195 0 80 0 - 76837 ep_pol Jan14 ? 00:00:05 postgres: 9.6/main: autovacuum launcher process
1 S postgres 1204 1195 0 80 0 - 40484 ep_pol Jan14 ? 00:00:04 postgres: 9.6/main: stats collector process
4 S XXXXXXXX 1262 1 0 80 0 - 49287 ep_pol Jan14 ? 00:02:54 /usr/bin/python /home/XXXXXXXX/trove/contrib/trove-guestagent --config-dir=/etc/trove/conf.d
4 S XXXXXXXX 1689 1128 0 80 0 - 5327 wait_w Jan14 tty1 00:00:00 -bash
1 S root 9805 2 0 80 0 - 0 worker Jan18 ? 00:01:40 [kworker/0:1]
4 S root 9836 1 0 80 0 - 15869 wait Jan18 ttyS0 00:00:00 /bin/login --
4 S XXXXXXXX 13625 9836 0 80 0 - 5315 wait 04:51 ttyS0 00:00:00 -bash
4 S root 13640 13625 0 80 0 - 12070 poll_s 04:51 ttyS0 00:00:00 sudo -s
4 S root 13641 13640 0 80 0 - 5297 wait 04:51 ttyS0 00:00:00 /bin/bash
1 S root 13705 2 0 80 0 - 0 worker 05:38 ? 00:00:00 [kworker/u2:1]
1 S root 13711 2 0 80 0 - 0 worker 05:41 ? 00:00:00 [kworker/0:2]
1 S root 13726 2 0 80 0 - 0 worker 05:52 ? 00:00:00 [kworker/u2:0]
1 S root 13741 2 0 80 0 - 0 worker 05:58 ? 00:00:00 [kworker/u2:2]
4 R root 13745 13641 0 80 0 - 9340 - 05:59 ttyS0 00:00:00 ps -elfwwpostgres プロセスが残って見えます。サービスが停止状態であることと食い違っています。
syslog 確認
エラーが出ていないか確認してみます。
/var/log/syslog
Jan 14 05:27:18 post systemd[1]: postgresql@9.6-main.service: Can't open PID file /run/postgresql/9.6-main.pid (yet?) after start: No such file or directory起動後に PID file (/run/postgresql/9.6-main.pid) が存在しないというエラーが出ています。
root@post:~# ls -l /run/postgresql
total 4
drwxr-s--- 2 postgres postgres 100 Jan 20 06:04 9.6-main.pg_stat_tmp
-rw-r--r-- 1 postgres postgres 5 Jan 14 05:27 postgresql.pid
root@post:~# cat /run/postgresql/postgresql.pid
1195該当ファイルのディレクトリを確認すると、/run/postgresql/9.6-main.pid は無く、代わりに /run/postgresql/postgresql.pid というファイルがあります。ファイルの中身は、ps コマンドで確認できた現在生存中のプロセス ID (1195) が正しく入っています。
systemd の PostgreSQL サービス設定確認
/var/log/syslog ファイルでは、systemd[1]: および postgresql@9.6-main.service: のキーワードとともにエラーが出ていたため、PostgreSQL 関連のサービス設定について確認します。
postgresql.service と postgresql@9.6-main.service の関係
systemd が管理する postgresql.service サービスは、以下ユニットファイルの設定をもとに制御されていると思います。
/lib/systemd/system/postgresql.service
# systemd service for managing all PostgreSQL clusters on the system. This
# service is actually a systemd target, but we are using a service since
# targets cannot be reloaded.
[Unit]
Description=PostgreSQL RDBMS
[Service]
Type=oneshot
ExecStart=/bin/true
ExecReload=/bin/true
RemainAfterExit=on
[Install]
WantedBy=multi-user.targetしかしよく見ると、内容に意味のあるものはほとんど無く、何も制御されていないようにも見えます。
実は、調べてみると postgresql.service には、他に関連するサービスが定義されています。
root@post:~# systemctl list-units --all --type=service | grep -i postgres
postgresql.service loaded inactive dead PostgreSQL RDBMS
postgresql@9.6-main.service loaded activating start start PostgreSQL Cluster 9.6-mainroot@post:~# systemctl status postgresql@9.6-main.service
● postgresql@9.6-main.service - PostgreSQL Cluster 9.6-main
Loaded: loaded (/lib/systemd/system/postgresql@.service; disabled; vendor preset: enabled)
Active: activating (start) since Thu 2021-01-14 05:27:13 UTC; 6 days ago
Process: 1018 ExecStart=/usr/bin/pg_ctlcluster --skip-systemctl-redirect %i start (code=exited, status=0/SUCCESS)
CGroup: /system.slice/system-postgresql.slice/postgresql@9.6-main.service
tq1195 /usr/lib/postgresql/9.6/bin/postgres -D /var/lib/postgresql/9.6/main -c config_file=/etc/postgresql/9.6/main/postgresql.conf
tq1200 postgres: 9.6/main: checkpointer process
tq1201 postgres: 9.6/main: writer process
tq1202 postgres: 9.6/main: wal writer process
tq1203 postgres: 9.6/main: autovacuum launcher process
mq1204 postgres: 9.6/main: stats collector process
Jan 14 05:27:13 post systemd[1]: Starting PostgreSQL Cluster 9.6-main...
Jan 14 05:27:18 post systemd[1]: postgresql@9.6-main.service: Can't open PID file /run/postgresql/9.6-main.pid (yet?) after start: No such file or directoryこちらのサービスの状態は、activating になっています。
postgresql@9.6-main.service サービスは、/lib/systemd/system/postgresql@.service の設定をもとに制御されており、このファイルは、Generator ファイル /lib/systemd/system-generators/postgresql-generator によって自動的に /run/systemd/generator/postgresql.service.wants/postgresql@9.6-main.service の名前でシンボリックリンクされているものです（systemd の Generator 詳細については割愛）。このシンボリックリンクの配置と /lib/systemd/system/postgresql@.service ファイル内の設定により、postgresql@9.6-main.service サービスは postgresql.service の依存サービスとなっています。そして PostgreSQL サーバーの実際の制御処理を行っています。
/lib/systemd/system/postgresql@.service
# systemd service template for PostgreSQL clusters. The actual instances will
# be called "postgresql@version-cluster", e.g. "postgresql@9.3-main". The
# variable %i expands to "version-cluster", %I expands to "version/cluster".
# (%I breaks for cluster names containing dashes.)
[Unit]
Description=PostgreSQL Cluster %i
AssertPathExists=/etc/postgresql/%I/postgresql.conf
RequiresMountsFor=/etc/postgresql/%I /var/lib/postgresql/%I
PartOf=postgresql.service
ReloadPropagatedFrom=postgresql.service
Before=postgresql.service
# stop server before networking goes down on shutdown
After=network.target
[Service]
Type=forking
# -: ignore startup failure (recovery might take arbitrarily long)
# the actual pg_ctl timeout is configured in pg_ctl.conf
ExecStart=-/usr/bin/pg_ctlcluster --skip-systemctl-redirect %i start
# 0 is the same as infinity, but "infinity" needs systemd 229
TimeoutStartSec=0
ExecStop=/usr/bin/pg_ctlcluster --skip-systemctl-redirect -m fast %i stop
TimeoutStopSec=1h
...
PIDFile=/run/postgresql/%i.pid
...また、このファイルの中に PIDFile=/run/postgresql/%i.pid という設定行が見つかります。%i は 9.6-main にあたるでしょう。
/var/log/syslog ファイル中では、/run/postgresql/9.6-main.pid というファイルが見つからないというエラーが出力され、代わりに /run/postgresql/postgresql.pid があったため、この違いを生み出したのは何かを調べていきます。
ファイル名 postgresql.pid を使った操作をしているコードを探すと、Trove が提供する PostgreSQL 用の elements に以下のコードが見つかります。
ubuntu-postgresql/install.d/30-postgresql
...
sed -i "s/external_pid_file =.*/external_pid_file = '\/var\/run\/postgresql\/postgresql.pid'/" /etc/postgresql/9.6/main/postgresql.conf
.../etc/postgresql/9.6/main/postgresql.conf ファイル中の PID file の設定を /var/run/postgresql/postgresql.pid となるように書き換えています。
/etc/postgresql/9.6/main/postgresql.conf
external_pid_file = '/var/run/postgresql/postgresql.pid'実際に確認してみると、確かにこの設定になっています。
root@post:~# ls -l /var/run
lrwxrwxrwx. 1 root root 4 Jan 14 02:02 /var/run -> /runここで、/var/run は /run へのシンボリックリンクとなっているため、/var/run/postgresql/postgresql.pid と /run/postgresql/postgresql.pid は同じファイルです。これにより、PostgreSQL サーバーの起動によって、PID file は設定どおりに正しく作成されていることがわかります。
また、もう 1 つ、postgresql.pid を使っている Trove の elements コードが見つかります。
ubuntu-xenial-postgresql/install.d/31-fix-init-script
...
sed -i "s/PIDFile=\/var\/run\/postgresql\/%i.pid/PIDFile=\/var\/run\/postgresql\/postgresql.pid/" /lib/systemd/system/postgresql@.service
...ここでは、まさに /lib/systemd/system/postgresql@.service ファイルに対しての変更を行っており、PIDFile= の設定を /var/run/postgresql/%i.pid から /var/run/postgresql/postgresql.pid に変えるものになっています。 しかしながら、実際の /lib/systemd/system/postgresql@.service ファイルの記述は、この想定された文字列パターンと比べ差分があるようです。
《問題原因》
ubuntu-xenial-postgresql/install.d/31-fix-init-script
...
sed -i "s/PIDFile=\/var\/run\/postgresql\/%i.pid/PIDFile=\/var\/run\/postgresql\/postgresql.pid/" /lib/systemd/system/postgresql@.service
.../lib/systemd/system/postgresql@.service
...
[Service]
...
PIDFile=/run/postgresql/%i.pid
...elements コード内の sed で想定しているマッチングパターンと、実際の /lib/systemd/system/postgresql@.service 内の記述を並べて比べると、以下のように違っています。
想定：
PIDFile=/var/run/postgresql/%i.pid実際：
PIDFile=/run/postgresql/%i.pid/var の差分がある分だけマッチングパターンに合わないため、sed による /lib/systemd/system/postgresql@.service ファイルの変更に失敗していたようです。
解析結果のまとめ
Diskimage-builder によって、PostgreSQL サーバー起動イメージ作成時に使用される elements コード ubuntu-xenial-postgresql/install.d/31-fix-init-script にある、sed コマンドのマッチングパターン
PIDFile=\/var\/run\/postgresql\/%i.pid
に、もとの /lib/systemd/system/postgresql@.service ファイルの設定行
PIDFile=/run/postgresql/%i.pid
が、/var の差分がある分だけマッチしないため、該当行を正しく
PIDFile=/var/run/postgresql/postgresql.pid
に変更できず、もとの記述のままでイメージが作成されていました。
一方 elements コード ubuntu-postgresql/install.d/30-postgresql では、
/etc/postgresql/9.6/main/postgresql.conf ファイルでの PID file の指定を
正しく
external_pid_file = '/var/run/postgresql/postgresql.pid'
となるよう書き換えています。
これにより、PostgreSQL 自体は /etc/postgresql/9.6/main/postgresql.conf の設定にしたがい
/var/run/postgresql/postgresql.pid ファイルを作成したが、
systemd による制御では PID file を /run/postgresql/9.6-main.pid と想定して動作しようとし、うまくサービス停止処理ができないという事態に陥りました。 また、PID file 名の相違は、postgresql@9.6-main.service サービスが activating 状態のままだったことにも影響していたと思われます。
※ /var/run は /run へのシンボリックリンクのため、/var/run/postgresql/postgresql.pid と /run/postgresql/postgresql.pid は同じファイルとなります。
問題の対処
PostgreSQL サーバー起動イメージ内の /lib/systemd/system/postgresql@.service ファイルが正しく変更されるように、イメージビルド環境にて elements コード ubuntu-xenial-postgresql/install.d/31-fix-init-script にある sed のマッチングパターンを修正し、イメージの再ビルド・再登録を実施します。
修正前：
...
sed -i "s/PIDFile=\/var\/run\/postgresql\/%i.pid/PIDFile=\/var\/run\/postgresql\/postgresql.pid/" /lib/systemd/system/postgresql@.service
...修正後：
...
sed -i "s/PIDFile=.*\/run\/postgresql\/%i.pid/PIDFile=\/var\/run\/postgresql\/postgresql.pid/" /lib/systemd/system/postgresql@.service
...イメージのビルド・登録については、Trove 導入入門編、イメージ作成編および、本記事の PostgreSQL 用のパラメータ設定を参照してください。
対処結果
PostgreSQL を使用した Trove インスタンスが正常に起動できない問題に対し、ここまでのログ解析・対処を行い、起動しなおしました。しかし、一部のエラーは解消されたものの、残念ながらまだ起動には至りませんでした。
そこで、次回は問題解析編 2として、引き続きログの解析を続け、失敗の原因をつきとめていきます。
記事をシェアする
