Article:

CosmosのAppHash不整合をデバッグする

2023/12/11

はじめに

CosmosSDKはPoS(Proof of Stake)なブロックチェーンを簡単に作成できるフレームワークです。CosmosSDKを使うことで、独自の機能を含めた「アプリケーション専用チェーン」を簡単に作ることができます。

Proof of Stakeなチェーンであるため、提案されたブロックが間違ったものでないかをそれぞれのノードでチェックするわけですが、この不整合(コンセンサスエラー)はただ悪意のノードによるものではなく、プログラムのミスによっても簡単に引き起こされます。

例えば、「処理を行った時刻」をアプリケーションのデータに含めようと思ってコード内でtime.Time()を実行した場合、それぞれのノードのハードウェアの時計のズレやそもそもリクエストを受信する時刻がバラバラですから、計算結果に不整合があるものとして検出されてしまいます。

ほかにも乱数の生成や、例えばgo言語であればmapをforで処理した場合、そのkeyの順序は非決定的であるので、そういった場所でもコンセンサスエラーは容易に発生します。

コンセンサスエラーが発生したときその詳細が分かれば良いのですが、実際は ERR CONSENSUS FAILURE!!! err="+2/3 committed an invalid block: wrong Block.Header.AppHash. Expected AAAA..., got BBBB..." というログが落ちるだけで、どのモジュールのどの変数が、どういった値のズレを起こしているのかまでは分かりません。

そんな暗闇のような状況ではデバッグのしようがないので、これを何とか簡単にデバッグできるようにスクリプトを書いてみようというのが本記事のトピックです。(そして、その時追いかけたsdkのソースの個人的な備忘録でもあります)

ツールとしてまとめたものをGitHubに上げているので、今まさに困ってるよという方はぜひ使ってみてください。

モジュールの状態管理

CosmosSDKではブロックチェーンの様々な機能を「モジュール」という単位に分割して整理されています。公式でメンテされているモジュールとして、トークンを管理し送金等を管理するBankモジュールをはじめ、様々な基本機能がモジュールとして実装されています。これらのモジュールを組み合わせるだけでなく、それぞれをカスタマイズしたり、また新たに自分の必要な機能を実装したモジュールを作成して組み込むことができます。

それぞれのモジュールでは現在のブロックチェーンの状態をKVとして保存しています。

例えばignite(CosmosSDKを用いたブロックチェーンのボイラープレートをチョッパヤで生成してくれるツール)を用いて ignite scaffold list post title body で作成したpostのレポジトリ層のコードは次のようになっています。(一部の定数を展開して記載しています)

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19


func (k Keeper) AppendPost(
	ctx sdk.Context,
	post types.Post,
) uint64 {
	// Create the post
	count := k.GetPostCount(ctx)

	// Set the ID of the appended value
	post.Id = count

	store := prefix.NewStore(ctx.KVStore("blog"), types.KeyPrefix("Post/value/"))
	appendedValue := k.cdc.MustMarshal(&post)
	store.Set(GetPostIDBytes(post.Id), appendedValue)

	// Update post count
	k.SetPostCount(ctx, count+1)

	return count
}

このコードでは(11行目:)“blog"という名前のKVStoreを"Post/value/“というprefixでオープンし、そこに対して(13行目:)post.IDをキーにしてpostの内容を書き込んでいますね。

また、値は(12行目:)cdc.MustMarshalによってシリアライズされています。このcdc(codec)の方法にもいろいろ設定があるようですが、基本的にはprotobufエンコーディングのようです。

このブロックチェーンに対して、次のトランザクションを送ってみます。

1

blogd tx blog create-post 'Hello, World!' 'This is a blog post' --from alice --chain-id blog

最終的には次の値が書き込まれていました(この値を取得する方法をのちに解説します。)

1
2


key(hex): blog 506f73742f76616c75652f0000000000000000
value(hex): 120d48656c6c6f2c20576f726c64211a1354686973206973206120626c6f6720706f7374222d636f736d6f7331307471743573637333746d387436686b727368646a6464723561743932677138716730716d74

キーの506f73742f76616c75652fの部分はasciiで解釈できてデコードするとPost/value/に、そのあとの0の羅列はpostIDのバイナリ表現ですね。よって、意味的に解釈するとPost/value/0というキーでレコードが作成されているようです。

一方値のほうはprotobufによってエンコードされていますが、Protobuf Decoderなどのツールで無理やり解釈すると、

FieldNumber Type   Content
         string Hello,World!
         string This is a blog post
         string cosmos10tqt5scs3tm8t6hkrshdjddr5at92gq8qg0qmt
    

といったデータが書き込まれていることが分かります。

このように、CosmosSDKで用いるモジュールが取るステートは最終的にはすべてキーとバリューのペアで表現されています。つまり、ノード間でデータ整合性由来のコンセンサスエラーが発生するということは、このKVの組み合わせのどれかが異なっているということです。

