CLN / VLS sync problem w/ RevokeCommitmentTx

This is related to #207 (closed).

Short summary:

1. CLN -> revoke commitment 4 -> VLS
2. both restarted before reply
3. CLN -> GetPerCommitmentPoint 6 -> VLS => cannot revoke commitment_number 4 when next_holder_commit_num is 5

This happened on the 2024-01-explicit-revoke-commitment-bis branch in CI: https://gitlab.com/lightning-signer/vls-hsmd/-/jobs/6057602998 in test_multichan

Log excerpt from vlsd-2:

[2024-01-30 23:01:25.113 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 500 dbid 1 - SignPenaltyToUs(SignPenaltyToUs { revocation_secret: e2f92f7c0820ceedf08ff6aa9d468ceccfb3d5dd9127f608577ec4b82cea4747, tx: WithSize(Transaction { version: 2, lock_time: PackedLockTime(0), input: [TxIn { previous_output: OutPoint { txid: c8795c3e8680e6c86f3efb2c13dd73aa1a158f9111eccd98dcd37be6b21f987f, vout: 2 }, script_sig: Script(), sequence: Sequence(4294967295), witness: Witness { content: [], witness_elements: 0, last: 0, second_to_last: 0 } }], output: [TxOut { value: 786165, script_pubkey: Script(OP_PUSHNUM_1 OP_PUSHBYTES_32 c423564d07f77208dc317df1536b3c24e635bb7b11c38a6f9690863ee371c9ff) }] }), psbt: WithSize(PartiallySignedTransaction { unsigned_tx: Transaction { version: 2, lock_time: PackedLockTime(0), input: [TxIn { previous_output: OutPoint { txid: c8795c3e8680e6c86f3efb2c13dd73aa1a158f9111eccd98dcd37be6b21f987f, vout: 2 }, script_sig: Script(), sequence: Sequence(4294967295), witness: Witness { content: [], witness_elements: 0, last: 0, second_to_last: 0 } }], output: [TxOut { value: 786165, script_pubkey: Script(OP_PUSHNUM_1 OP_PUSHBYTES_32 c423564d07f77208dc317df1536b3c24e635bb7b11c38a6f9690863ee371c9ff) }] }, version: 0, xpub: {}, proprietary: {}, unknown: {}, inputs: [Input { non_witness_utxo: None, witness_utxo: Some(TxOut { value: 790140, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 33267dad98a69f2784d9356fe29f27bfb9be8c6109eb530304ce71c024564d1d) }), partial_sigs: {}, sighash_type: None, redeem_script: None, witness_script: Some(Script(OP_IF OP_PUSHBYTES_33 0391d6a6bf38fa334a02181f266b32ff0041626de1340ef602f3ea8c6056e2c6cd OP_ELSE OP_PUSHNUM_5 OP_CSV OP_DROP OP_PUSHBYTES_33 0290a329074d5543f14623a2ebb685c6f4d3608708a96227c4a1a716d78ec943d6 OP_ENDIF OP_CHECKSIG)), bip32_derivation: {}, final_script_sig: None, final_script_witness: None, ripemd160_preimages: {}, sha256_preimages: {}, hash160_preimages: {}, hash256_preimages: {}, tap_key_sig: None, tap_script_sigs: {}, tap_scripts: {}, tap_key_origins: {}, tap_internal_key: None, tap_merkle_root: None, proprietary: {}, unknown: {} }], outputs: [Output { redeem_script: None, witness_script: None, bip32_derivation: {}, tap_internal_key: None, tap_tree: None, tap_key_origins: {XOnlyPublicKey(35e5aba02afc8e9fe85cf6bcaccf786674b37b404ebd881c67cd35d15ef2a8c8a4883d56d2c7ca26d7551e0e1cc49939fe7f2f88acf5a533de115af52a9561a6): ([], (d0eac62f, m/1))}, proprietary: {}, unknown: {} }] }), wscript: 63210391d6a6bf38fa334a02181f266b32ff0041626de1340ef602f3ea8c6056e2c6cd6755b275210290a329074d5543f14623a2ebb685c6f4d3608708a96227c4a1a716d78ec943d668ac })
[2024-01-30 23:01:25.117 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer sending reply[m[K 500 - (SignTxReply { signature: BitcoinSignature { signature: 20a10453fe4629f411d1bc6a9992f048d49ccaa3e171af92003ac6bc04fce1de6c673f6ccdfe18d8bb303003e006466e7359a2459ad51e5e7a80814e044c8832, sighash: 1 } }, [])
[2024-01-30 23:01:25.129 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 501 dbid 1 - ValidateCommitmentTx(ValidateCommitmentTx { tx: WithSize(Transaction { version: 2, lock_time: PackedLockTime(551097450), input: [TxIn { previous_output: OutPoint { txid: fdcdb290c48bff23ea94db856ad92da31ed104b6f4c7f04383e2b18b5f2bc600, vout: 0 }, script_sig: Script(), sequence: Sequence(2152511126), witness: Witness { content: [], witness_elements: 0, last: 0, second_to_last: 0 } }], output: [TxOut { value: 200000, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 9228dcd0f346ab5ea44a38ca7fa838e6ada8eceae8484c68b058b27904320fbb) }, TxOut { value: 792033, script_pubkey: Script(OP_0 OP_PUSHBYTES_20 2633ce82ee05910eb3f078416ce541b971b7e847) }] }), psbt: WithSize(PartiallySignedTransaction { unsigned_tx: Transaction { version: 2, lock_time: PackedLockTime(551097450), input: [TxIn { previous_output: OutPoint { txid: fdcdb290c48bff23ea94db856ad92da31ed104b6f4c7f04383e2b18b5f2bc600, vout: 0 }, script_sig: Script(), sequence: Sequence(2152511126), witness: Witness { content: [], witness_elements: 0, last: 0, second_to_last: 0 } }], output: [TxOut { value: 200000, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 9228dcd0f346ab5ea44a38ca7fa838e6ada8eceae8484c68b058b27904320fbb) }, TxOut { value: 792033, script_pubkey: Script(OP_0 OP_PUSHBYTES_20 2633ce82ee05910eb3f078416ce541b971b7e847) }] }, version: 0, xpub: {}, proprietary: {}, unknown: {}, inputs: [Input { non_witness_utxo: None, witness_utxo: Some(TxOut { value: 1000000, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 8698658a01efb001e1cc4df6a8b6f3adb461fa3e679385fdaae400bd73996b32) }), partial_sigs: {PublicKey { compressed: true, inner: PublicKey(7a7e6ddd0a1957c3bca54037032514c5d4d84a212f77fb50324c54b392ae95d5f8cb51984841af774383e7af3d729a1fbb69d0433a166648776b3c21e591b97d) }: EcdsaSig { sig: 304402205ca43d48c4979c3339639899fa2bd1c8b3b0daeeecf6daeebce2412b07f7d09402203e8a519fba48ec150a3e70691d50500f815f6e7a03d4faecc57888905576cc70, hash_ty: All }}, sighash_type: Some(PsbtSighashType { inner: 1 }), redeem_script: None, witness_script: Some(Script(OP_PUSHNUM_2 OP_PUSHBYTES_33 02d595ae92b3544c3250fb772f214ad8d4c51425033740a5bcc357190add6d7e7a OP_PUSHBYTES_33 02d6063d022691b2490ab454dee73a57c6ff5d308352b461ece69f3c284f2c2412 OP_PUSHNUM_2 OP_CHECKMULTISIG)), bip32_derivation: {PublicKey(7a7e6ddd0a1957c3bca54037032514c5d4d84a212f77fb50324c54b392ae95d5f8cb51984841af774383e7af3d729a1fbb69d0433a166648776b3c21e591b97d): (baa6fd21, m/0), PublicKey(12242c4f283c9fe6ec61b45283305dffc6573ae7de54b40a49b29126023d06d6aad1aeba72defeaa534d9b711dfc907a252bf811240556a59f3c20fa282bf1e3): (fdaf6c21, m/0)}, final_script_sig: None, final_script_witness: None, ripemd160_preimages: {}, sha256_preimages: {}, hash160_preimages: {}, hash256_preimages: {}, tap_key_sig: None, tap_script_sigs: {}, tap_scripts: {}, tap_key_origins: {}, tap_internal_key: None, tap_merkle_root: None, proprietary: {}, unknown: {} }], outputs: [Output { redeem_script: None, witness_script: Some(Script(OP_IF OP_PUSHBYTES_33 0262987fc7ad740e9eaad0c38206649b5c55147ed0fd0d19b82966f7cd02a5fd5c OP_ELSE OP_PUSHNUM_5 OP_CSV OP_DROP OP_PUSHBYTES_33 021475e89de7859757afe7ab43f8fc15ad1fc7dddd5ffe221b85b44415cf0679e0 OP_ENDIF OP_CHECKSIG)), bip32_derivation: {}, tap_internal_key: None, tap_tree: None, tap_key_origins: {}, proprietary: {}, unknown: {} }, Output { redeem_script: None, witness_script: None, bip32_derivation: {}, tap_internal_key: None, tap_tree: None, tap_key_origins: {}, proprietary: {}, unknown: {} }] }), htlcs: Array([]), commitment_number: 5, feerate: 11005, signature: BitcoinSignature { signature: 5ca43d48c4979c3339639899fa2bd1c8b3b0daeeecf6daeebce2412b07f7d0943e8a519fba48ec150a3e70691d50500f815f6e7a03d4faecc57888905576cc70, sighash: 1 }, htlc_signatures: Array([]) })
[2024-01-30 23:01:25.136 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer sending reply[m[K 501 - (ValidateCommitmentTxReply { old_commitment_secret: None, next_per_commitment_point: 023bf768f23d0faffa8b8eec9479afbd580c7e92529b775b03222fcd6d389a76b9 }, [])
[2024-01-30 23:01:25.162 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 502 dbid 1 - RevokeCommitmentTx(RevokeCommitmentTx { commitment_number: 4 })

[2024-01-30 23:01:25.420 [01;31m[Kvlsd2/vlsd2 INFO] vlsd2 git_desc[m[K=v0.11.0-rc.1-70-gc4ce3ddb starting
[2024-01-30 23:01:26.726 [01;31m[Kvlsd2/vls_proxy::util WARN] VLS_PERMISSIVE: ALL POLICY ERRORS ARE REPORTED AS WARN[m[KINGS
[2024-01-30 23:01:26.726 [01;31m[Kvlsd2/vls_proxy::util WARN[m[K] VLS_PERMISSIVE: ALL INVOICES, KEYSENDS, AND PAYMENTS AUTOMATICALLY APPROVED
[2024-01-30 23:01:26.766 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 0 dbid 0 - HsmdInit(HsmdInit { key_version: Bip32KeyVersion { pubkey_version: "0x43587cf", privkey_version: "0x4358394" }, chain_params: 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206, encryption_key: None, dev_privkey: None, dev_bip32_seed: None, dev_channel_secrets: None, dev_channel_secrets_shaseed: None, hsm_wire_min_version: 3, hsm_wire_max_version: 5 })
[2024-01-30 23:01:26.767 [01;31m[Kvlsd2/vls_protocol_signer::handler INFO] signer max_hsmd_protocol_version 5, node hsm_wire_max_version 5, setting hsmd_protocol_version to[m[K 5
[2024-01-30 23:01:26.767 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer sending reply[m[K 0 - (HsmdInitReplyV4 { hsm_version: 5, hsm_capabilities: ArrayBE([28, 142, 147, 149, 32, 34, 40]), node_id: 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d, bip32: 043587cf02e3a4318200000000e0b00f4c97853a105b54a36e8c6131d5ddb923d0f932eb5059e3555c637c6fd803697b839e8f19cc3dcf460b896a51d1c2ace86a0d21eb80c1bca3d4aa9bd4a474, bolt12: 0399d1513366c77c5d5cbd1e5db9eaf416543a3207b657dceece4a924dfd79b7b6 }, [])
[2024-01-30 23:01:26.768 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 1 dbid 0 - NodeInfo(NodeInfo)
[2024-01-30 23:01:26.768 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer sending reply[m[K 1 - (NodeInfoReply { network_name: "regtest", node_id: 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d, bip32: 043587cf02e3a4318200000000e0b00f4c97853a105b54a36e8c6131d5ddb923d0f932eb5059e3555c637c6fd803697b839e8f19cc3dcf460b896a51d1c2ace86a0d21eb80c1bca3d4aa9bd4a474 }, [])
[2024-01-30 23:01:26.770 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 2 dbid 0 - DeriveSecret(DeriveSecret { info: 626f6c7431322d696e766f6963652d62617365 })
[2024-01-30 23:01:26.771 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer sending reply[m[K 2 - (DeriveSecretReply { secret: ****** }, [])
[2024-01-30 23:01:26.774 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 3 dbid 0 - DeriveSecret(DeriveSecret { info: 636f6d6d616e646f })
[2024-01-30 23:01:26.774 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer sending reply[m[K 3 - (DeriveSecretReply { secret: ****** }, [])
[2024-01-30 23:01:27.058 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 6 dbid 0 - DeriveSecret(DeriveSecret { info: 626f6c7431322d696e766f6963652d62617365 })
[2024-01-30 23:01:27.058 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer sending reply[m[K 6 - (DeriveSecretReply { secret: ****** }, [])
[2024-01-30 23:01:27.063 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 7 dbid 0 - DeriveSecret(DeriveSecret { info: 73636220736563726574 })
[2024-01-30 23:01:27.063 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer sending reply[m[K 7 - (DeriveSecretReply { secret: ****** }, [])
[2024-01-30 23:01:27.090 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 8 dbid 0 - SignCommitmentTx(SignMutualCloseTx as a SignCommitmentTx { peer_id: 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59, dbid: 2, tx: WithSize(Transaction { version: 2, lock_time: PackedLockTime(0), input: [TxIn { previous_output: OutPoint { txid: 726e3452945326967f1ee3bd6eb5935cf0045af1b320f720b78e57f7a7594f2e, vout: 0 }, script_sig: Script(), sequence: Sequence(4294967295), witness: Witness { content: [], witness_elements: 0, last: 0, second_to_last: 0 } }], output: [TxOut { value: 100000, script_pubkey: Script(OP_PUSHNUM_1 OP_PUSHBYTES_32 a7583f0c421663b8ca76fa579018b40682ef8553d73fd061cd8f216ecdced6a3) }, TxOut { value: 898105, script_pubkey: Script(OP_PUSHNUM_1 OP_PUSHBYTES_32 9d68645892a57906f0a70ff7512301ae29263126d932676374b62282260396fb) }] }), psbt: WithSize(PartiallySignedTransaction { unsigned_tx: Transaction { version: 2, lock_time: PackedLockTime(0), input: [TxIn { previous_output: OutPoint { txid: 726e3452945326967f1ee3bd6eb5935cf0045af1b320f720b78e57f7a7594f2e, vout: 0 }, script_sig: Script(), sequence: Sequence(4294967295), witness: Witness { content: [], witness_elements: 0, last: 0, second_to_last: 0 } }], output: [TxOut { value: 100000, script_pubkey: Script(OP_PUSHNUM_1 OP_PUSHBYTES_32 a7583f0c421663b8ca76fa579018b40682ef8553d73fd061cd8f216ecdced6a3) }, TxOut { value: 898105, script_pubkey: Script(OP_PUSHNUM_1 OP_PUSHBYTES_32 9d68645892a57906f0a70ff7512301ae29263126d932676374b62282260396fb) }] }, version: 0, xpub: {}, proprietary: {}, unknown: {}, inputs: [Input { non_witness_utxo: None, witness_utxo: Some(TxOut { value: 1001000, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 78cce5f6f6e4d35db91b62bbd726a7e135cfe168ebb8c78ffcfbb450e2ef5a3c) }), partial_sigs: {}, sighash_type: None, redeem_script: None, witness_script: Some(Script(OP_PUSHNUM_2 OP_PUSHBYTES_33 03076e706f83f43656ddecd366f764a3dc0f9a8af33dfec947f4d70c074971f129 OP_PUSHBYTES_33 0369b5ce24c8f8a5c4a3b37c805a6a486fc286028e23dafe8f0d3efff555b6f4f6 OP_PUSHNUM_2 OP_CHECKMULTISIG)), bip32_derivation: {}, final_script_sig: None, final_script_witness: None, ripemd160_preimages: {}, sha256_preimages: {}, hash160_preimages: {}, hash256_preimages: {}, tap_key_sig: None, tap_script_sigs: {}, tap_scripts: {}, tap_key_origins: {}, tap_internal_key: None, tap_merkle_root: None, proprietary: {}, unknown: {} }], outputs: [Output { redeem_script: None, witness_script: None, bip32_derivation: {}, tap_internal_key: None, tap_tree: None, tap_key_origins: {XOnlyPublicKey(7db04b0574f64ff468879e556f61de9930714e3b8620f6d933384be866e15c2206d8234974c7344c31f14253979347716b8db83ab31e4fc61392759e9fb28dee): ([], (38c10854, m/2))}, proprietary: {}, unknown: {} }, Output { redeem_script: None, witness_script: None, bip32_derivation: {}, tap_internal_key: None, tap_tree: None, tap_key_origins: {}, proprietary: {}, unknown: {} }] }), remote_funding_key: 03076e706f83f43656ddecd366f764a3dc0f9a8af33dfec947f4d70c074971f129, commitment_number: 2 })
[2024-01-30 23:01:27.105 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer sending reply[m[K 8 - (SignCommitmentTxReply { signature: BitcoinSignature { signature: 77ae44bda92bd3f70bf0d6bb2a599178f6b6168ae30840da74cddfb90680640a7186d1841a8a71a53b839a5a1d743607d13371fce915aa78886f8b1ba9892761, sighash: 1 } }, [])
[2024-01-30 23:01:27.133 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 9 dbid 0 - CheckPubKey(CheckPubKey { index: 2, pubkey: 02225ce166e84b3833d9f620863b4e713099de616f559e8768f44ff674054bb07d })
[2024-01-30 23:01:27.133 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer sending reply[m[K 9 - (CheckPubKeyReply { ok: true }, [])
[2024-01-30 23:01:27.376 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 10 dbid 0 - Ecdh(Ecdh { point: 03cc6f4fbc698935ed199cc720910fa285d7175ac6c3f002810d681370930f5e1e })
[2024-01-30 23:01:27.377 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer sending reply[m[K 10 - (EcdhReply { secret: ****** }, [])
[2024-01-30 23:01:27.388 [01;31m[Kvlsd2/vls_proxy::grpc::signer INFO] signer got request[m[K 11 dbid 1 - GetPerCommitmentPoint(GetPerCommitmentPoint { commitment_number: 6 })
[2024-01-30 23:01:27.388 [01;31m[Kvlsd2/lightning_signer::policy WARN[m[K] policy failed: policy-revoke-new-commitment-signed get_per_commitment_secret: cannot revoke commitment_number 4 when next_holder_commit_num is 5

The blank line in the middle is where the restart happened ...