カタパルトでReorg起こしてみる

はじめに

特に新しいことをやるわけではないのですが、Reorgを起こしてみるとどんな感じになるのかを見てみようと思いました。

カタパルトのマイルストーンはelephant 2のものを使います

シナリオ

1. Peerノードを2台稼働させて、どちらもハーベストする
2. 1台目のPeerノードを停止する
3. トランスファートランザクションを送信する
4. 2台目のPeerノードを停止し、1台目のPeerノードを開始する
5. Reorgするのを待つ
6. 2台目のPeerノードを開始する

Apiノードは1台稼働させる。特に止めたりはしない。

観察

Peerノードを2台稼働させて、どちらもハーベストする

まずは2台で稼働します。ハーベスターが2アカウントあるのがわかります。1台目が83396f~で、eb0e49~です。

こちらはトランスファートランザクションを送信するアカウント。残高は449,949,999.9あります。

1台目のPeerノードを停止する

ブロック番号19がハーベストされた後、1台目のPeerノードを停止します。

トランスファートランザクションを送信する

そして数ブロック後、適当なトランスファートランザクションを送信します。

ブロック番号24でハーベストされました。

アカウントのページを見てみます。残高は499,826,543.9に減りました。トランザクション履歴も表示されています。

2台目のPeerノードを停止し、1台目のPeerノードを開始する

ブロック番号26までハーベストされたところで、2台目のPeerノードを停止し、1台目のノードを開始します。

1台目のノードはブロック番号19までしか保有しておらず、かつ他にPeerノードがいないため、ブロック番号20からハーベストをします。

ブロックエクスプローラー上では、Reorgするまでは表示に変化はありませんでした。

Reorgするのを待つ

ブロック番号27がハーベストされました。これがその時のブロックエクスプローラーの状態です。

下から見ていくと、ブロック番号26まで順番に並んだ後、ブロック番号20から27が追加されているのがわかります。

ブロックエクスプローラーでは、初回のロードではREST APIを使ってデータを取得し、最新ブロックの更新はWebSocketを使って検知し、行を追加しています。

これにより、WebSocketでは、Reorgにより置き換わったブロックの情報が新たに送られてくるというのがわかりました。

リロードしてみます。

ブロック番号24でハーベストされたトランザクションがなくなっているのがわかります。

残高はどうなったでしょうか。トランザクション履歴がなくなり、残高も元に戻りました。

2台目のPeerノードを開始する

ブロック番号31がハーベストされた後、2台目のPeerノードを開始しました。

すると、ブロック番号32で、なくなったトランザクションが復活しました。

アカウントのページを見てみます。以前のトランザクションがブロック番号32になって表示されているのがわかります。

ログを見てみる

Apiブローカーノード

Reorgによる巻き戻しを検知して、ブロックとトランザクションを削除したり、トランザクションを未承認状態に戻しているのがわかります。

※Apiブローカーノードは、Apiノードが検知したチェーンの変更をもとに、mongoDBに書き込んだりZeroMQによる通知をしたりするノードです。

ブロック番号19のハーベスト
2019-09-22 11:02:54.468275 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:02:54.472675 preparing to process 2 messages from /data/spool/state_change
1台目のPeerノードを停止
ブロック番号20のハーベスト
2019-09-22 11:04:00.499080 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:04:00.506345 preparing to process 2 messages from /data/spool/state_change
ブロック番号21のハーベスト
2019-09-22 11:04:21.513880 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:04:21.518064 preparing to process 2 messages from /data/spool/state_change
ブロック番号22のハーベスト
2019-09-22 11:04:49.028040 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:04:49.032250 preparing to process 2 messages from /data/spool/state_change
トランスファートランザクションを送信する
2019-09-22 11:05:35.049595 preparing to process 1 messages from /data/spool/unconfirmed_transactions_change
ブロック番号23のハーベスト
2019-09-22 11:05:37.050251 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:05:37.055341 preparing to process 2 messages from /data/spool/state_change
ブロック番号24のハーベスト、トランザクションが承認された
2019-09-22 11:06:13.068257 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:06:13.075168 preparing to process 1 messages from /data/spool/unconfirmed_transactions_change
2019-09-22 11:06:13.078068 preparing to process 2 messages from /data/spool/state_change
ブロック番号25のハーベスト
2019-09-22 11:06:52.589877 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:06:52.594515 preparing to process 2 messages from /data/spool/state_change
ブロック番号26のハーベスト
2019-09-22 11:07:16.603614 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:07:16.608360 preparing to process 2 messages from /data/spool/state_change
2台目のPeerノードを停止し、1台目のPeerノードを開始する
5分間出力ログなし
ブロック番号27のハーベスト、Reorg発生
2019-09-22 11:13:03.253733 preparing to process 9 messages from /data/spool/block_change
2019-09-22 11:13:03.255198 deleted 7 blocks
2019-09-22 11:13:03.260238 deleted 1 transactions
2019-09-22 11:13:03.262747 deleted 7 transactionStatements
2019-09-22 11:13:03.265502 deleted 0 addressResolutionStatements
2019-09-22 11:13:03.267383 deleted 1 mosaicResolutionStatements
（推測）Reorgにより、トランザクションが未承認に戻された
2019-09-22 11:13:03.283715 preparing to process 1 messages from /data/spool/unconfirmed_transactions_change
2019-09-22 11:13:03.286471 preparing to process 2 messages from /data/spool/state_change
ブロック番号28のハーベスト
2019-09-22 11:13:30.793814 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:13:30.800600 preparing to process 2 messages from /data/spool/state_change
ブロック番号29のハーベスト
2019-09-22 11:13:46.306111 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:13:46.314320 preparing to process 2 messages from /data/spool/state_change
ブロック番号30のハーベスト
2019-09-22 11:14:22.823650 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:14:22.827927 preparing to process 2 messages from /data/spool/state_change
ブロック番号31のハーベスト
2019-09-22 11:14:31.831075 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:14:31.836028 preparing to process 2 messages from /data/spool/state_change
2台目のPeerノードを開始する
ブロック番号32のハーベスト、トランザクションが承認された
2019-09-22 11:15:01.860040 preparing to process 1 messages from /data/spool/block_change
2019-09-22 11:15:01.865319 preparing to process 1 messages from /data/spool/unconfirmed_transactions_change
2019-09-22 11:15:01.869059 preparing to process 2 messages from /data/spool/state_change