つまり、あるノードがとっているKVと、整合性エラーを主張している別のノードのKVを全てダンプし、diffをとればどのモジュールのどの値でエラーが発生したのかを特定することができそうです。

Cosmosのデータ構造概要

Multistore and Keepersのドキュメントがよく解説してくれています。

抽象的な概要としては、CosmosSDKは全体の状態を「Multistore」という構造体に格納しており、またこのMultistoreは内部に複数のKVStoreを持つといった構造を取っているようです。

そして、これらが最終的にはLevelDB上のKVとして表現されています。なんだかややこしいですね。順を追って紐解いていきましょう。

DBをのぞき見してみる

ま、とりあえずDBの中身をばばーんとダンプして見てみましょう。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30


package main

import (
	"fmt"
	dbm "github.com/cometbft/cometbft-db"
)

func main() {
	dataDir := "/home/totegamma/.blog/data" // replace me

	// Open DB
	db, err := dbm.NewDB("application", dbm.GoLevelDBBackend, dataDir)
	if err != nil {
		panic(err)
	}
	defer db.Close()

	itr, err := db.Iterator(nil, nil)
	if err != nil {
		panic(err)
	}
	defer itr.Close()

	// 全てのkeyを表示
	for ; itr.Valid(); itr.Next() {
 		fmt.Println("---")
		fmt.Println(string(itr.Key()))
		fmt.Println("---")
	}
}

このコードを実行すると、このような結果が得られます。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22


