はじめに
カタパルトにはリカバリーノードというのがあります。
何かのきっかけで、通常ノードが異常終了した際、そのままでは再開始はできません。
これを修復してくれるのがリカバリーノードです。
slackでチラホラ情報を見かけるようになったので、やってみました。
やってみる
準備
まずは、APIノードとmongoDBとブローカーノードを起動した状況を作成します。
基本は、catapult-service-bootstrapを使います。
あと、プロジェクトのルートにこのようなファイルを置きます。
docker-compose.yml
# Copyright 2018 Tech Bureau, Corp
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http:#www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
version: '2'
services:
db:
image: mongo
command: bash -c "mongod --dbpath=/dbdata --bind_ip=db"
stop_signal: SIGINT
volumes:
- ./data/mongo:/dbdata:rw
- ./bin/bash:/bin-mount
init-db:
image: mongo
command: bash -c "/bin/bash /userconfig/mongors.sh"
volumes:
- ./data/mongo:/dbdata:rw
- ./static-config/mongo/:/userconfig/:ro
- ./bin/bash:/bin-mount
depends_on:
- db
api-node-0:
build: cmds/docker/dockerfiles/catapult
command: bash -c "/bin-mount/wait /state/api-node-0-nemgen && /bin-mount/wait /state/api-node-0-broker && /bin/bash /userconfig/startApiServer.sh"
stop_signal: SIGINT
ports:
- "7610:7610"
volumes:
- ./build/catapult-config/api-node-0/userconfig/resources/:/userconfig/resources/
- ./data/api-node-0:/data:rw
- ./bin/bash:/bin-mount
- ./build/state:/state
api-node-broker-0:
build: cmds/docker/dockerfiles/catapult
command: bash -c "/bin-mount/wait /state/api-node-0-nemgen && /bin/bash /userconfig/startBroker.sh"
stop_signal: SIGINT
volumes:
- ./build/catapult-config/api-node-0/userconfig/resources/:/userconfig/resources/
- ./data/api-node-0:/data:rw
- ./bin/bash:/bin-mount
- ./build/state:/state
api-node-0-recover:
build: cmds/docker/dockerfiles/catapult
command: bash -c "/bin-mount/wait /state/api-node-0-nemgen && /bin/bash /userconfig/runServerRecover.sh"
stop_signal: SIGINT
volumes:
- ./build/catapult-config/api-node-0/userconfig/resources/:/userconfig/resources/
- ./data/api-node-0:/data:rw
- ./bin/bash:/bin-mount
- ./build/state:/state
Peerノードはどこかで動いているとしたら、最低限このような感じになると思います。
$ docker-compose ps
Name Command State Ports
---------------------------------------------------------------------------------------------------
catapult_api-node-0_1 bash -c /bin-mount/wait /s ... Up 0.0.0.0:7610->7610/tcp
catapult_api-node-broker-0_1 bash -c /bin-mount/wait /s ... Up
catapult_db_1 docker-entrypoint.sh bash ... Up 27017/tcp
catapult_init-db_1 docker-entrypoint.sh bash ... Exit 0
まずは、これをなんとかして異常終了させようと思います。
高負荷をかけて異常終了させる
stressを使い、負荷をかけました。
$ stress -d 16 -m 6 -c 6 -i 6
stress: info: [15630] dispatching hogs: 6 cpu, 6 io, 6 vm, 16 hdd
APIノードは、遅延のログが出ましたが、ダウンしませんでした。
api-node-0_1 | 2019-10-28 14:14:57.658355 0x00007f11917fa700: <warning> (utils::StackLogger.h@64) slow operation detected: 'HashCache/' (1250ms)
api-node-0_1 | 2019-10-28 14:15:00.307660 0x00007f11917fa700: <warning> (utils::StackLogger.h@64) slow operation detected: 'MultisigCache/' (1175ms)
api-node-0_1 | 2019-10-28 14:15:01.977564 0x00007f11917fa700: <warning> (utils::StackLogger.h@64) slow operation detected: 'HashLockInfoCache/' (1421ms)
api-node-0_1 | 2019-10-28 14:15:04.513163 0x00007f11917fa700: <warning> (utils::StackLogger.h@64) slow operation detected: 'AccountRestrictionCache/' (1148ms)
api-node-0_1 | 2019-10-28 14:15:07.053232 0x00007f11917fa700: <warning> (utils::StackLogger.h@64) slow operation detected: 'MosaicRestrictionCache/' (1243ms)
mongoDBはダウンしました。
db_1 | 2019-10-28T14:15:04.194+0000 I COMMAND [PeriodicTaskRunner] task: DBConnectionPool-cleaner took: 374ms
db_1 | 2019-10-28T14:15:19.395+0000 I COMMAND [conn6] command catapult.blocks command: insert { insert: "blocks", ordered: true, $db: "catapult" } ninserted:1 keysInserted:5 numYields:0 reslen:45 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } }, Mutex: { acquireCount: { r: 2 } } } flowControl:{ acquireCount: 1 } storage:{} protocol:op_msg 1013ms
catapult_db_1 exited with code 137
BrokerノードはmongoDBがダウンしたため、ダウンしました。
api-node-broker-0_1 | 2019-10-28 14:16:48.887760 0x00007f87991ec700: <fatal> (process::ProcessMain.cpp@65)
api-node-broker-0_1 | thread: 0 (broker) work
api-node-broker-0_1 | unhandled exception while running local node!
api-node-broker-0_1 | Dynamic exception type: mongocxx::v_noabi::bulk_write_exception
api-node-broker-0_1 | std::exception::what: No suitable servers found: `serverSelectionTimeoutMS` expired: [Failed to resolve 'db']: generic server error
api-node-broker-0_1 |
catapult_api-node-broker-0_1 exited with code 139
このような状況になりました。
$ docker-compose ps
Name Command State Ports
----------------------------------------------------------------------------------------------------
catapult_api-node-0_1 bash -c /bin-mount/wait /s ... Up 0.0.0.0:7610->7610/tcp
catapult_api-node-broker-0_1 bash -c /bin-mount/wait /s ... Exit 139
catapult_db_1 docker-entrypoint.sh bash ... Exit 137
catapult_init-db_1 docker-entrypoint.sh bash ... Exit 0
dataフォルダーには、broker.lockファイルが残っています。
$ ls -l data/api-node-0/
total 12020
drwxrwxr-x 2 ec2-user ec2-user 3952640 Oct 28 13:32 00000
drwxr-xr-x 2 root root 2445312 Oct 28 14:27 00001
drwxr-xr-x 4 root root 4096 Oct 28 13:13 audit
---------- 1 root root 0 Oct 28 13:12 broker.lock
-rw-r--r-- 1 root root 143478 Oct 28 14:16 catapult_broker0000.log
-rw-r--r-- 1 root root 2060352 Oct 28 14:26 catapult_server0000.log
-rw------- 1 root root 8 Oct 28 14:27 commit_step.dat
-rw------- 1 root root 104710144 Oct 28 14:16 core.1
-rw-r--r-- 1 root root 8 Oct 28 14:27 index.dat
drwxr-xr-x 2 root root 4096 Oct 28 13:12 logs
---------- 1 root root 0 Oct 28 13:13 server.lock
drwxr-xr-x 8 root root 4096 Oct 28 13:13 spool
drwxr-xr-x 2 root root 4096 Oct 28 13:13 startup
drwxr-xr-x 2 root root 4096 Oct 28 14:27 state
drwxr-xr-x 12 root root 4096 Oct 28 13:13 statedb
リカバリーノードを動かしてみる
それではリカバリーノードを動かしてみます。
$ docker-compose up api-node-0-recover
api-node-0-recover_1 | !!!! Have lock file present, going to run recovery....
api-node-0-recover_1 | Copyright (c) Jaguar0625, gimre, BloodyRookie, Tech Bureau, Corp.
api-node-0-recover_1 | catapult version: 0.8.0.3 (public)
api-node-0-recover_1 | loading resources from "/userconfig/resources"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-inflation.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-extensions-recovery.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-user.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-logging-recovery.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-node.properties"
api-node-0-recover_1 | 2019-10-28 14:29:53.952364 0x00007f7cab53f480: <info> (process::ProcessMain.cpp@80) booting process with public key 63A2094799D5B4F1DAAE34C707DE1E6F18C8CDD955A95266B7126A5B041DF536
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-network.properties"
api-node-0-recover_1 | 2019-10-28 14:29:53.958982 0x00007f7cab53f480: <info> (thread::IoThreadPool.cpp@104) spawned 1 workers (recovery)
api-node-0-recover_1 | 2019-10-28 14:29:53.961605 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libextension.addressextraction.so
api-node-0-recover_1 | 2019-10-28 14:29:53.965972 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libextension.addressextraction.so loaded as 0x55d12b944790
api-node-0-recover_1 | 2019-10-28 14:29:53.966470 0x00007f7cab53f480: <info> (extensions::ProcessBootstrapper.cpp@102) registering dynamic extension extension.addressextraction
api-node-0-recover_1 | 2019-10-28 14:29:53.973198 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libextension.mongo.so
api-node-0-recover_1 | 2019-10-28 14:29:53.978990 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libextension.mongo.so loaded as 0x55d12b9515a0
api-node-0-recover_1 | 2019-10-28 14:29:53.979071 0x00007f7cab53f480: <info> (extensions::ProcessBootstrapper.cpp@102) registering dynamic extension extension.mongo
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-database.properties"
api-node-0-recover_1 | 2019-10-28 14:29:53.996384 0x00007f7cab53f480: <info> (thread::IoThreadPool.cpp@104) spawned 4 workers (bulk writer)
api-node-0-recover_1 | 2019-10-28 14:29:53.999347 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.restrictionmosaic.so
api-node-0-recover_1 | 2019-10-28 14:29:54.000886 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.restrictionmosaic.so loaded as 0x55d12b960450
api-node-0-recover_1 | 2019-10-28 14:29:54.000975 0x00007f7cab53f480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.restrictionmosaic
api-node-0-recover_1 | 2019-10-28 14:29:54.047509 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.restrictionaccount.so
api-node-0-recover_1 | 2019-10-28 14:29:54.049861 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.restrictionaccount.so loaded as 0x55d12b963040
api-node-0-recover_1 | 2019-10-28 14:29:54.049970 0x00007f7cab53f480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.restrictionaccount
api-node-0-recover_1 | 2019-10-28 14:29:54.051609 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.multisig.so
api-node-0-recover_1 | 2019-10-28 14:29:54.055278 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.multisig.so loaded as 0x55d12b966150
api-node-0-recover_1 | 2019-10-28 14:29:54.055374 0x00007f7cab53f480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.multisig
api-node-0-recover_1 | 2019-10-28 14:29:54.059330 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.mosaic.so
api-node-0-recover_1 | 2019-10-28 14:29:54.061040 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.mosaic.so loaded as 0x55d12b9693a0
api-node-0-recover_1 | 2019-10-28 14:29:54.061205 0x00007f7cab53f480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.mosaic
api-node-0-recover_1 | 2019-10-28 14:29:54.062563 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.metadata.so
api-node-0-recover_1 | 2019-10-28 14:29:54.064908 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.metadata.so loaded as 0x55d12b96c320
api-node-0-recover_1 | 2019-10-28 14:29:54.065367 0x00007f7cab53f480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.metadata
api-node-0-recover_1 | 2019-10-28 14:29:54.066927 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.locksecret.so
api-node-0-recover_1 | 2019-10-28 14:29:54.068538 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.locksecret.so loaded as 0x55d12b96f8d0
api-node-0-recover_1 | 2019-10-28 14:29:54.068582 0x00007f7cab53f480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.locksecret
api-node-0-recover_1 | 2019-10-28 14:29:54.069934 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.lockhash.so
api-node-0-recover_1 | 2019-10-28 14:29:54.071596 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.lockhash.so loaded as 0x55d12b972a20
api-node-0-recover_1 | 2019-10-28 14:29:54.071638 0x00007f7cab53f480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.lockhash
api-node-0-recover_1 | 2019-10-28 14:29:54.074962 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.aggregate.so
api-node-0-recover_1 | 2019-10-28 14:29:54.076383 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.aggregate.so loaded as 0x55d12b975980
api-node-0-recover_1 | 2019-10-28 14:29:54.076425 0x00007f7cab53f480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.aggregate
api-node-0-recover_1 | 2019-10-28 14:29:54.076453 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.transfer.so
api-node-0-recover_1 | 2019-10-28 14:29:54.076642 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.transfer.so loaded as 0x55d12b976540
api-node-0-recover_1 | 2019-10-28 14:29:54.076674 0x00007f7cab53f480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.transfer
api-node-0-recover_1 | 2019-10-28 14:29:54.076696 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.namespace.so
api-node-0-recover_1 | 2019-10-28 14:29:54.078183 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.namespace.so loaded as 0x55d12b976cb0
api-node-0-recover_1 | 2019-10-28 14:29:54.078224 0x00007f7cab53f480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.namespace
api-node-0-recover_1 | 2019-10-28 14:29:54.080867 0x00007f7cab53f480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.accountlink.so
api-node-0-recover_1 | 2019-10-28 14:29:54.081120 0x00007f7cab53f480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.accountlink.so loaded as 0x55d12b979b60
api-node-0-recover_1 | 2019-10-28 14:29:54.081158 0x00007f7cab53f480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.accountlink
api-node-0-recover_1 | 2019-10-28 14:29:54.081203 0x00007f7cab53f480: <debug> (src::ExternalCacheStorageBuilder.h@49) creating ExternalCacheStorage with 9 storages
api-node-0-recover_1 | 2019-10-28 14:30:24.083510 0x00007f7cab53f480: <error> (extensions::ProcessBootstrapper.cpp@93) Throwing exception: Throw location unknown (consider using BOOST_THROW_EXCEPTION)
api-node-0-recover_1 | Dynamic exception type: boost::exception_detail::clone_impl<boost::exception_detail::current_exception_std_exception_wrapper<std::runtime_error> >
api-node-0-recover_1 | std::exception::what: No suitable servers found: `serverSelectionTimeoutMS` expired: [Failed to resolve 'db']: generic server error
api-node-0-recover_1 | mongocxx::v_noabi::bulk_write_exception
api-node-0-recover_1 | 2019-10-28 14:30:24.084396 0x00007f7cab53f480: <fatal> (process::ProcessMain.cpp@65)
api-node-0-recover_1 | thread: Process Main (r
api-node-0-recover_1 | unhandled exception while running local node!
api-node-0-recover_1 | /catapult-src/src/catapult/extensions/ProcessBootstrapper.cpp(93): Throw in function void catapult::extensions::{anonymous}::LoadExtension(const catapult::plugins::PluginModule&, catapult::extensions::ProcessBootstrapper&)
api-node-0-recover_1 | Dynamic exception type: boost::wrapexcept<catapult::plugins::plugin_load_error>
api-node-0-recover_1 | std::exception::what: Throw location unknown (consider using BOOST_THROW_EXCEPTION)
api-node-0-recover_1 | Dynamic exception type: boost::exception_detail::clone_impl<boost::exception_detail::current_exception_std_exception_wrapper<std::runtime_error> >
api-node-0-recover_1 | std::exception::what: No suitable servers found: `serverSelectionTimeoutMS` expired: [Failed to resolve 'db']: generic server error
api-node-0-recover_1 | mongocxx::v_noabi::bulk_write_exception
api-node-0-recover_1 |
catapult_api-node-0-recover_1 exited with code 139
失敗しました。mongocxx::v_noabi::bulk_write_exceptionとあるので、mongoDBが起動していないからでしょうか。
mongoDBを起動します。
$ docker-compose start mongoDB
Recoveryノードを起動します。
api-node-0-recover_1 | !!!! Have lock file present, going to run recovery....
api-node-0-recover_1 | Copyright (c) Jaguar0625, gimre, BloodyRookie, Tech Bureau, Corp.
api-node-0-recover_1 | catapult version: 0.8.0.3 (public)
api-node-0-recover_1 | loading resources from "/userconfig/resources"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-inflation.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-extensions-recovery.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-user.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-logging-recovery.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-node.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-network.properties"
api-node-0-recover_1 | 2019-10-28 14:31:52.484516 0x00007f622f456480: <warning> (io::FileLock.cpp@74) LockOpen failed: 2
api-node-0-recover_1 | 2019-10-28 14:31:52.484542 0x00007f622f456480: <fatal> (process::ProcessMain.cpp@121) could not acquire instance lock "/data/recovery.lock"
recovery.lockが残っているとしてエラーになりました。消します。
$ sudo rm data/api-node-0/recovery.lock
もう一度Recoveryノードを動かします。
api-node-0-recover_1 | !!!! Have lock file present, going to run recovery....
api-node-0-recover_1 | Copyright (c) Jaguar0625, gimre, BloodyRookie, Tech Bureau, Corp.
api-node-0-recover_1 | catapult version: 0.8.0.3 (public)
api-node-0-recover_1 | loading resources from "/userconfig/resources"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-inflation.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-extensions-recovery.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-user.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-logging-recovery.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-node.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-network.properties"
api-node-0-recover_1 | 2019-10-28 14:32:08.264827 0x00007f1214828480: <info> (process::ProcessMain.cpp@80) booting process with public key 63A2094799D5B4F1DAAE34C707DE1E6F18C8CDD955A95266B7126A5B041DF536
api-node-0-recover_1 | 2019-10-28 14:32:08.269205 0x00007f1214828480: <info> (thread::IoThreadPool.cpp@104) spawned 1 workers (recovery)
api-node-0-recover_1 | 2019-10-28 14:32:08.269282 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libextension.addressextraction.so
api-node-0-recover_1 | 2019-10-28 14:32:08.269965 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libextension.addressextraction.so loaded as 0x55997e66e790
api-node-0-recover_1 | 2019-10-28 14:32:08.270094 0x00007f1214828480: <info> (extensions::ProcessBootstrapper.cpp@102) registering dynamic extension extension.addressextraction
api-node-0-recover_1 | 2019-10-28 14:32:08.270320 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libextension.mongo.so
api-node-0-recover_1 | 2019-10-28 14:32:08.272633 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libextension.mongo.so loaded as 0x55997e67b5a0
api-node-0-recover_1 | 2019-10-28 14:32:08.279898 0x00007f1214828480: <info> (extensions::ProcessBootstrapper.cpp@102) registering dynamic extension extension.mongo
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-database.properties"
api-node-0-recover_1 | 2019-10-28 14:32:08.290123 0x00007f1214828480: <info> (thread::IoThreadPool.cpp@104) spawned 4 workers (bulk writer)
api-node-0-recover_1 | 2019-10-28 14:32:08.291148 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.restrictionmosaic.so
api-node-0-recover_1 | 2019-10-28 14:32:08.292260 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.restrictionmosaic.so loaded as 0x55997e68a490
api-node-0-recover_1 | 2019-10-28 14:32:08.292995 0x00007f1214828480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.restrictionmosaic
api-node-0-recover_1 | 2019-10-28 14:32:08.293311 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.restrictionaccount.so
api-node-0-recover_1 | 2019-10-28 14:32:08.295235 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.restrictionaccount.so loaded as 0x55997e68d060
api-node-0-recover_1 | 2019-10-28 14:32:08.300515 0x00007f1214828480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.restrictionaccount
api-node-0-recover_1 | 2019-10-28 14:32:08.304652 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.multisig.so
api-node-0-recover_1 | 2019-10-28 14:32:08.305887 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.multisig.so loaded as 0x55997e6901a0
api-node-0-recover_1 | 2019-10-28 14:32:08.307133 0x00007f1214828480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.multisig
api-node-0-recover_1 | 2019-10-28 14:32:08.310674 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.mosaic.so
api-node-0-recover_1 | 2019-10-28 14:32:08.311927 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.mosaic.so loaded as 0x55997e6933e0
api-node-0-recover_1 | 2019-10-28 14:32:08.312767 0x00007f1214828480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.mosaic
api-node-0-recover_1 | 2019-10-28 14:32:08.313622 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.metadata.so
api-node-0-recover_1 | 2019-10-28 14:32:08.314763 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.metadata.so loaded as 0x55997e696360
api-node-0-recover_1 | 2019-10-28 14:32:08.315604 0x00007f1214828480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.metadata
api-node-0-recover_1 | 2019-10-28 14:32:08.316457 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.locksecret.so
api-node-0-recover_1 | 2019-10-28 14:32:08.317434 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.locksecret.so loaded as 0x55997e699910
api-node-0-recover_1 | 2019-10-28 14:32:08.318449 0x00007f1214828480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.locksecret
api-node-0-recover_1 | 2019-10-28 14:32:08.319159 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.lockhash.so
api-node-0-recover_1 | 2019-10-28 14:32:08.320127 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.lockhash.so loaded as 0x55997e69ca60
api-node-0-recover_1 | 2019-10-28 14:32:08.321433 0x00007f1214828480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.lockhash
api-node-0-recover_1 | 2019-10-28 14:32:08.322190 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.aggregate.so
api-node-0-recover_1 | 2019-10-28 14:32:08.323189 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.aggregate.so loaded as 0x55997e69f9c0
api-node-0-recover_1 | 2019-10-28 14:32:08.324037 0x00007f1214828480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.aggregate
api-node-0-recover_1 | 2019-10-28 14:32:08.324596 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.transfer.so
api-node-0-recover_1 | 2019-10-28 14:32:08.325327 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.transfer.so loaded as 0x55997e6a0580
api-node-0-recover_1 | 2019-10-28 14:32:08.326284 0x00007f1214828480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.transfer
api-node-0-recover_1 | 2019-10-28 14:32:08.326833 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.namespace.so
api-node-0-recover_1 | 2019-10-28 14:32:08.327730 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.namespace.so loaded as 0x55997e6a0cf0
api-node-0-recover_1 | 2019-10-28 14:32:08.328859 0x00007f1214828480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.namespace
api-node-0-recover_1 | 2019-10-28 14:32:08.329570 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.accountlink.so
api-node-0-recover_1 | 2019-10-28 14:32:08.330341 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.accountlink.so loaded as 0x55997e6a3ba0
api-node-0-recover_1 | 2019-10-28 14:32:08.331336 0x00007f1214828480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.accountlink
api-node-0-recover_1 | 2019-10-28 14:32:08.332095 0x00007f1214828480: <debug> (src::ExternalCacheStorageBuilder.h@49) creating ExternalCacheStorage with 9 storages
api-node-0-recover_1 | 2019-10-28 14:32:08.343566 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libextension.zeromq.so
api-node-0-recover_1 | 2019-10-28 14:32:08.352669 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libextension.zeromq.so loaded as 0x55997e6b4950
api-node-0-recover_1 | 2019-10-28 14:32:08.353686 0x00007f1214828480: <info> (extensions::ProcessBootstrapper.cpp@102) registering dynamic extension extension.zeromq
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-messaging.properties"
api-node-0-recover_1 | 2019-10-28 14:32:08.367007 0x00007f1214828480: <info> (thread::IoThreadPool.cpp@104) spawned 1 workers (ZeroMqEntityPublisher)
api-node-0-recover_1 | 2019-10-28 14:32:08.370383 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libextension.hashcache.so
api-node-0-recover_1 | 2019-10-28 14:32:08.373597 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libextension.hashcache.so loaded as 0x55997e6bc8d0
api-node-0-recover_1 | 2019-10-28 14:32:08.374427 0x00007f1214828480: <info> (extensions::ProcessBootstrapper.cpp@102) registering dynamic extension extension.hashcache
api-node-0-recover_1 | 2019-10-28 14:32:08.377322 0x00007f1214828480: <info> (recovery::RecoveryOrchestrator.cpp@118) registering system plugins
api-node-0-recover_1 | 2019-10-28 14:32:08.378134 0x00007f1214828480: <info> (plugins::PluginLoader.cpp@50) registering dynamic plugin catapult.plugins.coresystem
api-node-0-recover_1 | 2019-10-28 14:32:08.378898 0x00007f1214828480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.plugins.coresystem.so
api-node-0-recover_1 | 2019-10-28 14:32:08.382306 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.plugins.coresystem.so loaded as 0x55997e6bded0
api-node-0-recover_1 | 2019-10-28 14:32:08.387442 0x00007f1214828480: <error> (cache_db::RocksDatabase.cpp@128) Throwing exception: couldn't open database (/data/statedb/AccountStateCache, IO error: While lock file: /data/statedb/AccountStateCache/LOCK: Resource temporarily unavailable)
api-node-0-recover_1 | 2019-10-28 14:32:08.388639 0x00007f1214828480: <error> (plugins::PluginLoader.cpp@44) Throwing exception: /catapult-src/src/catapult/cache_db/RocksDatabase.cpp(128): Throw in function catapult::cache::RocksDatabase::RocksDatabase(const catapult::cache::RocksDatabaseSettings&)
api-node-0-recover_1 | Dynamic exception type: boost::exception_detail::clone_impl<catapult::catapult_error<std::runtime_error> >
api-node-0-recover_1 | std::exception::what: couldn't open database
api-node-0-recover_1 | [catapult::ErrorParam1*] = /data/statedb/AccountStateCache
api-node-0-recover_1 | [catapult::ErrorParam2*] = IO error: While lock file: /data/statedb/AccountStateCache/LOCK: Resource temporarily unavailable
api-node-0-recover_1 |
api-node-0-recover_1 | 2019-10-28 14:32:08.390213 0x00007f1214828480: <debug> (plugins::PluginModule.cpp@85) unloading module 0x55997e6bded0 (libcatapult.plugins.coresystem.so)
api-node-0-recover_1 | 2019-10-28 14:32:08.391192 0x00007f1214828480: <fatal> (local::HostUtils.h@42) unhandled exception while boot!
api-node-0-recover_1 | /catapult-src/src/catapult/plugins/PluginLoader.cpp(44): Throw in function void catapult::plugins::{anonymous}::LoadPlugin(catapult::plugins::PluginManager&, const catapult::plugins::PluginModule&, const char*)
api-node-0-recover_1 | Dynamic exception type: boost::wrapexcept<catapult::plugins::plugin_load_error>
api-node-0-recover_1 | std::exception::what: /catapult-src/src/catapult/cache_db/RocksDatabase.cpp(128): Throw in function catapult::cache::RocksDatabase::RocksDatabase(const catapult::cache::RocksDatabaseSettings&)
api-node-0-recover_1 | Dynamic exception type: boost::exception_detail::clone_impl<catapult::catapult_error<std::runtime_error> >
api-node-0-recover_1 | std::exception::what: couldn't open database
api-node-0-recover_1 | [catapult::ErrorParam1*] = /data/statedb/AccountStateCache
api-node-0-recover_1 | [catapult::ErrorParam2*] = IO error: While lock file: /data/statedb/AccountStateCache/LOCK: Resource temporarily unavailable
api-node-0-recover_1 |
api-node-0-recover_1 |
api-node-0-recover_1 | 2019-10-28 14:32:08.393124 0x00007f1214828480: <error> (local::HostUtils.h@43) Throwing exception: /catapult-src/src/catapult/cache_db/RocksDatabase.cpp(128): Throw in function catapult::cache::RocksDatabase::RocksDatabase(const catapult::cache::RocksDatabaseSettings&)
api-node-0-recover_1 | Dynamic exception type: boost::exception_detail::clone_impl<catapult::catapult_error<std::runtime_error> >
api-node-0-recover_1 | std::exception::what: couldn't open database
api-node-0-recover_1 | [catapult::ErrorParam1*] = /data/statedb/AccountStateCache
api-node-0-recover_1 | [catapult::ErrorParam2*] = IO error: While lock file: /data/statedb/AccountStateCache/LOCK: Resource temporarily unavailable
api-node-0-recover_1 |
api-node-0-recover_1 | 2019-10-28 14:32:08.394743 0x00007f1214828480: <fatal> (process::ProcessMain.cpp@65)
api-node-0-recover_1 | thread: Process Main (r
api-node-0-recover_1 | unhandled exception while running local node!
api-node-0-recover_1 | /catapult-src/src/catapult/local/HostUtils.h(43): Throw in function std::unique_ptr<_Tp> catapult::local::CreateAndBootHost(TArgs&& ...) [with THost = catapult::local::{anonymous}::DefaultRecoveryOrchestrator; TArgs = {std::unique_ptr<catapult::extensions::ProcessBootstrapper, std::default_delete<catapult::extensions::ProcessBootstrapper> >}]
api-node-0-recover_1 | Dynamic exception type: boost::wrapexcept<catapult::catapult_error<std::runtime_error> >
api-node-0-recover_1 | std::exception::what: /catapult-src/src/catapult/cache_db/RocksDatabase.cpp(128): Throw in function catapult::cache::RocksDatabase::RocksDatabase(const catapult::cache::RocksDatabaseSettings&)
api-node-0-recover_1 | Dynamic exception type: boost::exception_detail::clone_impl<catapult::catapult_error<std::runtime_error> >
api-node-0-recover_1 | std::exception::what: couldn't open database
api-node-0-recover_1 | [catapult::ErrorParam1*] = /data/statedb/AccountStateCache
api-node-0-recover_1 | [catapult::ErrorParam2*] = IO error: While lock file: /data/statedb/AccountStateCache/LOCK: Resource temporarily unavailable
api-node-0-recover_1 |
api-node-0-recover_1 |
catapult_api-node-0-recover_1 exited with code 139
RocksDBがオープンできないというエラーになりました。起動している他のコンテナーの中で、RocksDBを使っているのはAPIノードです。これを止めます。
$ docker-compose stop api-node-0
もう一度Recoveryノードを起動します。
api-node-0-recover_1 | !!!! Have lock file present, going to run recovery....
api-node-0-recover_1 | Copyright (c) Jaguar0625, gimre, BloodyRookie, Tech Bureau, Corp.
api-node-0-recover_1 | catapult version: 0.8.0.3 (public)
...
api-node-0-recover_1 | 2019-10-28 14:39:23.894866 0x00007fd1accf8480: <debug> (recovery::RecoveryOrchestrator.cpp@121) initializing cache
api-node-0-recover_1 | 2019-10-28 14:39:23.894883 0x00007fd1accf8480: <debug> (cache::CatapultCacheBuilder.h@50) creating CatapultCache with 11 sub caches
api-node-0-recover_1 | 2019-10-28 14:39:23.894891 0x00007fd1accf8480: <info> (utils::StackLogger.h@35) pushing scope 'running recovery operations'
api-node-0-recover_1 | 2019-10-28 14:39:23.894895 0x00007fd1accf8480: <info> (recovery::RecoveryOrchestrator.cpp@132) repairing spooling, commit step 2
api-node-0-recover_1 | 2019-10-28 14:39:23.897943 0x00007fd1accf8480: <debug> (recovery::RepairSpooling.cpp@37) - leaving block_change unchanged
api-node-0-recover_1 | 2019-10-28 14:39:23.897957 0x00007fd1accf8480: <debug> (recovery::RepairSpooling.cpp@37) - leaving transaction_status unchanged
api-node-0-recover_1 | 2019-10-28 14:39:23.897962 0x00007fd1accf8480: <debug> (recovery::RepairSpooling.cpp@42) - purging partial_transactions_change
api-node-0-recover_1 | 2019-10-28 14:39:23.898039 0x00007fd1accf8480: <debug> (recovery::RepairSpooling.cpp@42) - purging unconfirmed_transactions_change
api-node-0-recover_1 | 2019-10-28 14:39:23.898085 0x00007fd1accf8480: <debug> (recovery::RepairSpooling.cpp@42) - purging block_recover
api-node-0-recover_1 | 2019-10-28 14:39:23.898107 0x00007fd1accf8480: <debug> (recovery::RepairSpooling.cpp@42) - purging block_sync
api-node-0-recover_1 | 2019-10-28 14:39:23.898125 0x00007fd1accf8480: <debug> (recovery::RepairSpooling.cpp@59) - setting index_server.dat to index.dat
api-node-0-recover_1 | 2019-10-28 14:39:23.898152 0x00007fd1accf8480: <info> (recovery::RecoveryOrchestrator.cpp@135) repairing messages
api-node-0-recover_1 | 2019-10-28 14:39:23.898175 0x00007fd1accf8480: <debug> (subscribers::BrokerMessageReaders.h@89) preparing to process 108 messages from /data/spool/block_change
api-node-0-recover_1 | 2019-10-28 14:39:24.039850 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 1 blocks
api-node-0-recover_1 | 2019-10-28 14:39:24.046336 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 0 transactions
api-node-0-recover_1 | 2019-10-28 14:39:24.047593 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 1 transactionStatements
api-node-0-recover_1 | 2019-10-28 14:39:24.052663 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 0 addressResolutionStatements
api-node-0-recover_1 | 2019-10-28 14:39:24.057923 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 0 mosaicResolutionStatements
api-node-0-recover_1 | 2019-10-28 14:39:24.061961 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 2 blocks
api-node-0-recover_1 | 2019-10-28 14:39:24.063065 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 0 transactions
api-node-0-recover_1 | 2019-10-28 14:39:24.064182 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 2 transactionStatements
api-node-0-recover_1 | 2019-10-28 14:39:24.065216 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 0 addressResolutionStatements
api-node-0-recover_1 | 2019-10-28 14:39:24.066243 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 0 mosaicResolutionStatements
api-node-0-recover_1 | 2019-10-28 14:39:24.070004 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 2 blocks
api-node-0-recover_1 | 2019-10-28 14:39:24.071131 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 0 transactions
api-node-0-recover_1 | 2019-10-28 14:39:24.072239 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 2 transactionStatements
api-node-0-recover_1 | 2019-10-28 14:39:24.073267 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 0 addressResolutionStatements
api-node-0-recover_1 | 2019-10-28 14:39:24.074329 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 0 mosaicResolutionStatements
api-node-0-recover_1 | 2019-10-28 14:39:24.082380 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 2 blocks
api-node-0-recover_1 | 2019-10-28 14:39:24.083500 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 0 transactions
api-node-0-recover_1 | 2019-10-28 14:39:24.084599 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 2 transactionStatements
api-node-0-recover_1 | 2019-10-28 14:39:24.085627 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 0 addressResolutionStatements
api-node-0-recover_1 | 2019-10-28 14:39:24.086657 0x00007fd1accf8480: <info> (src::MongoBlockStorage.cpp@143) deleted 0 mosaicResolutionStatements
api-node-0-recover_1 | 2019-10-28 14:39:24.105246 0x00007fd1accf8480: <info> (recovery::RecoveryOrchestrator.cpp@138) loading state
api-node-0-recover_1 | 2019-10-28 14:39:24.106206 0x00007fd1accf8480: <warning> (utils::StackLogger.h@35) pushing scope 'load state'
api-node-0-recover_1 | 2019-10-28 14:39:24.107258 0x00007fd1accf8480: <debug> (cache::SupplementalDataStorage.cpp@31) read last recalculation height 109629 dynamic fee multiplier 10000 total transactions 9227 (score = [0, 2496763646886046501], height = 109636)
api-node-0-recover_1 | 2019-10-28 14:39:24.130363 0x00007fd1accf8480: <warning> (utils::StackLogger.h@41) popping scope 'load state' (24ms)
api-node-0-recover_1 | 2019-10-28 14:39:24.131577 0x00007fd1accf8480: <info> (recovery::RecoveryOrchestrator.cpp@146) loaded block chain (height = 109636, score = 2496763646886046501)
api-node-0-recover_1 | 2019-10-28 14:39:24.132354 0x00007fd1accf8480: <info> (recovery::RecoveryOrchestrator.cpp@148) repairing state
api-node-0-recover_1 | 2019-10-28 14:39:24.133153 0x00007fd1accf8480: <debug> (subscribers::BrokerMessageReaders.h@89) preparing to process 188 messages from /data/spool/state_change
api-node-0-recover_1 | 2019-10-28 14:39:24.275341 0x00007fd1accf8480: <debug> (recovery::RecoveryOrchestrator.cpp@200) - purging state.tmp
api-node-0-recover_1 | 2019-10-28 14:39:24.276607 0x00007fd1accf8480: <info> (recovery::RecoveryOrchestrator.cpp@151) finalizing
api-node-0-recover_1 | 2019-10-28 14:39:24.277479 0x00007fd1accf8480: <info> (utils::StackLogger.h@41) popping scope 'running recovery operations' (382ms)
api-node-0-recover_1 | 2019-10-28 14:39:24.278293 0x00007fd1accf8480: <info> (process::ProcessMain.cpp@86) shutting down process
api-node-0-recover_1 | 2019-10-28 14:39:24.279122 0x00007fd1accf8480: <info> (utils::StackLogger.h@35) pushing scope 'shutting down recovery orchestrator'
api-node-0-recover_1 | 2019-10-28 14:39:24.279928 0x00007fd1accf8480: <info> (thread::MultiServicePool.h@161) shutting down bulk writer (isolated pool)
api-node-0-recover_1 | 2019-10-28 14:39:24.280741 0x00007fd1accf8480: <debug> (thread::IoThreadPool.cpp@111) waiting for 4 thread pool threads to exit (bulk writer)
api-node-0-recover_1 | 2019-10-28 14:39:24.281751 0x00007fd1accf8480: <info> (thread::IoThreadPool.cpp@113) all thread pool threads exited (bulk writer)
api-node-0-recover_1 | 2019-10-28 14:39:24.282530 0x00007fd1accf8480: <debug> (thread::IoThreadPool.cpp@111) waiting for 1 thread pool threads to exit (recovery)
api-node-0-recover_1 | 2019-10-28 14:39:24.283443 0x00007fd1accf8480: <info> (thread::IoThreadPool.cpp@113) all thread pool threads exited (recovery)
api-node-0-recover_1 | 2019-10-28 14:39:24.284634 0x00007fd1accf8480: <debug> (cache::SupplementalDataStorage.cpp@31) wrote last recalculation height 109629 dynamic fee multiplier 10000 total transactions 9227 (score = [0, 2496763646886046501], height = 109636)
api-node-0-recover_1 | 2019-10-28 14:39:24.285628 0x00007fd1accf8480: <info> (utils::StackLogger.h@41) popping scope 'shutting down recovery orchestrator' (6ms)
...
catapult_api-node-0-recover_1 exited with code 0
こんどはうまくいきました。
deleted 1 blocks
deleted 0 transactions
deleted 1 transactionStatements
deleted 0 addressResolutionStatements
deleted 0 mosaicResolutionStatements
このようなログが出ているので、何かを修復したと思われます。
正常復帰
APIノードとBrokerノードを立ち上げます。
$ docker-compose start api-node-0 api-node-broker-0
これで正常な状態に戻りました。
$ docker-compose ps
Name Command State Ports
---------------------------------------------------------------------------------------------------
catapult_api-node-0-recover_1 bash -c /bin-mount/wait /s ... Exit 0
catapult_api-node-0_1 bash -c /bin-mount/wait /s ... Up 0.0.0.0:7610->7610/tcp
catapult_api-node-broker-0_1 bash -c /bin-mount/wait /s ... Up
catapult_db_1 docker-entrypoint.sh bash ... Up 27017/tcp
catapult_init-db_1 docker-entrypoint.sh bash ... Exit 0
壊れた時の手順まとめ
これまでのやり方をまとめます。
たぶん、異常終了しているときは、このような状態になっていると思います。
Name Command State Ports
----------------------------------------------------------------------------------------------------
catapult_api-node-0_1 bash -c /bin-mount/wait /s ... Up 0.0.0.0:7610->7610/tcp
catapult_api-node-broker-0_1 bash -c /bin-mount/wait /s ... Exit 139
catapult_db_1 docker-entrypoint.sh bash ... Exit 137
catapult_init-db_1 docker-entrypoint.sh bash ... Exit 0
APIノードを止めます。ブローカーノードも動いていた場合、これも止めます。
$ docker-compose stop api-node-0
$ docker-compose stop api-node-broker-0
mongoDBを開始します。
$ docker-compose start db
このような状況になっていると思います。
Name Command State Ports
---------------------------------------------------------------------------------------
catapult_api-node-0_1 bash -c /bin-mount/wait /s ... Exit 0
catapult_api-node-broker-0_1 bash -c /bin-mount/wait /s ... Exit 139
catapult_db_1 docker-entrypoint.sh bash ... Up 27017/tcp
catapult_init-db_1 docker-entrypoint.sh bash ... Exit 0
リカバリーノードを起動します。
$ docker-compose up api-node-0-recover
api-node-0-recover_1 | 2019-10-29 03:49:56.240469 0x00007f7522a14480: <debug> (cache::CatapultCacheBuilder.h@50) creating CatapultCache with 11 sub caches
api-node-0-recover_1 | 2019-10-29 03:49:56.240926 0x00007f7522a14480: <info> (utils::StackLogger.h@35) pushing scope 'running recovery operations'
api-node-0-recover_1 | 2019-10-29 03:49:56.241378 0x00007f7522a14480: <info> (recovery::RecoveryOrchestrator.cpp@132) repairing spooling, commit step 2
api-node-0-recover_1 | 2019-10-29 03:49:56.241867 0x00007f7522a14480: <debug> (recovery::RepairSpooling.cpp@37) - leaving block_change unchanged
api-node-0-recover_1 | 2019-10-29 03:49:56.242311 0x00007f7522a14480: <debug> (recovery::RepairSpooling.cpp@37) - leaving transaction_status unchanged
api-node-0-recover_1 | 2019-10-29 03:49:56.242769 0x00007f7522a14480: <debug> (recovery::RepairSpooling.cpp@42) - purging partial_transactions_change
api-node-0-recover_1 | 2019-10-29 03:49:56.243719 0x00007f7522a14480: <debug> (recovery::RepairSpooling.cpp@42) - purging unconfirmed_transactions_change
api-node-0-recover_1 | 2019-10-29 03:49:56.244292 0x00007f7522a14480: <debug> (recovery::RepairSpooling.cpp@42) - purging block_recover
api-node-0-recover_1 | 2019-10-29 03:49:56.244795 0x00007f7522a14480: <debug> (recovery::RepairSpooling.cpp@42) - purging block_sync
api-node-0-recover_1 | 2019-10-29 03:49:56.244826 0x00007f7522a14480: <debug> (recovery::RepairSpooling.cpp@59) - setting index_server.dat to index.dat
api-node-0-recover_1 | 2019-10-29 03:49:56.244885 0x00007f7522a14480: <info> (recovery::RecoveryOrchestrator.cpp@135) repairing messages
api-node-0-recover_1 | 2019-10-29 03:49:56.244913 0x00007f7522a14480: <debug> (subscribers::BrokerMessageReaders.h@89) preparing to process 12 messages from /data/spool/block_change
api-node-0-recover_1 | 2019-10-29 03:49:56.266075 0x00007f7522a14480: <info> (recovery::RecoveryOrchestrator.cpp@138) loading state
api-node-0-recover_1 | 2019-10-29 03:49:56.266742 0x00007f7522a14480: <warning> (utils::StackLogger.h@35) pushing scope 'load state'
api-node-0-recover_1 | 2019-10-29 03:49:56.267410 0x00007f7522a14480: <debug> (cache::SupplementalDataStorage.cpp@31) read last recalculation height 112749 dynamic fee multiplier 10000 total transactions 9234 (score = [0, 2576772370251271596], height = 112785)
api-node-0-recover_1 | 2019-10-29 03:49:56.286149 0x00007f7522a14480: <warning> (utils::StackLogger.h@41) popping scope 'load state' (19ms)
api-node-0-recover_1 | 2019-10-29 03:49:56.286687 0x00007f7522a14480: <info> (recovery::RecoveryOrchestrator.cpp@146) loaded block chain (height = 112785, score = 2576772370251271596)
api-node-0-recover_1 | 2019-10-29 03:49:56.287157 0x00007f7522a14480: <info> (recovery::RecoveryOrchestrator.cpp@148) repairing state
api-node-0-recover_1 | 2019-10-29 03:49:56.287654 0x00007f7522a14480: <debug> (subscribers::BrokerMessageReaders.h@89) preparing to process 18 messages from /data/spool/state_change
api-node-0-recover_1 | 2019-10-29 03:49:56.299294 0x00007f7522a14480: <debug> (recovery::RecoveryOrchestrator.cpp@200) - purging state.tmp
api-node-0-recover_1 | 2019-10-29 03:49:56.299835 0x00007f7522a14480: <info> (recovery::RecoveryOrchestrator.cpp@151) finalizing
api-node-0-recover_1 | 2019-10-29 03:49:56.300367 0x00007f7522a14480: <info> (utils::StackLogger.h@41) popping scope 'running recovery operations' (59ms)
api-node-0-recover_1 | 2019-10-29 03:49:56.300822 0x00007f7522a14480: <info> (process::ProcessMain.cpp@86) shutting down process
api-node-0-recover_1 | 2019-10-29 03:49:56.301271 0x00007f7522a14480: <info> (utils::StackLogger.h@35) pushing scope 'shutting down recovery orchestrator'
api-node-0-recover_1 | 2019-10-29 03:49:56.301717 0x00007f7522a14480: <info> (thread::MultiServicePool.h@161) shutting down bulk writer (isolated pool)
api-node-0-recover_1 | 2019-10-29 03:49:56.302160 0x00007f7522a14480: <debug> (thread::IoThreadPool.cpp@111) waiting for 4 thread pool threads to exit (bulk writer)
api-node-0-recover_1 | 2019-10-29 03:49:56.302812 0x00007f7522a14480: <info> (thread::IoThreadPool.cpp@113) all thread pool threads exited (bulk writer)
api-node-0-recover_1 | 2019-10-29 03:49:56.303325 0x00007f7522a14480: <debug> (thread::IoThreadPool.cpp@111) waiting for 1 thread pool threads to exit (recovery)
api-node-0-recover_1 | 2019-10-29 03:49:56.303831 0x00007f7522a14480: <info> (thread::IoThreadPool.cpp@113) all thread pool threads exited (recovery)
api-node-0-recover_1 | 2019-10-29 03:49:56.304652 0x00007f7522a14480: <debug> (cache::SupplementalDataStorage.cpp@31) wrote last recalculation height 112749 dynamic fee multiplier 10000 total transactions 9234 (score = [0, 2576772370251271596], height = 112785)
api-node-0-recover_1 | 2019-10-29 03:49:56.305310 0x00007f7522a14480: <info> (utils::StackLogger.h@41) popping scope 'shutting down recovery orchestrator' (4ms)
APIノードを起動します。
$ docker-compose start api-node-broker-0
$ docker-compose start api-node-0
これでたぶん元通りになるかもしれません。
おわりに
リカバリーノードを動かして、データを正常に戻すことをやりました。
ブローカーノードなどが異常終了した後、broker.lockを手動削除して再開しようとしたがうまくいかなかったような状態の後でも、ちゃんとリカバリーノードがうまく動作するのかはわかりません。
異常終了した際はとりあえず、APIノードを止めてDBを起動して、リカバリーノードを試してみるのがよさそうだと思いました。
それでもダメな場合は、APIノードとDBのデータを削除して、再同期するのがよいと思います。
追記
2019/11/14
リカバリーノードでも対処できませんでした。
$ docker-compose ps
Name Command State Ports
------------------------------------------------------------------------------------------------------
fushicho_api-node-0_1 bash -c /bin-mount/wait /s ... Up 0.0.0.0:7610->7610/tcp
fushicho_api-node-broker-0_1 bash -c /bin-mount/wait /s ... Exit 139
fushicho_db-0_1 docker-entrypoint.sh bash ... Exit 14
fushicho_db-1_1 docker-entrypoint.sh bash ... Up 0.0.0.0:27618->27017/tcp
fushicho_db-2_1 docker-entrypoint.sh bash ... Up 0.0.0.0:27619->27017/tcp
fushicho_init-db-m_1 docker-entrypoint.sh bash ... Exit 1
上記の状態からapi-node-0を止めて、db-0を開始させ、api-node-0-recoverを起動しましたが、以下のようになりました。
api-node-0-recover_1 | !!!! Have lock file present, going to run recovery....
api-node-0-recover_1 | Copyright (c) Jaguar0625, gimre, BloodyRookie, Tech Bureau, Corp.
api-node-0-recover_1 | catapult version: 0.8.0.3 (public)
api-node-0-recover_1 | loading resources from "/userconfig/resources"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-inflation.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-extensions-recovery.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-user.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-logging-recovery.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-node.properties"
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-network.properties"
api-node-0-recover_1 | 2019-11-14 14:18:54.672899 0x00007f111b1f5480: <info> (process::ProcessMain.cpp@80) booting process with public key 63A2094799D5B4F1DAAE34C707DE1E6F18C8CDD955A95266B7126A5B041DF536
api-node-0-recover_1 | 2019-11-14 14:18:54.678985 0x00007f111b1f5480: <info> (thread::IoThreadPool.cpp@104) spawned 1 workers (recovery)
api-node-0-recover_1 | 2019-11-14 14:18:54.680403 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libextension.addressextraction.so
api-node-0-recover_1 | 2019-11-14 14:18:54.685849 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libextension.addressextraction.so loaded as 0x55de117a3790
api-node-0-recover_1 | 2019-11-14 14:18:54.686320 0x00007f111b1f5480: <info> (extensions::ProcessBootstrapper.cpp@102) registering dynamic extension extension.addressextraction
api-node-0-recover_1 | 2019-11-14 14:18:54.690588 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libextension.mongo.so
api-node-0-recover_1 | 2019-11-14 14:18:54.712592 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libextension.mongo.so loaded as 0x55de117b05a0
api-node-0-recover_1 | 2019-11-14 14:18:54.713394 0x00007f111b1f5480: <info> (extensions::ProcessBootstrapper.cpp@102) registering dynamic extension extension.mongo
api-node-0-recover_1 | loading configuration from "/userconfig/resources/config-database.properties"
api-node-0-recover_1 | 2019-11-14 14:18:54.735039 0x00007f111b1f5480: <info> (thread::IoThreadPool.cpp@104) spawned 4 workers (bulk writer)
api-node-0-recover_1 | 2019-11-14 14:18:54.736940 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.restrictionmosaic.so
api-node-0-recover_1 | 2019-11-14 14:18:54.740697 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.restrictionmosaic.so loaded as 0x55de117bf450
api-node-0-recover_1 | 2019-11-14 14:18:54.740717 0x00007f111b1f5480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.restrictionmosaic
api-node-0-recover_1 | 2019-11-14 14:18:54.741672 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.restrictionaccount.so
api-node-0-recover_1 | 2019-11-14 14:18:54.744999 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.restrictionaccount.so loaded as 0x55de117c2fb0
api-node-0-recover_1 | 2019-11-14 14:18:54.745019 0x00007f111b1f5480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.restrictionaccount
api-node-0-recover_1 | 2019-11-14 14:18:54.745921 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.multisig.so
api-node-0-recover_1 | 2019-11-14 14:18:54.749454 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.multisig.so loaded as 0x55de117c6d70
api-node-0-recover_1 | 2019-11-14 14:18:54.749927 0x00007f111b1f5480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.multisig
api-node-0-recover_1 | 2019-11-14 14:18:54.750402 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.mosaic.so
api-node-0-recover_1 | 2019-11-14 14:18:54.754070 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.mosaic.so loaded as 0x55de117c9ed0
api-node-0-recover_1 | 2019-11-14 14:18:54.754593 0x00007f111b1f5480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.mosaic
api-node-0-recover_1 | 2019-11-14 14:18:54.755125 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.metadata.so
api-node-0-recover_1 | 2019-11-14 14:18:54.758871 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.metadata.so loaded as 0x55de117cce50
api-node-0-recover_1 | 2019-11-14 14:18:54.759341 0x00007f111b1f5480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.metadata
api-node-0-recover_1 | 2019-11-14 14:18:54.759899 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.locksecret.so
api-node-0-recover_1 | 2019-11-14 14:18:54.763704 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.locksecret.so loaded as 0x55de117d0400
api-node-0-recover_1 | 2019-11-14 14:18:54.764224 0x00007f111b1f5480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.locksecret
api-node-0-recover_1 | 2019-11-14 14:18:54.764725 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.lockhash.so
api-node-0-recover_1 | 2019-11-14 14:18:54.769581 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.lockhash.so loaded as 0x55de117d3550
api-node-0-recover_1 | 2019-11-14 14:18:54.770055 0x00007f111b1f5480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.lockhash
api-node-0-recover_1 | 2019-11-14 14:18:54.771451 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.aggregate.so
api-node-0-recover_1 | 2019-11-14 14:18:54.775063 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.aggregate.so loaded as 0x55de117d64b0
api-node-0-recover_1 | 2019-11-14 14:18:54.775605 0x00007f111b1f5480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.aggregate
api-node-0-recover_1 | 2019-11-14 14:18:54.776042 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.transfer.so
api-node-0-recover_1 | 2019-11-14 14:18:54.779412 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.transfer.so loaded as 0x55de117d7070
api-node-0-recover_1 | 2019-11-14 14:18:54.779871 0x00007f111b1f5480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.transfer
api-node-0-recover_1 | 2019-11-14 14:18:54.780306 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.namespace.so
api-node-0-recover_1 | 2019-11-14 14:18:54.784089 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.namespace.so loaded as 0x55de117d77e0
api-node-0-recover_1 | 2019-11-14 14:18:54.784557 0x00007f111b1f5480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.namespace
api-node-0-recover_1 | 2019-11-14 14:18:54.785082 0x00007f111b1f5480: <info> (plugins::PluginModule.cpp@79) loading plugin from libcatapult.mongo.plugins.accountlink.so
api-node-0-recover_1 | 2019-11-14 14:18:54.788274 0x00007f111b1f5480: <debug> (plugins::PluginModule.cpp@92) plugin libcatapult.mongo.plugins.accountlink.so loaded as 0x55de117da690
api-node-0-recover_1 | 2019-11-14 14:18:54.788738 0x00007f111b1f5480: <info> (src::MongoPluginLoader.cpp@38) registering dynamic mongo plugin catapult.mongo.plugins.accountlink
api-node-0-recover_1 | 2019-11-14 14:18:54.789190 0x00007f111b1f5480: <debug> (src::ExternalCacheStorageBuilder.h@49) creating ExternalCacheStorage with 9 storages
api-node-0-recover_1 | 2019-11-14 14:18:54.793197 0x00007f111b1f5480: <error> (extensions::ProcessBootstrapper.cpp@93) Throwing exception: Throw location unknown (consider using BOOST_THROW_EXCEPTION)
api-node-0-recover_1 | Dynamic exception type: boost::exception_detail::clone_impl<boost::exception_detail::current_exception_std_exception_wrapper<std::runtime_error> >
api-node-0-recover_1 | std::exception::what: not master: generic server error
api-node-0-recover_1 | mongocxx::v_noabi::bulk_write_exception
api-node-0-recover_1 | 2019-11-14 14:18:54.794021 0x00007f111b1f5480: <fatal> (process::ProcessMain.cpp@65)
api-node-0-recover_1 | thread: Process Main (r
api-node-0-recover_1 | unhandled exception while running local node!
api-node-0-recover_1 | /catapult-src/src/catapult/extensions/ProcessBootstrapper.cpp(93): Throw in function void catapult::extensions::{anonymous}::LoadExtension(const catapult::plugins::PluginModule&, catapult::extensions::ProcessBootstrapper&)
api-node-0-recover_1 | Dynamic exception type: boost::wrapexcept<catapult::plugins::plugin_load_error>
api-node-0-recover_1 | std::exception::what: Throw location unknown (consider using BOOST_THROW_EXCEPTION)
api-node-0-recover_1 | Dynamic exception type: boost::exception_detail::clone_impl<boost::exception_detail::current_exception_std_exception_wrapper<std::runtime_error> >
api-node-0-recover_1 | std::exception::what: not master: generic server error
api-node-0-recover_1 | mongocxx::v_noabi::bulk_write_exception
api-node-0-recover_1 |
nf-fushicho_api-node-0-recover_1 exited with code 139
これ以上やりかたはわからないので、再同期しました。