カタパルトのリカバリーノードを動かす

# はじめに

カタパルトにはリカバリーノードというのがあります。

何かのきっかけで、通常ノードが異常終了した際、そのままでは再開始はできません。
これを修復してくれるのがリカバリーノードです。

slackでチラホラ情報を見かけるようになったので、やってみました。

# やってみる

## 準備

まずは、APIノードとmongoDBとブローカーノードを起動した状況を作成します。

基本は、`catapult-service-bootstrap`を使います。

あと、プロジェクトのルートにこのようなファイルを置きます。

```yaml: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
```

これ以上やりかたはわからないので、再同期しました。