c-lightningの主キー制約とリストア

ライトニングネットワークの実装ソフトウェアの１つであるc-lightningのノード運用をこれまでしていたのですが、バージョンアップ（v0.8）を期にエラーがでるようになり、たまにプロセスが落ちるようになりました。

エラー内容は以下のようなSQLの主キー制約エラーなんですが、たぶんバージョンアップをする際に上手くDBが更新されなかったのかな？たちが悪いのがどのブロックのutxoを追加しようとしてるときにエラーとなっているのがわからないことです。

+245.990149661 lightningdBROKEN: Error executing statement: wallet/wallet.c:2923: INSERT INTO utxoset ( txid, outnum, blockheight, spendheight, txindex, scriptpubkey, satoshis) VALUES(?, ?, ?, ?, ?, ?, ?);: UNIQUE constraint failed: utxoset.txid, utxoset.outnum
+246.144652678 lightningdBROKEN: FATAL SIGNAL 6 (version v0.8.0)

Githubでそれっぽいイシューがないか調べてみたら、同じような主キー違反に関するイシューがありました。ただこのイシューではある特定のブロック高でエラーが発生していることなので、自分の現象とは少し違っていそうでした。

そこで、--rescan <blockheight>コマンドでc-lightningが持っているブロック情報をリスキャンしてみました。実際は以下のコマンドを実施。ブロック高を500,000にしているのはLNがローンチしたのがそれ以降だからです。※リスキャン前にすべてのチャネルを閉じて、どのピアとも接続していない状態にしてあります。

lightningd --rescan 500000

これでブロックを最初からリスキャンしだしたのですが、途中でプロセスが停止。お？？？と思いログを確認したら、以下のように特定ブロック高でエラーになっているのが分かりました。どうやらブロック高481824のあるutxoを保存しようとしてエラーとなっているみたいです。

+6.783965955 lightningdDEBUG: Adding block 481821: 0000000000000000007651ca005cf3c59f4e718cfde2a586268cc7dd13a71ac7
+6.992840665 lightningdDEBUG: Adding block 481822: 0000000000000000003bec88b7ba0bebd8eb3b1c1c599e44a2b270ad3e8203ca
+7.182897289 lightningdDEBUG: Adding block 481823: 000000000000000000cbeff0b533f8e1189cf09dfbebf57a8ebe349362811b80
+7.391582983 lightningdDEBUG: Adding block 481824: 0000000000000000001c8018d9cb3b742ef25114f27563e3fc4a1902167f9893
+7.392275350 lightningdBROKEN: Error executing statement: wallet/wallet.c:2885: INSERT INTO utxoset ( txid, outnum, blockheight, spendheight, txindex, scriptpubkey, satoshis) VALUES(?, ?, ?, ?, ?, ?, ?);: UNIQUE constraint failed: utxoset.txid, utxoset.outnum
+7.552624607 lightningdBROKEN: FATAL SIGNAL 6 (version v0.8.0)

これは先ほどみたイシューと同じ現象なので、それをを参考にc-lightningのchaintopology.cファイルを以下のように編集し、ログにどのトランザクションでエラーが発生しているか吐き出すようにしました。

static void topo_add_utxos(struct chain_topology *topo, struct block *b)
{
        for (size_t i = 0; i < tal_count(b->full_txs); i++) {
                const struct bitcoin_tx *tx = b->full_txs[i];
                for (size_t j = 0; j < tx->wtx->num_outputs; j++) {
                        if (tx->wtx->outputs[j].features & WALLY_TX_IS_COINBASE)
                                continue;

                        const u8 *script = bitcoin_tx_output_get_script(tmpctx, tx, j);
                        struct amount_asset amt = bitcoin_tx_output_get_amount(tx, j);

                        if (amount_asset_is_main(&amt) && is_p2wsh(script, NULL)) {
                            //以下の5行を追加した
                            log_debug(topo->log, "j: %u", j);
                            log_debug(topo->log, "height: %i", b->height);
                            log_debug(topo->log, "i: %u", i);
                            log_debug(topo->log, "script: %s", script);
                            //log_debug(topo->log, "amount: %s", amount_asset_to_sat(&amt));

                                wallet_utxoset_add(topo->ld->wallet, tx, j,
                                                   b->height, i, script,
                                                   amount_asset_to_sat(&amt));
                        }
                }
        }
}

実際に吐き出されたログは以下となります。481824:495:0のトランザクションを追加しようとしてエラーになっていることが分かりました。

+5.103369147 lightningdDEBUG: Adding block 481821: 0000000000000000007651ca005cf3c59f4e718cfde2a586268cc7dd13a71ac7
+5.284580110 lightningdDEBUG: Adding block 481822: 0000000000000000003bec88b7ba0bebd8eb3b1c1c599e44a2b270ad3e8203ca
+5.471972098 lightningdDEBUG: Adding block 481823: 000000000000000000cbeff0b533f8e1189cf09dfbebf57a8ebe349362811b80
+5.708419111 lightningdDEBUG: Adding block 481824: 0000000000000000001c8018d9cb3b742ef25114f27563e3fc4a1902167f9893
+5.708918349 lightningdDEBUG: j: 0
+5.708919879 lightningdDEBUG: height: 481824
+5.708920737 lightningdDEBUG: i: 495
+5.708921192 lightningdDEBUG: script: 
+5.709035755 lightningdBROKEN: Error executing statement: wallet/wallet.c:2885: INSERT INTO utxoset ( txid, outnum, blockheight, spendheight, txindex, scriptpubkey, satoshis) VALUES(?, ?, ?, ?, ?, ?, ?);: UNIQUE constraint failed: utxoset.txid, utxoset.outnum
+5.912366142 lightningdBROKEN: FATAL SIGNAL 6 (version v0.8.0-modded)

上記の内容をもとにlightningd.sqlite3のutxosetテーブルを検索すると、すでに対象のトランザクションが保存されていました。

>SELECT hex(txid), txindex, satoshis, outnum, blockheight, spendheight FROM utxoset where blockheight = 481824
>D67903B0BE8C6E046EFD98CDA56B11E706AAD75B502C60065CE7A0A04A8A1E46	495	500000	0	481824

これが原因で主キー違反となっていたのですが、そもそも既に保存されているんだから挿入しなければいいのでは？と思いつつも、コードを読み解く力もなく、思い切って対象のトランザクションを削除しました。

Delete from utxoset where blockheight = 481824;

その後、再度デーモンを起動したのですが、またプロセスが停止。ログを見ると、先ほどのブロック高以降でも同じエラーが発生。対象のトランザクション（ブロック）を削除しましたが、またあるブロック高でエラーに。こうなればもうブロック高481824以降のデータを全消しだ！実際はその時にエラーとなっていたブロック高以降を以下のようにして消しました。

Delete from utxoset where blockheight >= 483709;

デーモンを起動しなおすこと2日ほど経過し同期が完了しました。その後今までのような主キー違反によるプロセス終了がなくなったのでした。めでたしめでたし。

おまけ