search

stakwork / sphinx-key

Lightning hardware signer on ESP32
28 stars 1 forks source link

Unexpected increments of sequence #131

Closed irriden closed 9 months ago

irriden commented 10 months ago

To reproduce:

  1. Signer 1 does keysends with broker.
  2. While flying, connect signer 2, and it picks up the remaining keysends.
  3. Unplug signer 2.
  4. Broker switches back to 1, and triggers a restart of 1 due to gap in sequence.
  5. Broker pings signer 1 four times while signer 1 restarts, then switches back to pinging signer 2.
  6. When broker pings signer 1 again, sequence is off by 1, and signer 1 does another restart.
irriden commented 10 months ago

Actually sequence is not necessarily off by 1. Just now it was off by 3.

irriden commented 10 months ago

Need to post this log below, as the steps above don't reproduce the bug always, only some of the time. Here the sequence is off by 2.

It seems like if we are too slow with responding to CLN, it says adding HTLC 523 too slow: killing connection.

Maybe that's what causing the issue ? Not sure, see below:

[2023-09-22T04:32:16.746 hsmd  /sphinx_key_broker::looper INFO] loop 121730/32: got SignRemoteCommitmentTx(SignRemoteCommitmentTx { tx: WithSize(Transaction { version: 2, lock_time: PackedLockTime(200baba9), input: [TxIn { previous_output: OutPoint { txid: bc5116b38d2ed7a1d046240d00e9f39e919cd42ad73ba484fd6f86e3b98cbaf3, vout: 0 }, script_sig: Script(), sequence: Sequence(8029018f), witness: Witness { content: [], witness_elements: 0, last: 0, second_to_last: 0 } }], output: [TxOut { value: 26239f, script_pubkey: Script(OP_0 OP_PUSHBYTES_20 ba4392a311f2a6817f7cb4ae5c45cc98c64792a7) }, TxOut { value: 2626e9, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 a1a53bf4c233014caae01066d6f2d3b21da22507407897a05a695258d6b17628) }] }), psbt: WithSize(PartiallySignedTransaction { unsigned_tx: Transaction { version: 2, lock_time: PackedLockTime(200baba9), input: [TxIn { previous_output: OutPoint { txid: bc5116b38d2ed7a1d046240d00e9f39e919cd42ad73ba484fd6f86e3b98cbaf3, vout: 0 }, script_sig: Script(), sequence: Sequence(8029018f), witness: Witness { content: [], witness_elements: 0, last: 0, second_to_last: 0 } }], output: [TxOut { value: 26239f, script_pubkey: Script(OP_0 OP_PUSHBYTES_20 ba4392a311f2a6817f7cb4ae5c45cc98c64792a7) }, TxOut { value: 2626e9, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 a1a53bf4c233014caae01066d6f2d3b21da22507407897a05a695258d6b17628) }] }, version: 0, xpub: {}, proprietary: {}, unknown: {}, inputs: [Input { non_witness_utxo: None, witness_utxo: Some(TxOut { value: 4c4b40, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 50423d638e8f76a9a1328b2533220be57659e4e6af8dee5f0f27018f5ca42a36) }), partial_sigs: {}, sighash_type: None, redeem_script: None, witness_script: Some(Script(OP_PUSHNUM_2 OP_PUSHBYTES_33 032766f281aee2449a1f09f971be46402628b74978b6bfa80df950e26ec9137d2e OP_PUSHBYTES_33 039ab710de241f5337d7bafc96bd64a66a1648855e9a3720ad590221510d51d835 OP_PUSHNUM_2 OP_CHECKMULTISIG)), bip32_derivation: {PublicKey(2e7d13c96ee250f90da8bfb67849b728264046be71f9091f9a44e2ae81f26627579308bb99156a554565517d6a0ca479bcb5017eeee13aea43d3182c070b0034): (7990cac0, m/0), PublicKey(35d8510d51210259ad20379a5e8548166aa664bd96fcbad737531f24de10b79a07076810ba0dd878742430ac35d4e79cc85c23762b8c5f844eb55727c1cf0785): (2a5d7d6c, 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: None, bip32_derivation: {}, tap_internal_key: None, tap_tree: None, tap_key_origins: {}, proprietary: {}, unknown: {} }, Output { redeem_script: None, witness_script: Some(Script(OP_IF OP_PUSHBYTES_33 02508347b09eb3fc23e395a3a5c5668c5c4887e100a0d6a44408d237b92a5b14ca OP_ELSE OP_PUSHNUM_6 OP_CSV OP_DROP OP_PUSHBYTES_33 03d2c3c415d5608654311988f78ea930866bd44727315917db2e545bc08b884f79 OP_ENDIF OP_CHECKSIG)), bip32_derivation: {}, tap_internal_key: None, tap_tree: None, tap_key_origins: {}, proprietary: {}, unknown: {} }] }), remote_funding_key: 039ab710de241f5337d7bafc96bd64a66a1648855e9a3720ad590221510d51d835, remote_per_commitment_point: 03282691706e5b69ecf19d520f4cdf4c5174e172c33763fed44ed039c69ea87c8b, option_static_remotekey: true, commitment_number: 42d, htlcs: Array([]), feerate: fd })
[2023-09-22T04:32:16.746 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("6edb9d322098987132548aa64a1d78fb"), true
[2023-09-22T04:32:16.746 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:32:16.747 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:32:20.747 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:32:24.748 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:32:28.748 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:32:32.749 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T04:32:32.749 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T04:32:32.749 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6
[2023-09-22T04:32:32.845 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T04:32:32.845 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:32:32.845 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:32:36.846 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:32:40.346 hsmd  /rumqttd::server::broker ERROR] Disconnected!! error=Network(Io(Os { code: 104, kind: ConnectionReset, message: "Connection reset by peer" }))
[2023-09-22T04:32:40.846 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:32:44.847 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:32:44.914 hsmd  /rumqttd::server::broker ERROR] remote_link; tenant_id=None
2023-09-22T04:32:45.406Z UNUSUAL 0260452a05af8ba367e05032cca3622f47a1cd984658f89932e8ad5d7fab076595-channeld-chan#1: Adding HTLC 523 too slow: killing connection
2023-09-22T04:32:45.407Z INFO    0260452a05af8ba367e05032cca3622f47a1cd984658f89932e8ad5d7fab076595-chan#1: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (9)
[2023-09-22T04:32:45.426 hsmd  /sphinx_key_broker::looper INFO] loop 121730/30: got SignChannelUpdate(SignChannelUpdate { update: 0102184f66d2fd2546ae8ec3a426481e6722e5dde6abeda0d9bc629ab97cfda5866901ce2082827e6e21a15ae77a689a81dbe93a6422be612524c2ec0b85755d0e0e06226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f0000700000010000650d18ed010300060000000000000000000000010000000a00000001270b0180 })
[2023-09-22T04:32:45.427 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T04:32:45.427 hsmd  /sphinx_key_broker::looper INFO] loop 121730/3: got PreapproveKeysend(PreapproveKeysend { destination: 0260452a05af8ba367e05032cca3622f47a1cd984658f89932e8ad5d7fab076595, payment_hash: ba2e39e853e898fccd3ab214cdd8fa669c1d6bcd2bb650f19b34e89ffe1bf164, amount_msat: 3e8 })
[2023-09-22T04:32:45.427 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T04:32:46.642 hsmd  /sphinx_key_broker INFO] => connection status: 7a19c73d7f39d8c1b766fefa682c61b6: true
[2023-09-22T04:32:46.642 hsmd  /sphinx_key_broker::lss INFO] CLIENT 7a19c73d7f39d8c1b766fefa682c61b6 connected!
[2023-09-22T04:32:46.647 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic init-1-msg
[2023-09-22T04:32:47.235 hsmd  /sphinx_key_broker::looper INFO] loop 121730/29: got Ecdh(Ecdh { point: 02d118ed38caeb3b2b729bd34ff8f1c09ac6bd405e7cb18577c9a190c46f24519e })
[2023-09-22T04:32:47.236 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:47.236 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:47.332 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:47.332 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:47.428 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:47.428 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:47.525 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:47.525 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:47.548 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic init-2-msg
[2023-09-22T04:32:47.621 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:47.621 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:47.717 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:47.718 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:47.814 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:47.814 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:47.910 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:47.910 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:48.007 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:48.007 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:48.103 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:48.103 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:48.199 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:48.199 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:48.296 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:48.296 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:48.392 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:48.392 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:48.489 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:48.489 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:48.585 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:48.585 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:48.681 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:48.681 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:48.778 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), false
[2023-09-22T04:32:48.778 hsmd  /sphinx_key_broker::handle INFO] current client still syncing...
[2023-09-22T04:32:48.847 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T04:32:48.848 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T04:32:48.848 hsmd  /sphinx_key_broker::conn INFO] => client switched to 6edb9d322098987132548aa64a1d78fb
[2023-09-22T04:32:48.874 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("6edb9d322098987132548aa64a1d78fb"), true
[2023-09-22T04:32:48.888 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:32:48.889 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:32:48.944 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("6edb9d322098987132548aa64a1d78fb"), true
[2023-09-22T04:32:49.266 hsmd  /sphinx_key_broker INFO] adding client to the list? true
[2023-09-22T04:32:49.455 hsmd  /sphinx_key_broker::handle INFO] GOT ON vls-res
[2023-09-22T04:32:49.465 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:32:49.466 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:32:49.542 hsmd  /sphinx_key_broker::handle INFO] GOT ON vls-res
2023-09-22T04:32:49.542Z INFO    plugin-keysend: cmd 34 partid 0: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (Outgoing subdaemon died)
[2023-09-22T04:32:49.543 hsmd  /sphinx_key_broker::looper INFO] loop 121730/3: got PreapproveKeysend(PreapproveKeysend { destination: 0260452a05af8ba367e05032cca3622f47a1cd984658f89932e8ad5d7fab076595, payment_hash: ba2e39e853e898fccd3ab214cdd8fa669c1d6bcd2bb650f19b34e89ffe1bf164, amount_msat: 3e8 })
[2023-09-22T04:32:49.543 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T04:32:49.547 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:32:49.548 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:32:53.548 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:32:57.548 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:33:01.549 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:33:05.549 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T04:33:05.550 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T04:33:05.550 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6
[2023-09-22T04:33:05.581 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:33:05.581 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:33:05.646 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T04:33:09.581 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:33:13.582 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:33:17.582 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:33:21.583 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T04:33:21.583 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T04:33:21.583 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6
[2023-09-22T04:33:21.669 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:33:21.669 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:33:21.680 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T04:33:25.670 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:33:29.670 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
^C[2023-09-22T04:33:31.162 hsmd  /rocket::server WARN] Received SIGINT. Requesting shutdown.
[2023-09-22T04:33:31.162 hsmd  /sphinx_key_broker::looper ERROR] loop 121730/30: error Bitcoin
irriden commented 10 months ago

One more log, it doesn't look like the CLN complaint predicts to the sequence jump. It jumped by two here.

[2023-09-22T04:42:56.639 hsmd  /sphinx_key_broker::looper INFO] loop 140335/31: got SignRemoteCommitmentTx(SignRemoteCommitmentTx { tx: WithSize(Transaction { version: 2, lock_time: PackedLockTime(200babb2), input: [TxIn { previous_output: OutPoint { txid: bc5116b38d2ed7a1d046240d00e9f39e919cd42ad73ba484fd6f86e3b98cbaf3, vout: 0 }, script_sig: Script(), sequence: Sequence(8029018f), witness: Witness { content: [], witness_elements: 0, last: 0, second_to_last: 0 } }], output: [TxOut { value: 26239b, script_pubkey: Script(OP_0 OP_PUSHBYTES_20 ba4392a311f2a6817f7cb4ae5c45cc98c64792a7) }, TxOut { value: 2626ee, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 28c716f1e99a4631b44c753164cac2b024278773628b5c9eed1a0590deda4026) }] }), psbt: WithSize(PartiallySignedTransaction { unsigned_tx: Transaction { version: 2, lock_time: PackedLockTime(200babb2), input: [TxIn { previous_output: OutPoint { txid: bc5116b38d2ed7a1d046240d00e9f39e919cd42ad73ba484fd6f86e3b98cbaf3, vout: 0 }, script_sig: Script(), sequence: Sequence(8029018f), witness: Witness { content: [], witness_elements: 0, last: 0, second_to_last: 0 } }], output: [TxOut { value: 26239b, script_pubkey: Script(OP_0 OP_PUSHBYTES_20 ba4392a311f2a6817f7cb4ae5c45cc98c64792a7) }, TxOut { value: 2626ee, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 28c716f1e99a4631b44c753164cac2b024278773628b5c9eed1a0590deda4026) }] }, version: 0, xpub: {}, proprietary: {}, unknown: {}, inputs: [Input { non_witness_utxo: None, witness_utxo: Some(TxOut { value: 4c4b40, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 50423d638e8f76a9a1328b2533220be57659e4e6af8dee5f0f27018f5ca42a36) }), partial_sigs: {}, sighash_type: None, redeem_script: None, witness_script: Some(Script(OP_PUSHNUM_2 OP_PUSHBYTES_33 032766f281aee2449a1f09f971be46402628b74978b6bfa80df950e26ec9137d2e OP_PUSHBYTES_33 039ab710de241f5337d7bafc96bd64a66a1648855e9a3720ad590221510d51d835 OP_PUSHNUM_2 OP_CHECKMULTISIG)), bip32_derivation: {PublicKey(2e7d13c96ee250f90da8bfb67849b728264046be71f9091f9a44e2ae81f26627579308bb99156a554565517d6a0ca479bcb5017eeee13aea43d3182c070b0034): (7990cac0, m/0), PublicKey(35d8510d51210259ad20379a5e8548166aa664bd96fcbad737531f24de10b79a07076810ba0dd878742430ac35d4e79cc85c23762b8c5f844eb55727c1cf0785): (2a5d7d6c, 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: None, bip32_derivation: {}, tap_internal_key: None, tap_tree: None, tap_key_origins: {}, proprietary: {}, unknown: {} }, Output { redeem_script: None, witness_script: Some(Script(OP_IF OP_PUSHBYTES_33 02b2a90380832344cc0c9fe3e45481de76fa17aef626406644a24e65ee4edd5d4a OP_ELSE OP_PUSHNUM_6 OP_CSV OP_DROP OP_PUSHBYTES_33 0362f2139ee858194e7bedde90117a10554c6bdcadad4c4da4444d3ce8b9a47a1e OP_ENDIF OP_CHECKSIG)), bip32_derivation: {}, tap_internal_key: None, tap_tree: None, tap_key_origins: {}, proprietary: {}, unknown: {} }] }), remote_funding_key: 039ab710de241f5337d7bafc96bd64a66a1648855e9a3720ad590221510d51d835, remote_per_commitment_point: 025ccc28f64468d7d384cbf2917b539c61f88b4812482425de8d622070e710c8ad, option_static_remotekey: true, commitment_number: 436, htlcs: Array([]), feerate: fd })
[2023-09-22T04:42:56.639 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("6edb9d322098987132548aa64a1d78fb"), true
[2023-09-22T04:42:56.820 hsmd  /sphinx_key_broker::handle INFO] GOT ON vls-res
[2023-09-22T04:42:56.825 hsmd  /sphinx_key_broker::looper INFO] loop 140335/3: got PreapproveKeysend(PreapproveKeysend { destination: 0260452a05af8ba367e05032cca3622f47a1cd984658f89932e8ad5d7fab076595, payment_hash: cc049cffa7c8f44fdfcf64aba0b53592ed93e0b70febf0e784c17b3b09e36168, amount_msat: 3e8 })
[2023-09-22T04:42:56.826 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("6edb9d322098987132548aa64a1d78fb"), true
[2023-09-22T04:42:56.831 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:42:56.832 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:43:00.832 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:43:04.833 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:43:08.833 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:43:12.834 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T04:43:12.834 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T04:43:12.834 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6
[2023-09-22T04:43:12.887 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:43:12.888 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:43:12.930 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T04:43:16.888 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:43:20.889 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:43:24.889 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:43:28.890 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T04:43:28.890 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T04:43:28.890 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6
[2023-09-22T04:43:28.896 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:43:28.896 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:43:28.986 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T04:43:32.897 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:43:36.897 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:43:37.713 hsmd  /rumqttd::server::broker ERROR] Disconnected!! error=Network(Io(Os { code: 104, kind: ConnectionReset, message: "Connection reset by peer" }))
[2023-09-22T04:43:38.839 hsmd  /rumqttd::server::broker ERROR] remote_link; tenant_id=None
[2023-09-22T04:43:40.604 hsmd  /sphinx_key_broker INFO] => connection status: 7a19c73d7f39d8c1b766fefa682c61b6: true
[2023-09-22T04:43:40.605 hsmd  /sphinx_key_broker::lss INFO] CLIENT 7a19c73d7f39d8c1b766fefa682c61b6 connected!
[2023-09-22T04:43:40.609 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic init-1-msg
[2023-09-22T04:43:40.898 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:43:41.520 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic init-2-msg
[2023-09-22T04:43:43.249 hsmd  /sphinx_key_broker INFO] adding client to the list? true
[2023-09-22T04:43:44.898 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T04:43:44.898 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T04:43:44.899 hsmd  /sphinx_key_broker::conn INFO] => client switched to 6edb9d322098987132548aa64a1d78fb
[2023-09-22T04:43:44.949 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:43:44.949 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:43:44.995 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("6edb9d322098987132548aa64a1d78fb"), true
[2023-09-22T04:43:45.246 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Io("current client changed")
[2023-09-22T04:43:45.246 hsmd  /sphinx_key_broker::conn INFO] => client switched to 6edb9d322098987132548aa64a1d78fb
[2023-09-22T04:43:45.284 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:43:45.284 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:43:45.342 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("6edb9d322098987132548aa64a1d78fb"), true
[2023-09-22T04:43:49.284 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:43:53.285 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:43:57.285 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:44:01.286 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T04:44:01.286 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T04:44:01.286 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6
[2023-09-22T04:44:01.306 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:44:01.307 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:44:01.383 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T04:44:05.307 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:44:09.308 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:44:13.308 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T04:44:17.309 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T04:44:17.309 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T04:44:17.309 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6
[2023-09-22T04:44:17.349 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:44:17.349 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:44:17.405 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T04:44:21.350 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:44:25.350 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:44:29.350 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:44:33.351 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T04:44:33.351 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T04:44:33.351 hsmd  /sphinx_key_broker::conn INFO] => client switched to 6edb9d322098987132548aa64a1d78fb
[2023-09-22T04:44:33.365 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T04:44:33.365 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T04:44:33.447 hsmd  /sphinx_key_broker::conn WARN] current client and synced returns Some("6edb9d322098987132548aa64a1d78fb"), true
^C[2023-09-22T04:44:33.861 hsmd  /rocket::server WARN] Received SIGINT. Requesting shutdown.
[2023-09-22T04:44:33.861 hsmd  /sphinx_key_broker::looper ERROR] loop 140335/29: error Bitcoin
irriden commented 10 months ago

Ok here is the full story that causes this problem:

1. [loop a] Unplug signer 2 on `SignRemoteCommitmentTx` message send.
2. [loop a] Broker pings signer 2 four times.
3. [loop a] Broker switches to signer 1.
4. [loop a] Broker pings signer 1, and signer 1 initiates the restart on badsequence.
5. [loop a] Broker pings singer 1 four more times, but never gets a response.
6. [loop b] Broker receives `SignChannelUpdate`, creates a new loop for it that will ping signer 1 first.
7. [loop c] Broker receives `PreapproveKeysend`, creates a new loop that will ping signer 1 first.
8. Signer 1 reconnects.
9. [loop a] `SignRemoteCOmmitmentTx` loop switches to signer 2.
10. [loop b] now starts.
- Signer 1 finishes dance and gets added to the list.
- loop b receives response
12. [loop c] now starts, and receives response from signer 1.
13. [loop a] now starts, but pings signer 2, and doesn't get a response. Sequence is incremented.
14. [loop a] now pings signer 1, but is one step ahead so signer 1 restarts.
irriden commented 10 months ago

Full log below:

[2023-09-22T17:46:52.848 hsmd  /sphinx_key_broker::looper INFO] loop 39555/32: got SignRemoteCommitmentTx(SignRemoteCommitmentTx { tx: WithSize(Transaction { version: 2, lock_time: PackedLockTime(20dd5fd7), input: [TxIn { previous_output: OutPoint { txid: 461913bf15eac59d9eb419112ee220ee68b4572d03d8b1fb2feafe834b285c05, vout: 0 }, script_sig: Script(), sequence: Sequence(80afdd43), witness: Witness { content: [], witness_elements: 0, last: 0, second_to_last: 0 } }], output: [TxOut { value: 26252e, script_pubkey: Script(OP_0 OP_PUSHBYTES_20 ba4392a311f2a6817f7cb4ae5c45cc98c64792a7) }, TxOut { value: 26255a, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 efc45143fa1499fa4e08ffe746ae82b8ad0738424e590c9067bb6e76e0f914fb) }] }), psbt: WithSize(PartiallySignedTransaction { unsigned_tx: Transaction { version: 2, lock_time: PackedLockTime(20dd5fd7), input: [TxIn { previous_output: OutPoint { txid: 461913bf15eac59d9eb419112ee220ee68b4572d03d8b1fb2feafe834b285c05, vout: 0 }, script_sig: Script(), sequence: Sequence(80afdd43), witness: Witness { content: [], witness_elements: 0, last: 0, second_to_last: 0 } }], output: [TxOut { value: 26252e, script_pubkey: Script(OP_0 OP_PUSHBYTES_20 ba4392a311f2a6817f7cb4ae5c45cc98c64792a7) }, TxOut { value: 26255a, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 efc45143fa1499fa4e08ffe746ae82b8ad0738424e590c9067bb6e76e0f914fb) }] }, version: 0, xpub: {}, proprietary: {}, unknown: {}, inputs: [Input { non_witness_utxo: None, witness_utxo: Some(TxOut { value: 4c4b40, script_pubkey: Script(OP_0 OP_PUSHBYTES_32 ffcb76ca0927b350e3126ade5e33aa9fbfed14f7c7beb1da0a6b40cb80432e1b) }), partial_sigs: {}, sighash_type: None, redeem_script: None, witness_script: Some(Script(OP_PUSHNUM_2 OP_PUSHBYTES_33 02e64d9f29de4e79f5148aaf9a3d1b51a2e3362360204a53f6fe11519cb79f99d9 OP_PUSHBYTES_33 032766f281aee2449a1f09f971be46402628b74978b6bfa80df950e26ec9137d2e OP_PUSHNUM_2 OP_CHECKMULTISIG)), bip32_derivation: {PublicKey(d9999fb79c5111fef6534a20602336e3a2511b3d9aaf8a14f5794ede299f4de62672848799a65552ace49c5736e49cdf728d935c3dfb21e75fca9824a1be1acc): (0b89de05, m/0), PublicKey(2e7d13c96ee250f90da8bfb67849b728264046be71f9091f9a44e2ae81f26627579308bb99156a554565517d6a0ca479bcb5017eeee13aea43d3182c070b0034): (7990cac0, 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: None, bip32_derivation: {}, tap_internal_key: None, tap_tree: None, tap_key_origins: {}, proprietary: {}, unknown: {} }, Output { redeem_script: None, witness_script: Some(Script(OP_IF OP_PUSHBYTES_33 0345495fc709c29488f41134df581178085ff53c61a1b43e4535f3ade2b77bccf7 OP_ELSE OP_PUSHNUM_6 OP_CSV OP_DROP OP_PUSHBYTES_33 030a5a4c9d328893cf09eb9c3ee7085ef42593b6f154dea1874101a87d463ada29 OP_ENDIF OP_CHECKSIG)), bip32_derivation: {}, tap_internal_key: None, tap_tree: None, tap_key_origins: {}, proprietary: {}, unknown: {} }] }), remote_funding_key: 02e64d9f29de4e79f5148aaf9a3d1b51a2e3362360204a53f6fe11519cb79f99d9, remote_per_commitment_point: 02daf55e6389be272e706d07225a3eef0ba1eb4ff04a95f6ec0d508459b5fabd2a, option_static_remotekey: true, commitment_number: e7, htlcs: Array([]), feerate: fd })
[2023-09-22T17:46:52.848 hsmd  /sphinx_key_broker::looper INFO] CLIENT handle message
[2023-09-22T17:46:52.848 hsmd  /sphinx_key_broker::handle INFO] new loop!
[2023-09-22T17:46:52.849 hsmd  /sphinx_key_broker::handle INFO] got tuple: Some("6edb9d322098987132548aa64a1d78fb"), true
[2023-09-22T17:46:52.849 hsmd  /sphinx_key_broker::handle INFO] Starting handle_message_inner with ticket 517
[2023-09-22T17:46:52.849 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T17:46:52.849 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T17:46:56.849 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T17:47:00.849 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T17:47:04.850 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T17:47:08.850 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T17:47:08.850 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T17:47:08.850 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6
[2023-09-22T17:47:08.947 hsmd  /sphinx_key_broker::handle INFO] new loop!
[2023-09-22T17:47:08.947 hsmd  /sphinx_key_broker::handle INFO] got tuple: Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T17:47:08.947 hsmd  /sphinx_key_broker::handle INFO] Starting handle_message_inner with ticket 518
[2023-09-22T17:47:08.947 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T17:47:08.947 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T17:47:12.947 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T17:47:16.476 hsmd  /rumqttd::server::broker ERROR] Disconnected!! error=Network(Io(Os { code: 104, kind: ConnectionReset, message: "Connection reset by peer" }))
[2023-09-22T17:47:16.948 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T17:47:20.948 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T17:47:21.415 hsmd  /rumqttd::server::broker ERROR] remote_link; tenant_id=None
2023-09-22T17:47:22.185Z UNUSUAL 0260452a05af8ba367e05032cca3622f47a1cd984658f89932e8ad5d7fab076595-channeld-chan#1: Adding HTLC 114 too slow: killing connection
2023-09-22T17:47:22.185Z INFO    0260452a05af8ba367e05032cca3622f47a1cd984658f89932e8ad5d7fab076595-chan#1: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (9)
[2023-09-22T17:47:22.205 hsmd  /sphinx_key_broker::looper INFO] loop 39555/30: got SignChannelUpdate(SignChannelUpdate { update: 0102b5b27f291f8f2888c60297ccbabaef3a9616fa2421390c80d90bc92a9e31de7a68d2c795769ce47b39ccdf289754ae0a545aceaa0ad2eca471e99b3a54e88fc406226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f0000700000010000650dd32b010300060000000000000000000000010000000a00000001270b0180 })
[2023-09-22T17:47:22.205 hsmd  /sphinx_key_broker::looper INFO] CLIENT handle message
[2023-09-22T17:47:22.205 hsmd  /sphinx_key_broker::handle INFO] new loop!
[2023-09-22T17:47:22.205 hsmd  /sphinx_key_broker::handle INFO] got tuple: Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
2023-09-22T17:47:22.206Z INFO    plugin-keysend: cmd 34 partid 0: failed: WIRE_TEMPORARY_CHANNEL_FAILURE (Outgoing subdaemon died)
[2023-09-22T17:47:22.206 hsmd  /sphinx_key_broker::looper INFO] loop 39555/3: got PreapproveKeysend(PreapproveKeysend { destination: 0260452a05af8ba367e05032cca3622f47a1cd984658f89932e8ad5d7fab076595, payment_hash: a8ca988c6165f6c4820313b2c9538ec6b71944328dfd5d7b8f747b16f43edcaa, amount_msat: 3e8 })
[2023-09-22T17:47:22.206 hsmd  /sphinx_key_broker::looper INFO] MASTER handle message
[2023-09-22T17:47:22.206 hsmd  /sphinx_key_broker::handle INFO] new loop!
[2023-09-22T17:47:22.206 hsmd  /sphinx_key_broker::handle INFO] got tuple: Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T17:47:23.164 hsmd  /sphinx_key_broker INFO] => connection status: 7a19c73d7f39d8c1b766fefa682c61b6: true
[2023-09-22T17:47:23.164 hsmd  /sphinx_key_broker::lss INFO] CLIENT 7a19c73d7f39d8c1b766fefa682c61b6 connected!
[2023-09-22T17:47:23.169 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic init-1-msg
[2023-09-22T17:47:24.085 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic init-2-msg
[2023-09-22T17:47:24.948 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T17:47:24.949 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T17:47:24.949 hsmd  /sphinx_key_broker::conn INFO] => client switched to 6edb9d322098987132548aa64a1d78fb
[2023-09-22T17:47:24.994 hsmd  /sphinx_key_broker::handle INFO] Starting handle_message_inner with ticket 519
[2023-09-22T17:47:24.994 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T17:47:24.994 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T17:47:25.045 hsmd  /sphinx_key_broker::handle INFO] new loop!
[2023-09-22T17:47:25.045 hsmd  /sphinx_key_broker::handle INFO] got tuple: Some("6edb9d322098987132548aa64a1d78fb"), true
[2023-09-22T17:47:25.808 hsmd  /sphinx_key_broker INFO] adding client to the list? true
[2023-09-22T17:47:26.008 hsmd  /sphinx_key_broker::handle INFO] GOT ON vls-res
[2023-09-22T17:47:26.051 hsmd  /sphinx_key_broker::handle INFO] Starting handle_message_inner with ticket 520
[2023-09-22T17:47:26.052 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T17:47:26.052 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T17:47:26.132 hsmd  /sphinx_key_broker::handle INFO] GOT ON vls-res
[2023-09-22T17:47:26.133 hsmd  /sphinx_key_broker::looper INFO] loop 39555/3: got PreapproveKeysend(PreapproveKeysend { destination: 0260452a05af8ba367e05032cca3622f47a1cd984658f89932e8ad5d7fab076595, payment_hash: a8ca988c6165f6c4820313b2c9538ec6b71944328dfd5d7b8f747b16f43edcaa, amount_msat: 3e8 })
[2023-09-22T17:47:26.133 hsmd  /sphinx_key_broker::looper INFO] MASTER handle message
[2023-09-22T17:47:26.133 hsmd  /sphinx_key_broker::handle INFO] new loop!
[2023-09-22T17:47:26.133 hsmd  /sphinx_key_broker::handle INFO] got tuple: Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T17:47:26.199 hsmd  /sphinx_key_broker::handle INFO] Starting handle_message_inner with ticket 521
[2023-09-22T17:47:26.199 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T17:47:26.199 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T17:47:30.200 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T17:47:34.200 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T17:47:38.201 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 6edb9d322098987132548aa64a1d78fb on topic vls
[2023-09-22T17:47:42.201 hsmd  /sphinx_key_broker::handle WARN] no reply from signer...
[2023-09-22T17:47:42.201 hsmd  /sphinx_key_broker::handle WARN] error handle_message_inner, trying again... Eof
[2023-09-22T17:47:42.201 hsmd  /sphinx_key_broker::conn INFO] => client switched to 7a19c73d7f39d8c1b766fefa682c61b6
[2023-09-22T17:47:42.287 hsmd  /sphinx_key_broker::handle INFO] Starting handle_message_inner with ticket 522
[2023-09-22T17:47:42.287 hsmd  /sphinx_key_broker::handle INFO] SEND ON vls
[2023-09-22T17:47:42.287 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T17:47:42.298 hsmd  /sphinx_key_broker::handle INFO] new loop!
[2023-09-22T17:47:42.298 hsmd  /sphinx_key_broker::handle INFO] got tuple: Some("7a19c73d7f39d8c1b766fefa682c61b6"), true
[2023-09-22T17:47:46.288 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T17:47:50.288 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T17:47:51.273 hsmd  /rumqttd::server::broker ERROR] remote_link; tenant_id=None
[2023-09-22T17:47:51.278 hsmd  /rumqttd::server::broker ERROR] router-drop error=Recv(Disconnected)
[2023-09-22T17:47:53.045 hsmd  /sphinx_key_broker INFO] => connection status: 7a19c73d7f39d8c1b766fefa682c61b6: true
[2023-09-22T17:47:53.046 hsmd  /sphinx_key_broker::lss INFO] CLIENT 7a19c73d7f39d8c1b766fefa682c61b6 connected!
[2023-09-22T17:47:53.050 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic init-1-msg
[2023-09-22T17:47:53.949 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic init-2-msg
[2023-09-22T17:47:54.288 hsmd  /sphinx_key_broker::mqtt INFO] SENDING TO 7a19c73d7f39d8c1b766fefa682c61b6 on topic vls
[2023-09-22T17:47:55.724 hsmd  /sphinx_key_broker INFO] adding client to the list? true
^C[2023-09-22T17:47:56.970 hsmd  /rocket::server WARN] Received SIGINT. Requesting shutdown.
[2023-09-22T17:47:56.971 hsmd  /sphinx_key_broker::looper ERROR] loop 39555/29: error Bitcoin
[2023-09-22T17:47:56.971 hsmd  /sphinx_key_broker::looper ERROR] loop 39555/30: error Bitcoin
irriden commented 9 months ago

Closed in 80a23cb5f07bebc29e9bd0195423020f223a3a40

The solution is to let a thread switch between clients without having to retake a ticket after each switch.

Also important that a thread only reads the current client when it's their turn to handle_message.