Apiノード

自身のノードで保持しているチェーンのスコアと、他のノードのスコアを比較して、より大きいスコアだった場合にそれを取り込んでいるのがわかります。

2台目のPeerノードを停止
2019-09-22 11:07:34.482370 error handler triggered for peer-node-1 @ peer-node-1:7900
1台目のPeerノードを開始する
2019-09-22 11:07:57.278509 connected to peer-node-0 [172.19.0.6:7900]
Apiノードはブロック番号26までを持っているが、1台目のPeerノードはそれよりブロック番号が小さいので受け入れない（正確にはブロックスコアで比較される）
2019-09-22 11:07:58.593400 comparing chain scores: 1445220744074647 (local) vs 1205571253402171 (remote)
2019-09-22 11:08:22.945386 comparing chain scores: 1445220744074647 (local) vs 1245292685247661 (remote)
2019-09-22 11:09:02.517447 comparing chain scores: 1445220744074647 (local) vs 1283028045501147 (remote)
2019-09-22 11:09:42.089403 comparing chain scores: 1445220744074647 (local) vs 1318876637741958 (remote)
2019-09-22 11:10:27.749438 comparing chain scores: 1445220744074647 (local) vs 1352932800370720 (remote)
2019-09-22 11:11:13.369425 comparing chain scores: 1445220744074647 (local) vs 1385286154868041 (remote)
2019-09-22 11:11:52.941435 comparing chain scores: 1445220744074647 (local) vs 1416021841640498 (remote)
2019-09-22 11:12:11.205431 comparing chain scores: 1445220744074647 (local) vs 1445220744074352 (remote)
1台目のPeerノードのブロックスコアの方が大きくなった
2019-09-22 11:13:02.953417 comparing chain scores: 1445220744074647 (local) vs 1472959701386478 (remote)
2019-09-22 11:13:03.041420 pulling blocks from remote with common height 19 (fork depth = 7)
2019-09-22 11:13:03.129428 peer returned 8 blocks (heights 20 - 27)
2019-09-22 11:13:03.129748 disruptor queuing element 24 (8 blocks (heights 20 - 27) [00000000] from Remote_Pull)
1ブロックずつロールバックしている
2019-09-22 11:13:03.158299 rolling back block at height 26
2019-09-22 11:13:03.158453 rolling back block at height 25
2019-09-22 11:13:03.158517 rolling back block at height 24
2019-09-22 11:13:03.158642 rolling back block at height 23
2019-09-22 11:13:03.158703 rolling back block at height 22
2019-09-22 11:13:03.158755 rolling back block at height 21
2019-09-22 11:13:03.158806 rolling back block at height 20
2019-09-22 11:13:03.158861 rolling back state hash to height 19

おわりに

Reorgによりトランザクションが一度はなくなったけど、その後しっかりと復活したのがわかった。

Reorgにより未承認になったトランザクションは、最後に2台目のPeerノードを起動したタイミングで承認された。ということは、Apiノードはその未承認トランザクションをPeerノードに伝えることはなかったということになる。

今回は7ブロック程度のReorgだったが、maxRollbackBlocksを超えたらフォークするはず。