---
s/k:blog/fPost/count/
---
---
s/k:blog/fPost/value/
---
---
s/k:blog/mstorage_version
---
---
s/k:blog/n-J­'àµT÷3GBê=XÖY.µËÄ	h9ë+<ª
---
---
s/k:blog/n/9LÐã'áz¦
cýèdj¦Ôâ	!¦ÈÙÖ
---
---
s/k:blog/ndp²c¬Md"	¡J_T	î"lóügk:Y¼
---
---
s/k:blog/nÂÚìïbáûUñ`ãi5ÇSÓPò¿:¾a
---

やはり謎にエンコードされていて、Post/value/のようなキーは得られませんね。実際にキーが何かしらのルールでエンコードされていることが目で見てわかりました。

次の章でこのエンコードされた値も読みたいのですが、その前に複雑な作業をしなくても読めて、後で使うデータをここで取得しておきます。それはMultiStoreが保持している、現在のブロックの高さと、特定ブロックに含まれるモジュールの情報の2つです。

それぞれの内容が次のキーでエンコードされています。(cosmos-sdk/store/rootmulti/store.go)

1
2
3
4


const (
	latestVersionKey = "s/latest"
	commitInfoKeyFmt = "s/%d" // s/<version>
)

現在のブロックの高さは次のコードで読み込めます。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13


// import gogotypes "github.com/cosmos/gogoproto/types"
bz, err := db.Get([]byte("s/latest"))
if err != nil {
    panic(err)
}

var latestHeight int64
err = gogotypes.StdInt64Unmarshal(&latestHeight, bz)
if err != nil {
    panic(err)
}

fmt.Println("latestHeight: ", latestHeight)

特定のブロックに含まれるモジュールの情報は次のコードで読み込めます。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11


// import storetypes "cosmossdk.io/store/types"
bz, err = db.Get([]byte(fmt.Sprintf("s/%d", latestHeight)))
if err != nil {
    panic(err)
}

cInfo := storetypes.CommitInfo{}
err = cInfo.Unmarshal(bz)
if err != nil {
    panic(err)
}

commitInfoには次のような情報が含まれています。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35


{
    "version": 118,
    "store_infos": [
        {
            "name": "acc",
            "commit_id": {
                "version": 118,
                "hash": "xyfMg6xU7nn8d4NrRAxULb675QGi3g+1W350MIgVu3c="
            }
        },
        {
            "name": "authz",
            "commit_id": {
                "version": 118,
                "hash": "47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU="
            }
        },
        {
            "name": "bank",
            "commit_id": {
                "version": 118,
                "hash": "aMjs5bPsqNmAVxQ/8Fd4ucgLScCuVKmpYfW3s6INWU8="
            }
        },
        {
            "name": "blog",
            "commit_id": {
                "version": 118,
                "hash": "LzkAFUzQBeMCJ+F6l6YNY5796GRqptTiCQwhpsgI2dY="
            }
        },
        ...省略...
    ],
    "timestamp": "2023-12-11T14:47:26.192661798Z"
}

IAVLとしてデータを解釈する

RootMultiが管理するKVStoreは様々なエンコード方法を選択できるようなのですが、デフォルトではIAVLという形式が採用されているようです。 IAVLはImmutable AVL木のことで、AVL木にバージョニングの機能を追加したもののようです。

CosmosSDKではこのAVL木のバージョニングの機能を使って、ブロックごとの状態を定義しているようです。

IAVLはドキュメントによると次のルールでキーがエンコードされます

1

n|node.nodeKey.version|node.nodeKey.nonce

が、これを解釈するコード1から書くのはめんどくさいのでライブラリをどんどん使ってデータを解釈しにいきます。基本的にはrootmulti/store.go のloadCommitStoreFromParamsをベースに書いていきます。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23


for _, module := range modules {
    targetInfo := infos[module]

    prefix := "s/k:" + module + "/"
    prefixDB := dbm.NewPrefixDB(db, []byte(prefix))

    var id storetypes.CommitID = targetInfo.CommitId // ここでCommitIdを指定することで特定のブロックの状態をロードする
    targetStore, err := iavl.LoadStore(prefixDB, nil, nil, id, false, 0, false)
    if err != nil {
        panic(err)
    }

    itr := targetStore.Iterator(nil, nil)
    for ; itr.Valid(); itr.Next() {
        if isASCII(itr.Key()) {
            fmt.Printf("key(ascii): %s %s\n", module, string(itr.Key()))
        } else {
            fmt.Printf("key(hex): %s %x\n", module, itr.Key())
        }
        fmt.Printf("value(hex): %x\n", itr.Value())
        fmt.Println()
    }
}

これを実行すると、次のようなダンプを得ることができます。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14


key(ascii): blog Post/count/
value(hex): 0000000000000001

key(hex): blog 506f73742f76616c75652f0000000000000000
value(hex): 120d48656c6c6f2c20576f726c64211a1354686973206973206120626c6f6720706f7374222d636f736d6f7331307471743573637333746d387436686b727368646a6464723561743932677138716730716d74

key(hex): capability 6361706162696c6974795f696e6465780000000000000001
value(hex): 0a150a03696263120e706f7274732f7472616e736665720a1a0a087472616e73666572120e706f7274732f7472616e73666572

key(hex): capability 6361706162696c6974795f696e6465780000000000000002
value(hex): 0a140a03696263120d706f7274732f696361686f73740a180a07696361686f7374120d706f7274732f696361686f7374

key(ascii): capability index
value(hex): 0000000000000003

見覚えがある形でデータを得ることができました！

実際にデバッグに活用する

こうして作ったスクリプトを簡易的なツールとして形にしたものがこちらになります。

go installをすれば、cosmosdumpというコマンドとして使えるようになります。

ローカルで2つノードを動作させて、途中でコンセンサスエラーが発生したとしましょう。それぞれのデータディレクトリがmy-chain1とmy-chain2にあるとします。それぞれで1回データをダンプしてみます。

1
2


$ cosmosdump ~/.my-chain1 > chain1.dump
$ cosmosdump ~/.my-chain2 > chain2.dump

ここでdiffを取ってみてもいいのですが、おそらくmy-chain1とmy-chain2で計算されているブロックの高さが違います(片方のノードはコンセンサスエラーで停止しする一方、もう片方のノードは走り続けるので)。そうすると、ブロック生成報酬などが追加で動くため、直接的なコンセンサスエラー以外のdiffが大量に出てしまいます。

なので、コンセンサスエラーが発生したブロックを特定しましょう。大抵は、低い方がそれです。

chain1.dumpとchain2.dumpのそれぞれの冒頭には次のログがあり、それぞれは違う数字になっていることかと思います。

chain1.dump

1
2

latestHeight:  118
targetHeight:  118

chain2.dump

1
2

latestHeight:  100
targetHeight:  100

この場合、chain2のほうが100と小さい数字になっているので、このブロックのデータを指定してもう一度ダンプしてみましょう。

1
2


$ cosmosdump ~/.my-chain1 100 > chain1.dump
$ cosmosdump ~/.my-chain2 100 > chain2.dump

これのdiffを取ると、次のような結果が得られます

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23


$ diff chain1.dump chain2.dump -c1
*** dump1       2023-12-02 09:41:05.773711981 +0900
--- dump2       2023-12-02 09:41:09.943511826 +0900
***************
*** 1,3 ****
! dir: /home/totegamma/.my-chain1
! latestVersion:  175
  targetHeight:  101
--- 1,3 ----
! dir: /home/totegamma/.my-chain2
! latestVersion:  101
  targetHeight:  101
***************
*** 262,264 ****
  key(ascii): mymodule MyModule/value/hoge/
! value(hex): AAAAAA

--- 262,264 ----
  key(ascii): mymodule MyModule/value/hoge/
! value(hex): BBBBBB

Exit status: 1
[totegamma@09:41]~/tmp$

この結果から、mymoduleにある、MyModule/value/hogeというキーのデータで齟齬が発生していることが分かります。また、ここの値を直接protobuf decoderに直接与えることで、具体的にどのような値になっているのかの精査を行うことができます。これで、デバッグがより効率的に行えます。