search

ElementsProject / lightning

Core Lightning — Lightning Network implementation focusing on spec compliance and performance
Other
2.85k stars 901 forks source link

Payment is pending rather than failing when channel is AWAITING_UNILATERAL #5844

Closed NicolasDorier closed 1 year ago

NicolasDorier commented 1 year ago

EDIT: After posting this, issue, I understood why channel get closed. I think it is understandable behavior and not a bug (we were mining block during a HTLC) What is not normal, is pay blocking rather than failing fast.

Version 22.11.1 dev.

On our regtest environment, sometimes lightningd is VERY flaky.

I have only two nodes, Alice and Bob and Alice wants to send money to Bob.

The channel is constructed, then after a while suddenly the channel get stuck in a AWAITING_UNILATERAL state. Worse: When we attempt to pay an invoice after this happen, the call to pay is blocking rather than returning an error code telling us there is no route.

Analyzing the logs I see two issue:

  1. ~The channel seems to drop for some reason, when it shouldn't.~ (See comment https://github.com/ElementsProject/lightning/issues/5844#issuecomment-1362631025)
  2. When that happen, pay get stuck in pending rather than failed.

Alice:

{
   "peers": [
      {
         "id": "02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc",
         "connected": true,
         "netaddr": [
            "172.18.0.7:46842"
         ],
         "features": "08a000080269a2",
         "channels": [
            {
               "state": "AWAITING_UNILATERAL",
               "scratch_txid": "b343c15a3176ff0c78b0e48de79d64b1821acd16573f5b44a8ccb74c544abc66",
               "last_tx_fee_msat": "184000msat",
               "feerate": {
                  "perkw": 253,
                  "perkb": 1012
               },
               "short_channel_id": "119x1x1",
               "direction": 1,
               "channel_id": "854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e88",
               "funding_txid": "894e2813a271c765768b520dc28df0820788ff1dd13c678a114cc11b06374c85",
               "funding_outnum": 1,
               "close_to_addr": "bcrt1qq6lw2phek57x2nj37x0mguwwmw2ha0nqfqjd3p",
               "close_to": "001406bee506f9b53c654e51f19fb471cedb957ebe60",
               "private": false,
               "opener": "local",
               "alias": {
                  "local": "14220752x4562818x18809",
                  "remote": "6152938x5427602x64081"
               },
               "features": [
                  "option_static_remotekey"
               ],
               "funding": {
                  "local_msat": "16777215000msat",
                  "remote_msat": "0msat",
                  "pushed_msat": "0msat",
                  "local_funds_msat": "16777215000msat",
                  "remote_funds_msat": "0msat"
               },
               "msatoshi_to_us": 16159811654,
               "to_us_msat": "16159811654msat",
               "msatoshi_to_us_min": 16159811654,
               "min_to_us_msat": "16159811654msat",
               "msatoshi_to_us_max": 16777215000,
               "max_to_us_msat": "16777215000msat",
               "msatoshi_total": 16777215000,
               "total_msat": "16777215000msat",
               "fee_base_msat": "1msat",
               "fee_proportional_millionths": 10,
               "dust_limit_satoshis": 546,
               "dust_limit_msat": "546000msat",
               "max_htlc_value_in_flight_msat": 18446744073709551615,
               "max_total_htlc_in_msat": "18446744073709551615msat",
               "their_channel_reserve_satoshis": 167772,
               "their_reserve_msat": "167772000msat",
               "our_channel_reserve_satoshis": 167772,
               "our_reserve_msat": "167772000msat",
               "spendable_msatoshi": 4294967295,
               "spendable_msat": "4294967295msat",
               "receivable_msatoshi": 449631346,
               "receivable_msat": "449631346msat",
               "htlc_minimum_msat": 0,
               "minimum_htlc_in_msat": "0msat",
               "minimum_htlc_out_msat": "0msat",
               "maximum_htlc_out_msat": "16609443000msat",
               "their_to_self_delay": 6,
               "our_to_self_delay": 6,
               "max_accepted_htlcs": 483,
               "state_changes": [
                  {
                     "timestamp": "2022-12-22T08:59:34.453Z",
                     "old_state": "CHANNELD_AWAITING_LOCKIN",
                     "new_state": "CHANNELD_NORMAL",
                     "cause": "user",
                     "message": "Lockin complete"
                  },
                  {
                     "timestamp": "2022-12-22T09:00:34.163Z",
                     "old_state": "CHANNELD_NORMAL",
                     "new_state": "AWAITING_UNILATERAL",
                     "cause": "protocol",
                     "message": "Offered HTLC 16 SENT_ADD_COMMIT cltv 214 hit deadline"
                  }
               ],
               "status": [
                  "CHANNELD_NORMAL:Channel ready for use. Channel announced."
               ],
               "in_payments_offered": 0,
               "in_msatoshi_offered": 0,
               "in_offered_msat": "0msat",
               "in_payments_fulfilled": 0,
               "in_msatoshi_fulfilled": 0,
               "in_fulfilled_msat": "0msat",
               "out_payments_offered": 17,
               "out_msatoshi_offered": 1234687291,
               "out_offered_msat": "1234687291msat",
               "out_payments_fulfilled": 12,
               "out_msatoshi_fulfilled": 617403346,
               "out_fulfilled_msat": "617403346msat",
               "htlcs": [
                  {
                     "direction": "out",
                     "id": 16,
                     "msatoshi": 123456789,
                     "amount_msat": "123456789msat",
                     "expiry": 214,
                     "payment_hash": "9c0d2cd728e117913e5f35c5484fd5bba871667fe224a3f65fbb7d563ef22657",
                     "state": "SENT_ADD_COMMIT"
                  }
               ]
            }
         ],
         "log": [
            {
               "type": "SKIPPED",
               "num_skipped": 1865
            },
            {
               "type": "UNUSUAL",
               "time": "123.463049715",
               "node_id": "02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc",
               "source": "chan#1",
               "log": "Peer permanent failure in CHANNELD_NORMAL: Offered HTLC 16 SENT_ADD_COMMIT cltv 214 hit deadline"
            },
            {
               "type": "SKIPPED",
               "num_skipped": 16
            }
         ]
      }
   ]
}

Bob:

{
   "peers": [
      {
         "id": "02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1",
         "connected": true,
         "netaddr": [
            "172.18.0.9:9735"
         ],
         "features": "08a000080269a2",
         "channels": [
            {
               "state": "AWAITING_UNILATERAL",
               "scratch_txid": "a0fe8c0fbfa4c01e14dc7d6a496bff33e02d0bae52fc29fca377b1e4cd6f3b9e",
               "last_tx_fee_msat": "228000msat",
               "feerate": {
                  "perkw": 253,
                  "perkb": 1012
               },
               "short_channel_id": "119x1x1",
               "direction": 0,
               "channel_id": "854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e88",
               "funding_txid": "894e2813a271c765768b520dc28df0820788ff1dd13c678a114cc11b06374c85",
               "funding_outnum": 1,
               "close_to_addr": "bcrt1q7w7dyf6c7akk52eq0qa9s2yxq3kfh7u3h5rq7u",
               "close_to": "0014f3bcd22758f76d6a2b20783a582886046c9bfb91",
               "private": false,
               "opener": "remote",
               "alias": {
                  "local": "6152938x5427602x64081",
                  "remote": "14220752x4562818x18809"
               },
               "features": [
                  "option_static_remotekey"
               ],
               "funding": {
                  "local_msat": "0msat",
                  "remote_msat": "16777215000msat",
                  "pushed_msat": "0msat",
                  "local_funds_msat": "0msat",
                  "remote_funds_msat": "16777215000msat"
               },
               "msatoshi_to_us": 617403346,
               "to_us_msat": "617403346msat",
               "msatoshi_to_us_min": 0,
               "min_to_us_msat": "0msat",
               "msatoshi_to_us_max": 617403346,
               "max_to_us_msat": "617403346msat",
               "msatoshi_total": 16777215000,
               "total_msat": "16777215000msat",
               "fee_base_msat": "1msat",
               "fee_proportional_millionths": 10,
               "dust_limit_satoshis": 546,
               "dust_limit_msat": "546000msat",
               "max_htlc_value_in_flight_msat": 18446744073709551615,
               "max_total_htlc_in_msat": "18446744073709551615msat",
               "their_channel_reserve_satoshis": 167772,
               "their_reserve_msat": "167772000msat",
               "our_channel_reserve_satoshis": 167772,
               "our_reserve_msat": "167772000msat",
               "spendable_msatoshi": 449631346,
               "spendable_msat": "449631346msat",
               "receivable_msatoshi": 4294967295,
               "receivable_msat": "4294967295msat",
               "htlc_minimum_msat": 0,
               "minimum_htlc_in_msat": "0msat",
               "minimum_htlc_out_msat": "0msat",
               "maximum_htlc_out_msat": "16609443000msat",
               "their_to_self_delay": 6,
               "our_to_self_delay": 6,
               "max_accepted_htlcs": 483,
               "state_changes": [
                  {
                     "timestamp": "2022-12-22T08:59:34.462Z",
                     "old_state": "CHANNELD_AWAITING_LOCKIN",
                     "new_state": "CHANNELD_NORMAL",
                     "cause": "remote",
                     "message": "Lockin complete"
                  },
                  {
                     "timestamp": "2022-12-22T09:00:34.391Z",
                     "old_state": "CHANNELD_NORMAL",
                     "new_state": "AWAITING_UNILATERAL",
                     "cause": "protocol",
                     "message": "channeld: received ERROR error channel 854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e88: Offered HTLC 16 SENT_ADD_COMMIT cltv 214 hit deadline"
                  }
               ],
               "status": [
                  "CHANNELD_NORMAL:Received error channel 854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e88: Offered HTLC 16 SENT_ADD_COMMIT cltv 214 hit deadline",
                  "CHANNELD_NORMAL:Will attempt reconnect in 1 seconds"
               ],
               "in_payments_offered": 17,
               "in_msatoshi_offered": 1234687291,
               "in_offered_msat": "1234687291msat",
               "in_payments_fulfilled": 12,
               "in_msatoshi_fulfilled": 617403346,
               "in_fulfilled_msat": "617403346msat",
               "out_payments_offered": 0,
               "out_msatoshi_offered": 0,
               "out_offered_msat": "0msat",
               "out_payments_fulfilled": 0,
               "out_msatoshi_fulfilled": 0,
               "out_fulfilled_msat": "0msat",
               "htlcs": [
                  {
                     "direction": "in",
                     "id": 16,
                     "msatoshi": 123456789,
                     "amount_msat": "123456789msat",
                     "expiry": 214,
                     "payment_hash": "9c0d2cd728e117913e5f35c5484fd5bba871667fe224a3f65fbb7d563ef22657",
                     "state": "SENT_ADD_ACK_COMMIT"
                  }
               ]
            }
         ]
      }
   ]
}

Config Alice

bitcoin-datadir=/etc/bitcoin
bitcoin-rpcconnect=bitcoind
network=regtest
announce-addr=lightningd:9735
log-level=debug
dev-fast-gossip
dev-bitcoind-poll=1
database-upgrade=true

bind-addr=0.0.0.0:9735
network=regtest
rpc-file=/root/.lightning/lightning-rpc

Config Bob

bitcoin-datadir=/etc/bitcoin
bitcoin-rpcconnect=bitcoind
network=regtest
announce-addr=lightningd_dest:9735
log-level=debug
dev-fast-gossip
dev-bitcoind-poll=1
database-upgrade=true

bind-addr=0.0.0.0:9735
network=regtest
rpc-file=/root/.lightning/lightning-rpc

Stuck payment

      {
         "id": 17,
         "payment_hash": "9c0d2cd728e117913e5f35c5484fd5bba871667fe224a3f65fbb7d563ef22657",
         "groupid": 1,
         "destination": "02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc",
         "msatoshi": 123456789,
         "amount_msat": "123456789msat",
         "msatoshi_sent": 123456789,
         "amount_sent_msat": "123456789msat",
         "created_at": 1671699633,
         "status": "pending",
         "bolt11": "lnbcrt1234567890p1p36g893sp5eyalzunlqggjy3pudj97574n07027w06cwmpv2gnzjuu2kdltvrspp5nsxje4eguytez0jlxhz5sn74hw58zenlugj28ajlhd74v0hjyetsdpdg4h8xatjv4pk7mnwv43hgety23h5getnw35kuct5d9hkuxqryugcqp29qyysgq8hcp2ptf269w2l2gp7te2npzlhdhsazrp98qutu38nmfuuk2tqxjxm2sl4446gf2nkqps7jgmym8g7nhk3ln5ged94efpn075wz5lpqqmd7yhm"
      }

Alice when the payment seems to get stuck

2022-12-22T09:00:32.100Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-22T09:00:33.121Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-22T09:00:33.121Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-22T09:00:33.122Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-22T09:00:33.122Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253
2022-12-22T09:00:33.122Z DEBUG   lightningd: ... feerate estimate for htlc_resolution hit floor 253
2022-12-22T09:00:33.122Z DEBUG   lightningd: ... feerate estimate for penalty hit floor 253
2022-12-22T09:00:33.122Z DEBUG   lightningd: ... polled feerate estimate for min_acceptable (125) smoothed to 250 (alpha=0.02)
2022-12-22T09:00:33.122Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-22T09:00:33.492Z DEBUG   lightningd: routehint: {"jsonrpc":"2.0","id":"0/cln:listincoming#708","result":{"incoming":[{"id":"02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc","short_channel_id":"119x1x1","fee_base_msat":"1msat","htlc_min_msat":"0msat","htlc_max_msat":"16609443840msat","fee_proportional_millionths":10,"cltv_expiry_delta":6,"incoming_capacity_msat":"0msat","public":true,"peer_features":"88a000080269a2"}]}}
2022-12-22T09:00:33.492Z DEBUG   lightningd: 119x1x1: deadend
2022-12-22T09:00:33.492Z DEBUG   lightningd: needed = 10000msat, avail_capacity = 0msat, private_capacity = 0msat, offline_capacity = 0msat, deadend_capacity = 449631346msat
2022-12-22T09:00:33.501Z DEBUG   hsmd: Client: Received message 8 from client
2022-12-22T09:00:33.538Z DEBUG   lightningd: routehint: {"jsonrpc":"2.0","id":"14/cln:listincoming#709","result":{"incoming":[{"id":"02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc","short_channel_id":"119x1x1","fee_base_msat":"1msat","htlc_min_msat":"0msat","htlc_max_msat":"16609443840msat","fee_proportional_millionths":10,"cltv_expiry_delta":6,"incoming_capacity_msat":"0msat","public":true,"peer_features":"88a000080269a2"}]}}
2022-12-22T09:00:33.538Z DEBUG   lightningd: 119x1x1: deadend
2022-12-22T09:00:33.538Z DEBUG   lightningd: needed = 10000msat, avail_capacity = 0msat, private_capacity = 0msat, offline_capacity = 0msat, deadend_capacity = 449631346msat
2022-12-22T09:00:33.544Z DEBUG   hsmd: Client: Received message 8 from client
2022-12-22T09:00:33.565Z DEBUG   lightningd: routehint: {"jsonrpc":"2.0","id":"0/cln:listincoming#710","result":{"incoming":[{"id":"02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc","short_channel_id":"119x1x1","fee_base_msat":"1msat","htlc_min_msat":"0msat","htlc_max_msat":"16609443840msat","fee_proportional_millionths":10,"cltv_expiry_delta":6,"incoming_capacity_msat":"0msat","public":true,"peer_features":"88a000080269a2"}]}}
2022-12-22T09:00:33.565Z DEBUG   lightningd: 119x1x1: deadend
2022-12-22T09:00:33.565Z DEBUG   lightningd: needed = 10000msat, avail_capacity = 0msat, private_capacity = 0msat, offline_capacity = 0msat, deadend_capacity = 449631346msat
2022-12-22T09:00:33.570Z DEBUG   hsmd: Client: Received message 8 from client
2022-12-22T09:00:33.928Z DEBUG   plugin-pay: cmd 48 partid 0: Added a channel hint for 119x1x1/1: enabled true, estimated capacity 4294967295msat
2022-12-22T09:00:33.929Z DEBUG   plugin-pay: cmd 48 partid 0: Found a direct channel (119x1x1/1) with sufficient capacity, skipping route computation.
2022-12-22T09:00:33.929Z DEBUG   plugin-pay: cmd 48 partid 0: Created outgoing onion for route: 119x1x1
2022-12-22T09:00:33.930Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: NEW:: HTLC LOCAL 16 = SENT_ADD_HTLC/RCVD_ADD_HTLC
2022-12-22T09:00:33.930Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: Adding HTLC 16 amount=123456789msat cltv=214 gave CHANNEL_ERR_ADD_OK
2022-12-22T09:00:33.930Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: peer_out WIRE_UPDATE_ADD_HTLC
2022-12-22T09:00:33.930Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: REPLY WIRE_CHANNELD_OFFER_HTLC_REPLY with 0 fds
2022-12-22T09:00:33.936Z DEBUG   lightningd: Adding block 204: 07bdac43c191502548f9d5a9eb7b18c9c7d49dba8dcf48662bb5f6230d980a89
2022-12-22T09:00:33.952Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2022-12-22T09:00:33.953Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: Trying commit
2022-12-22T09:00:33.953Z DEBUG   hsmd: Client: Received message 19 from client
2022-12-22T09:00:33.953Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: htlc 16: SENT_ADD_HTLC->SENT_ADD_COMMIT
2022-12-22T09:00:33.953Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-hsmd: Got WIRE_HSMD_SIGN_REMOTE_HTLC_TX
2022-12-22T09:00:33.954Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: htlc added REMOTE: local 16159811654 remote 617403346
2022-12-22T09:00:33.954Z DEBUG   hsmd: Client: Received message 20 from client
2022-12-22T09:00:33.954Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: -> local 16036354865 remote 617403346
2022-12-22T09:00:33.954Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: sending_commit: HTLC LOCAL 16 = SENT_ADD_COMMIT/RCVD_ADD_COMMIT
2022-12-22T09:00:33.954Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: Creating commit_sig signature 33 30440220271c92445b57a29a07e1e9104a8a6da6560f3c11d1185ec0c289df4ba472dbf20220686747462517b89181d15eba8b603b2c594bd3768a4cec2551f4e302188dc86101 for tx 0200000001854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e89010000000092f347800340e2010000000000220020f86f4d4c85be72a46b15191eb1f378c9c41cb6437e405738e34ddb369fcf9059bb6b0900000000002200209ad08275d62ab3b1c79e6639ea747ddddf2a1abacf947ea22f5865efa345ba3020b1f40000000000160014472788bf89670a1c5b2060f5766e969df91c639894fca020 wscript 5221028b291f230181d5013456bfd7898130f5c826cd5b1c22bfd5a761da6b1e87cb542103429c323065d0c836cae69e400dd113a2fc39a6a4e2f3fe849e7214045970cd3c52ae key 03429c323065d0c836cae69e400dd113a2fc39a6a4e2f3fe849e7214045970cd3c
2022-12-22T09:00:33.954Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: Creating HTLC signature 30440220508ae7e299dc933d238bed3246c8a0ad442c2495252f47078333057a3b14398f022072895f459636b2522b976bfa42b7ffa2d04af2160628e8ca9e728a1ba139b08d01 for tx 02000000019e3b6fcde4b177a3fc29fc52ae0b2de033ff6b496a7ddc141ec0a4bf0f8cfea0000000000000000000018fe10100000000002200209ad08275d62ab3b1c79e6639ea747ddddf2a1abacf947ea22f5865efa345ba3000000000 wscript 76a914f58db6614d8ccc57cd822657298bb7c9617930308763ac672103fae0bbd7821714edd47f5c4b88808c29b62d4c652c6f69fd7cd5f976950ed7aa7c8201208763a9148aefd48fd5788c192066cbefbf48c5c71226fb8388527c21023f0b395148ff06b287ca6b862306ac8603071eaada465148b0a0b30d3d893e1052ae677502d600b175ac6868 key 03fae0bbd7821714edd47f5c4b88808c29b62d4c652c6f69fd7cd5f976950ed7aa
2022-12-22T09:00:33.954Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: Telling master we're about to commit...
2022-12-22T09:00:33.954Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: Sending master 1020
2022-12-22T09:00:33.955Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-chan#1: HTLC out 16 SENT_ADD_HTLC->SENT_ADD_COMMIT
2022-12-22T09:00:33.962Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: ... , awaiting 1120
2022-12-22T09:00:33.962Z DEBUG   lightningd: Payment part 0/0/1 status 0
2022-12-22T09:00:33.962Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: Got it!
2022-12-22T09:00:33.963Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: Sending commit_sig with 1 htlc sigs
2022-12-22T09:00:33.963Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: peer_out WIRE_COMMITMENT_SIGNED
2022-12-22T09:00:33.966Z DEBUG   lightningd: Adding block 205: 396c1047098dcd4a5a81f99304c8b7d22f51da3f1c2be514beb08b30f4386c5c
2022-12-22T09:00:33.984Z DEBUG   lightningd: Adding block 206: 4f86a9f413234fd05a5d47eaeb387b63739a6752fed55d91d841c0e7ffcfd6b0
2022-12-22T09:00:34.002Z DEBUG   lightningd: Adding block 207: 461eda996b4198e6655deb5bb71b68cc4b25f75ed1cded86bec2067f1e641cac
2022-12-22T09:00:34.025Z DEBUG   lightningd: Adding block 208: 6be780c5ea0c3b65aeca8cdf86cb98ce42b51481c9394a5e0242e5a599413d69
2022-12-22T09:00:34.040Z DEBUG   lightningd: Adding block 209: 1f61c689012b1152b7cbcc9e83e3131b973430668e42bcd697f68b599063317a
2022-12-22T09:00:34.061Z DEBUG   lightningd: Adding block 210: 0db21cbb6e3fe8394f6a1b0b2924aacc0b795f4ef73e504d0c5c645448ed3aeb
2022-12-22T09:00:34.084Z DEBUG   lightningd: Adding block 211: 2bd9e76b2aaa46b8d6bf145843d42648a55a48010fde7b25ba0da27e930f3ab3
2022-12-22T09:00:34.097Z DEBUG   lightningd: Adding block 212: 075aca92ec201090438cd4bc58f3008f7e91fd869c87a67de1afa3617772f96f
2022-12-22T09:00:34.110Z DEBUG   lightningd: Adding block 213: 18fc644fb2f27b84e1cbe04b59d379285be7b6d0753f1d0ec5e544353c5ad9e4
2022-12-22T09:00:34.127Z DEBUG   lightningd: Adding block 214: 4315b4e0d6c57039f8e21dc3acae77e1d79a7bed3b36ebbe8ed010e544e7bdc1
2022-12-22T09:00:34.153Z DEBUG   lightningd: Adding block 215: 630dd9b1d0be1d4290c89cc02ff29c78566e4057a3f4fa546bdedca8c1e09704
2022-12-22T09:00:34.159Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-22T09:00:34.159Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-22T09:00:34.159Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-22T09:00:34.159Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253
2022-12-22T09:00:34.159Z DEBUG   lightningd: ... feerate estimate for htlc_resolution hit floor 253
2022-12-22T09:00:34.159Z DEBUG   lightningd: ... feerate estimate for penalty hit floor 253
2022-12-22T09:00:34.159Z DEBUG   lightningd: ... polled feerate estimate for min_acceptable (125) smoothed to 250 (alpha=0.02)
2022-12-22T09:00:34.159Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-22T09:00:34.162Z UNUSUAL 02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-chan#1: Peer permanent failure in CHANNELD_NORMAL: Offered HTLC 16 SENT_ADD_COMMIT cltv 214 hit deadline
2022-12-22T09:00:34.162Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-channeld-chan#1: Status closed, but not exited. Killing
2022-12-22T09:00:34.163Z DEBUG   lightningd: Broadcasting txid b343c15a3176ff0c78b0e48de79d64b1821acd16573f5b44a8ccb74c544abc66
2022-12-22T09:00:34.163Z DEBUG   lightningd: sendrawtransaction: 02000000000101854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e89010000000092f3478002bb6b0900000000001600140f6bf194920fe473faa03a6308d6139c8e2c41f38c93f6000000000022002009c2fac7920b9f86b474f4b11c1479b65123a2600709dcf4fa541d85fee7be7a0400473044022046f234279a51fd782ba232c79a73ed454a7aba13efb4c23d1ce91b8ad940c7b7022043a700d4e909895c48c0025efd16c21d96a2e7de680bd62bb57fd1dc79e77f570147304402202d9a0566c7713a6498f8ce42722f466d42274a448987287a12cfe588f3002f9402207433058d8c315bc10a6a203d96dc645c42e5e396d00a1123b6e2990e96113a4d01475221028b291f230181d5013456bfd7898130f5c826cd5b1c22bfd5a761da6b1e87cb542103429c323065d0c836cae69e400dd113a2fc39a6a4e2f3fe849e7214045970cd3c52ae95fca020
2022-12-22T09:00:34.163Z INFO    02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-chan#1: State changed from CHANNELD_NORMAL to AWAITING_UNILATERAL
2022-12-22T09:00:34.163Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-chan#1: attempting update blockheight 854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e88
2022-12-22T09:00:34.168Z DEBUG   hsmd: Client: Received message 5 from client
2022-12-22T09:00:34.168Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds
2022-12-22T09:00:34.173Z DEBUG   plugin-bcli: sendrawtx exit 0 (bitcoin-cli -regtest -datadir=/etc/bitcoin -rpcconnect=bitcoind sendrawtransaction 02000000000101854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e89010000000092f3478002bb6b0900000000001600140f6bf194920fe473faa03a6308d6139c8e2c41f38c93f6000000000022002009c2fac7920b9f86b474f4b11c1479b65123a2600709dcf4fa541d85fee7be7a0400473044022046f234279a51fd782ba232c79a73ed454a7aba13efb4c23d1ce91b8ad940c7b7022043a700d4e909895c48c0025efd16c21d96a2e7de680bd62bb57fd1dc79e77f570147304402202d9a0566c7713a6498f8ce42722f466d42274a448987287a12cfe588f3002f9402207433058d8c315bc10a6a203d96dc645c42e5e396d00a1123b6e2990e96113a4d01475221028b291f230181d5013456bfd7898130f5c826cd5b1c22bfd5a761da6b1e87cb542103429c323065d0c836cae69e400dd113a2fc39a6a4e2f3fe849e7214045970cd3c52ae95fca020)
2022-12-22T09:00:34.388Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-connectd: Activating for message WIRE_REVOKE_AND_ACK
2022-12-22T09:00:34.388Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-lightningd: Telling connectd to send error 0011854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e8800354f6666657265642048544c432031362053454e545f4144445f434f4d4d495420636c7476203231342068697420646561646c696e65
2022-12-22T09:00:34.389Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-connectd: peer_out WIRE_ERROR
2022-12-22T09:00:34.389Z DEBUG   connectd: drain_peer
2022-12-22T09:00:34.389Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-lightningd: peer_disconnect_done
2022-12-22T09:00:34.389Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-lightningd: Not reconnecting: no active channel
2022-12-22T09:00:34.390Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-hsmd: Got WIRE_HSMD_CUPDATE_SIG_REQ
2022-12-22T09:00:34.390Z DEBUG   plugin-funder: Cleaning up inflights for peer id 02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc
2022-12-22T09:00:34.390Z DEBUG   connectd: maybe_free_peer freeing peer!
2022-12-22T09:00:34.390Z DEBUG   hsmd: Client: Received message 3 from client
2022-12-22T09:00:35.174Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-22T09:00:35.174Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-22T09:00:35.174Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-22T09:00:35.174Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253
2022-12-22T09:00:35.174Z DEBUG   lightningd: ... feerate estimate for htlc_resolution hit floor 253
2022-12-22T09:00:35.174Z DEBUG   lightningd: ... feerate estimate for penalty hit floor 253
2022-12-22T09:00:35.174Z DEBUG   lightningd: ... polled feerate estimate for min_acceptable (125) smoothed to 250 (alpha=0.02)
2022-12-22T09:00:35.174Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-22T09:00:36.141Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-hsmd: Got WIRE_HSMD_ECDH_REQ
2022-12-22T09:00:36.141Z DEBUG   hsmd: Client: Received message 1 from client
2022-12-22T09:00:36.142Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-connectd: Connect IN
2022-12-22T09:00:36.142Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-connectd: peer_out WIRE_INIT
2022-12-22T09:00:36.142Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-gossipd: seeker: starting gossip
2022-12-22T09:00:36.142Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-connectd: peer_in WIRE_INIT
2022-12-22T09:00:36.143Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-connectd: Handed peer, entering loop
2022-12-22T09:00:36.143Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-connectd: peer_out WIRE_GOSSIP_TIMESTAMP_FILTER
2022-12-22T09:00:36.143Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-connectd: peer_in WIRE_GOSSIP_TIMESTAMP_FILTER
2022-12-22T09:00:36.190Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-22T09:00:36.190Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-22T09:00:36.190Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-22T09:00:36.190Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253

Bob

2022-12-22T09:00:33.124Z DEBUG   lightningd: ... polled feerate estimate for min_acceptable (125) smoothed to 250 (alpha=0.02)
2022-12-22T09:00:33.124Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-22T09:00:33.749Z DEBUG   lightningd: Adding block 204: 07bdac43c191502548f9d5a9eb7b18c9c7d49dba8dcf48662bb5f6230d980a89
2022-12-22T09:00:33.763Z DEBUG   lightningd: Adding block 205: 396c1047098dcd4a5a81f99304c8b7d22f51da3f1c2be514beb08b30f4386c5c
2022-12-22T09:00:33.778Z DEBUG   lightningd: Adding block 206: 4f86a9f413234fd05a5d47eaeb387b63739a6752fed55d91d841c0e7ffcfd6b0
2022-12-22T09:00:33.831Z DEBUG   lightningd: Adding block 207: 461eda996b4198e6655deb5bb71b68cc4b25f75ed1cded86bec2067f1e641cac
2022-12-22T09:00:33.853Z DEBUG   lightningd: Adding block 208: 6be780c5ea0c3b65aeca8cdf86cb98ce42b51481c9394a5e0242e5a599413d69
2022-12-22T09:00:33.877Z DEBUG   lightningd: Adding block 209: 1f61c689012b1152b7cbcc9e83e3131b973430668e42bcd697f68b599063317a
2022-12-22T09:00:33.893Z DEBUG   lightningd: Adding block 210: 0db21cbb6e3fe8394f6a1b0b2924aacc0b795f4ef73e504d0c5c645448ed3aeb
2022-12-22T09:00:33.902Z DEBUG   lightningd: routehint: {"jsonrpc":"2.0","id":"0/cln:listincoming#715","result":{"incoming":[{"id":"02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1","short_channel_id":"119x1x1","fee_base_msat":"1msat","htlc_min_msat":"0msat","htlc_max_msat":"16609443840msat","fee_proportional_millionths":10,"cltv_expiry_delta":6,"incoming_capacity_msat":"0msat","public":true,"peer_features":"88a000080269a2"}]}}
2022-12-22T09:00:33.902Z DEBUG   lightningd: 119x1x1: deadend
2022-12-22T09:00:33.902Z DEBUG   lightningd: needed = 123456789msat, avail_capacity = 0msat, private_capacity = 0msat, offline_capacity = 0msat, deadend_capacity = 4294967295msat
2022-12-22T09:00:33.913Z DEBUG   lightningd: Adding block 211: 2bd9e76b2aaa46b8d6bf145843d42648a55a48010fde7b25ba0da27e930f3ab3
2022-12-22T09:00:33.918Z DEBUG   hsmd: Client: Received message 8 from client
2022-12-22T09:00:33.930Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: peer_in WIRE_UPDATE_ADD_HTLC
2022-12-22T09:00:33.931Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: NEW:: HTLC REMOTE 16 = RCVD_ADD_HTLC/SENT_ADD_HTLC
2022-12-22T09:00:33.935Z DEBUG   lightningd: Adding block 212: 075aca92ec201090438cd4bc58f3008f7e91fd869c87a67de1afa3617772f96f
2022-12-22T09:00:33.961Z DEBUG   lightningd: Adding block 213: 18fc644fb2f27b84e1cbe04b59d379285be7b6d0753f1d0ec5e544353c5ad9e4
2022-12-22T09:00:33.972Z DEBUG   lightningd: Adding block 214: 4315b4e0d6c57039f8e21dc3acae77e1d79a7bed3b36ebbe8ed010e544e7bdc1
2022-12-22T09:00:33.987Z DEBUG   lightningd: Adding block 215: 630dd9b1d0be1d4290c89cc02ff29c78566e4057a3f4fa546bdedca8c1e09704
2022-12-22T09:00:33.995Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-chan#1: attempting update blockheight 854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e88
2022-12-22T09:00:33.999Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds
2022-12-22T09:00:34.147Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-22T09:00:34.147Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-22T09:00:34.147Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-22T09:00:34.148Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253
2022-12-22T09:00:34.148Z DEBUG   lightningd: ... feerate estimate for htlc_resolution hit floor 253
2022-12-22T09:00:34.148Z DEBUG   lightningd: ... feerate estimate for penalty hit floor 253
2022-12-22T09:00:34.148Z DEBUG   lightningd: ... polled feerate estimate for min_acceptable (125) smoothed to 250 (alpha=0.02)
2022-12-22T09:00:34.148Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-22T09:00:34.172Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: peer_in WIRE_COMMITMENT_SIGNED
2022-12-22T09:00:34.172Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Received commit
2022-12-22T09:00:34.172Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: htlc 16: RCVD_ADD_HTLC->RCVD_ADD_COMMIT
2022-12-22T09:00:34.172Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: htlc added LOCAL: local 617403346 remote 16159811654
2022-12-22T09:00:34.172Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: -> local 617403346 remote 16036354865
2022-12-22T09:00:34.173Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-hsmd: Got WIRE_HSMD_VALIDATE_COMMITMENT_TX
2022-12-22T09:00:34.173Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: rcvd_commit: HTLC REMOTE 16 = RCVD_ADD_COMMIT/SENT_ADD_COMMIT
2022-12-22T09:00:34.173Z DEBUG   hsmd: Client: Received message 35 from client
2022-12-22T09:00:34.173Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Feerates are 253/253
2022-12-22T09:00:34.173Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: We need 167998sat at feerate 253 for 1 untrimmed htlcs: we have 16036354865msat/16159811654msat
2022-12-22T09:00:34.174Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Derived key 03fae0bbd7821714edd47f5c4b88808c29b62d4c652c6f69fd7cd5f976950ed7aa from basepoint 032945ceef79f479192a8a64193cc16d977c3c86b4a3404df2782ef86d345d9b5b, point 02fc55a194f838e6614dfd6a0c85200e984668d9a8fce637814763977db6c60dba
2022-12-22T09:00:34.174Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Received commit_sig with 1 htlc sigs
2022-12-22T09:00:34.174Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Sending revoke_and_ack
2022-12-22T09:00:34.174Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: htlc 16: RCVD_ADD_COMMIT->SENT_ADD_REVOCATION
2022-12-22T09:00:34.174Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: sending_revoke_and_ack: HTLC REMOTE 16 = SENT_ADD_REVOCATION/RCVD_ADD_REVOCATION
2022-12-22T09:00:34.174Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: revoke_and_ack made pending: commit timer
2022-12-22T09:00:34.174Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Sending master 1021
2022-12-22T09:00:34.174Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-chan#1: got commitsig 33: feerate 253, blockheight: 0, 1 added, 0 fulfilled, 0 failed, 0 changed
2022-12-22T09:00:34.175Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-chan#1: Adding their HTLC 16
2022-12-22T09:00:34.175Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-chan#1: HTLC in 16 RCVD_ADD_COMMIT->SENT_ADD_REVOCATION
2022-12-22T09:00:34.180Z DEBUG   hsmd: Client: Received message 1 from client
2022-12-22T09:00:34.180Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: ... , awaiting 1121
2022-12-22T09:00:34.180Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Got it!
2022-12-22T09:00:34.180Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: peer_out WIRE_REVOKE_AND_ACK
2022-12-22T09:00:34.184Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Trying commit
2022-12-22T09:00:34.184Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: htlc 16: SENT_ADD_REVOCATION->SENT_ADD_ACK_COMMIT
2022-12-22T09:00:34.184Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: htlc added REMOTE: local 617403346 remote 16159811654
2022-12-22T09:00:34.184Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: -> local 617403346 remote 16036354865
2022-12-22T09:00:34.184Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: sending_commit: HTLC REMOTE 16 = SENT_ADD_ACK_COMMIT/RCVD_ADD_ACK_COMMIT
2022-12-22T09:00:34.185Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2022-12-22T09:00:34.185Z DEBUG   hsmd: Client: Received message 19 from client
2022-12-22T09:00:34.185Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Creating commit_sig signature 33 3044022016ba31486d4a23b7611fb1e7fabd459deefb8e8a354350708b20c28f64b1b77302204af5ab253bd611851dd59ad065c78991709e82c1cb7efa4c743c6c19c9e7228b01 for tx 0200000001854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e89010000000092f347800340e201000000000022002030dcd1c239a5a201b4d3e4e0c53babc03fc856b8397f76e281da5b82beb3c5e0bb6b0900000000001600140f6bf194920fe473faa03a6308d6139c8e2c41f320b1f40000000000220020ec1765fe30d9eee0a194ee0d52d84a7038dec7591f37b7f6f83b9e358c66f57d94fca020 wscript 5221028b291f230181d5013456bfd7898130f5c826cd5b1c22bfd5a761da6b1e87cb542103429c323065d0c836cae69e400dd113a2fc39a6a4e2f3fe849e7214045970cd3c52ae key 028b291f230181d5013456bfd7898130f5c826cd5b1c22bfd5a761da6b1e87cb54
2022-12-22T09:00:34.186Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-hsmd: Got WIRE_HSMD_SIGN_REMOTE_HTLC_TX
2022-12-22T09:00:34.186Z DEBUG   hsmd: Client: Received message 20 from client
2022-12-22T09:00:34.186Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Creating HTLC signature 304402207fcd0a5df1b74a251432ba591312690568538822233f36dc36f875da1fd4434602200d64a0396a6f67b1e3214f71f093dd28b7bfd58429e9a36666e1cfbd81f06a0d01 for tx 020000000147654d772feb1648213bdfcce3092d2d4f6a38877221cf88322a174d1956da3a0000000000000000000199e1010000000000220020ec1765fe30d9eee0a194ee0d52d84a7038dec7591f37b7f6f83b9e358c66f57dd6000000 wscript 76a914897d5f9699305cedde4713b8ac7bdbfde2ab57f08763ac672102313b908a037ecd0dec9b15e6afac80cc0dd690908bdbd254ff4306cde14bee577c820120876475527c21022c90dff2ce05133e7858d16c5060924d16485173e3107b0359668113c0fd625b52ae67a9148aefd48fd5788c192066cbefbf48c5c71226fb8388ac6868 key 02313b908a037ecd0dec9b15e6afac80cc0dd690908bdbd254ff4306cde14bee57
2022-12-22T09:00:34.186Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Telling master we're about to commit...
2022-12-22T09:00:34.186Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Sending master 1020
2022-12-22T09:00:34.186Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-chan#1: HTLC in 16 SENT_ADD_REVOCATION->SENT_ADD_ACK_COMMIT
2022-12-22T09:00:34.193Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: ... , awaiting 1120
2022-12-22T09:00:34.194Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Got it!
2022-12-22T09:00:34.194Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: Sending commit_sig with 1 htlc sigs
2022-12-22T09:00:34.194Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: peer_out WIRE_COMMITMENT_SIGNED
2022-12-22T09:00:34.389Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-hsmd: Got WIRE_HSMD_CUPDATE_SIG_REQ
2022-12-22T09:00:34.389Z DEBUG   connectd: drain_peer
2022-12-22T09:00:34.389Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: peer_in WIRE_ERROR
2022-12-22T09:00:34.389Z DEBUG   hsmd: Client: Received message 3 from client
2022-12-22T09:00:34.389Z DEBUG   connectd: drain_peer draining subd!
2022-12-22T09:00:34.389Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-channeld-chan#1: billboard perm: Received error channel 854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e88: Offered HTLC 16 SENT_ADD_COMMIT cltv 214 hit deadline
2022-12-22T09:00:34.390Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-lightningd: peer_disconnect_done
2022-12-22T09:00:34.390Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-lightningd: Will try reconnect in 1 seconds
2022-12-22T09:00:34.390Z DEBUG   plugin-funder: Cleaning up inflights for peer id 02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1
2022-12-22T09:00:34.390Z DEBUG   connectd: maybe_free_peer freeing peer!
2022-12-22T09:00:34.390Z UNUSUAL 02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-chan#1: Peer permanent failure in CHANNELD_NORMAL: channeld: received ERROR error channel 854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e88: Offered HTLC 16 SENT_ADD_COMMIT cltv 214 hit deadline
2022-12-22T09:00:34.391Z DEBUG   lightningd: Broadcasting txid a0fe8c0fbfa4c01e14dc7d6a496bff33e02d0bae52fc29fca377b1e4cd6f3b9e
2022-12-22T09:00:34.391Z DEBUG   lightningd: sendrawtransaction: 02000000000101854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e89010000000092f347800340e2010000000000220020f86f4d4c85be72a46b15191eb1f378c9c41cb6437e405738e34ddb369fcf9059bb6b0900000000002200209ad08275d62ab3b1c79e6639ea747ddddf2a1abacf947ea22f5865efa345ba3020b1f40000000000160014472788bf89670a1c5b2060f5766e969df91c639804004730440220220c896641190ddd0f8409f633af43a9a8940b2fa84b4cf09eb082cb4f4d3ac602204bca1d5d01f5fdc739beb00e8c053a75cc470c554844b1530917ffcc6d4d0c13014730440220271c92445b57a29a07e1e9104a8a6da6560f3c11d1185ec0c289df4ba472dbf20220686747462517b89181d15eba8b603b2c594bd3768a4cec2551f4e302188dc86101475221028b291f230181d5013456bfd7898130f5c826cd5b1c22bfd5a761da6b1e87cb542103429c323065d0c836cae69e400dd113a2fc39a6a4e2f3fe849e7214045970cd3c52ae94fca020
2022-12-22T09:00:34.391Z INFO    02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-chan#1: State changed from CHANNELD_NORMAL to AWAITING_UNILATERAL
2022-12-22T09:00:34.399Z DEBUG   hsmd: Client: Received message 5 from client
2022-12-22T09:00:34.402Z DEBUG   plugin-bcli: sendrawtx exit 26 (bitcoin-cli -regtest -datadir=/etc/bitcoin -rpcconnect=bitcoind sendrawtransaction 02000000000101854c37061bc14c118a673cd11dff880782f08dc20d528b7665c771a213284e89010000000092f347800340e2010000000000220020f86f4d4c85be72a46b15191eb1f378c9c41cb6437e405738e34ddb369fcf9059bb6b0900000000002200209ad08275d62ab3b1c79e6639ea747ddddf2a1abacf947ea22f5865efa345ba3020b1f40000000000160014472788bf89670a1c5b2060f5766e969df91c639804004730440220220c896641190ddd0f8409f633af43a9a8940b2fa84b4cf09eb082cb4f4d3ac602204bca1d5d01f5fdc739beb00e8c053a75cc470c554844b1530917ffcc6d4d0c13014730440220271c92445b57a29a07e1e9104a8a6da6560f3c11d1185ec0c289df4ba472dbf20220686747462517b89181d15eba8b603b2c594bd3768a4cec2551f4e302188dc86101475221028b291f230181d5013456bfd7898130f5c826cd5b1c22bfd5a761da6b1e87cb542103429c323065d0c836cae69e400dd113a2fc39a6a4e2f3fe849e7214045970cd3c52ae94fca020) error code: -26\nerror message:\ninsufficient fee, rejecting replacement a0fe8c0fbfa4c01e14dc7d6a496bff33e02d0bae52fc29fca377b1e4cd6f3b9e; new feerate 0.00001022 BTC/kvB <= old feerate 0.00001022 BTC/kvB
2022-12-22T09:00:35.164Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-22T09:00:35.164Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-22T09:00:35.164Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-22T09:00:35.164Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253
2022-12-22T09:00:35.164Z DEBUG   lightningd: ... feerate estimate for htlc_resolution hit floor 253
2022-12-22T09:00:35.164Z DEBUG   lightningd: ... feerate estimate for penalty hit floor 253
2022-12-22T09:00:35.164Z DEBUG   lightningd: ... polled feerate estimate for min_acceptable (125) smoothed to 250 (alpha=0.02)
2022-12-22T09:00:35.164Z DEBUG   lightningd: ... feerate estimate for min_acceptable hit floor 253
2022-12-22T09:00:36.139Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GET_ADDRS_REPLY with 0 fds
2022-12-22T09:00:36.140Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-connectd: Connected out, starting crypto
2022-12-22T09:00:36.141Z DEBUG   02403c2f06653f30bb74441f80438c029a27ad248a617504c4b5c204fce4d6c9fc-hsmd: Got WIRE_HSMD_ECDH_REQ
2022-12-22T09:00:36.141Z DEBUG   hsmd: Client: Received message 1 from client
2022-12-22T09:00:36.141Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-connectd: Connect OUT
2022-12-22T09:00:36.141Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-connectd: peer_out WIRE_INIT
2022-12-22T09:00:36.142Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-connectd: peer_in WIRE_INIT
2022-12-22T09:00:36.143Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-gossipd: seeker: starting gossip
2022-12-22T09:00:36.143Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-connectd: Handed peer, entering loop
2022-12-22T09:00:36.143Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-connectd: peer_out WIRE_GOSSIP_TIMESTAMP_FILTER
2022-12-22T09:00:36.143Z DEBUG   02f64e768618158f0dc779bf4753f893e8e24e6871fd042af1df75271a716017c1-connectd: peer_in WIRE_GOSSIP_TIMESTAMP_FILTER
2022-12-22T09:00:36.180Z DEBUG   lightningd: ... feerate estimate for opening hit floor 253
2022-12-22T09:00:36.180Z DEBUG   lightningd: ... feerate estimate for mutual_close hit floor 253
2022-12-22T09:00:36.180Z DEBUG   lightningd: ... feerate estimate for unilateral_close hit floor 253
2022-12-22T09:00:36.180Z DEBUG   lightningd: ... feerate estimate for delayed_to_us hit floor 253
2022-12-22T09:00:36.180Z DEBUG   lightningd: ... feerate estimate for htlc_resolution hit floor 253
2022-12-22T09:00:36.180Z DEBUG   lightningd: ... feerate estimate for penalty hit floor 253
NicolasDorier commented 1 year ago

Analyzing the situation, it seems the HLTC fail because we are mining a bunch of block during a payment.

So my questions are:

  1. Is there a way to make the hltc deadline longer?
  2. Even if the channel get in the UNITERAL close state, pay shouldn't be pending.
cdecker commented 1 year ago

We can't terminate the pay call, as that is meant to be synchronous, and despite the channel going down, the HTLC may still succeed (completing the HTLC success path on-chain) or fail (completing on-chain via the timeout), hence pay cannot decide whether to report a success or a failure. Notice that in an MPP payment, pay would still report success or failure as long as one non-stuck HTLC reports an MPP_TIMEOUT (failure) or returns the preimage (success).

This is a common issue for payments, where an on-chain resolution can take considerable time, and we can't determine whether it is going to succeed or fail, so we can't report it back to the user.

NicolasDorier commented 1 year ago

@cdecker I agree maybe for the current payment being sent. But should it be the case for future payment?

Say I do payment first (success), second (pending, channel transition to unilateral close), the third payment shouldn't try to use the channel that is transitioning to unilateral close and thus be stuck with the second payment.

It's like if closing channel were considered for routing future payment?

NicolasDorier commented 1 year ago

Also about the channel dropping, I tried to change watchtime-blocks=100 expecting it would make the HTLC deadline 100 blocks. But didn't seem to work actually. Is there another solution?

cdecker commented 1 year ago

That detail is giving me some trouble: if the channel transitions away from CHANNELD_NORMAL into any other state, we will not consider it for a payment that is started after that transition happened. Even if we were there is no way for us to add an HTLC to a channel that isn't in CHANNELD_NORMAL, so it can't happen that the HTLC gets stuck on an already closing channel (not least because lightningd will simply report that the first hop is unavailable). So I don't see how we could get stuck on a closing channel, after that channel has started closing.

Do you have any logs showing how pay after the state transition causes the HTLC to be added to that channel and then getting stuck?

NicolasDorier commented 1 year ago

@cdecker I am silly, I think the issue is that I was just calling pay a second time with the same BOLT11 that was already pending.

It seems to me c-lightning is the only implementation doing the right thing, and others should have crashed before as they should have been in the same condition.

I am closing this one:

  1. The channel being dropped was normal. It seems blocks were found during the HTLC. I am unsure why it is the case, nor why it didn't crash on my tests over LND or Eclair or previous version of c-lightning, but that's another topic I need to dig in.
  2. The hanging pay is indeed normal as even if the channel is AWAITING UNILATERAL, the HLTC could still succeed. My second call to pay was on the same BOLT11 that was pending, so it is normal it also blocks.
cdecker commented 1 year ago

Good catch on identifying that another call to pay after the channel initiated a close would share the same fate of the pay before the close.

As for why blocks are being found during the payment: bcli polls the bitcoind process at regular intervals (30s without --dev-bitcoind-poll) so if you generate, and then send pay before lightningd has a chance to poll it'll fall behind and use its current blockheight. This is fine usually because we tend to generate a couple of blocks at a time, and we can wait for sync if needed, but if you generate dozens or hundreds of blocks at a time it can happen that the timeouts get triggered. I'd suggest waiting for sync if you want to stabilize tests. Notice also that 30s << 10m so in normal circumstances this cannot happen on mainnet.

NicolasDorier commented 1 year ago

@cdecker I use dev-bitcoind-poll=1 and normally my tests are waiting that clightning get synched with my new blocks before doing anything else with getinfo. I am digging into what happen right now.

NicolasDorier commented 1 year ago

I believe this issue was related to the fact I may have missed a corner case where I wasn't waiting for the sync. The fact c-lightning is polling may have mattered on the timing. Sorry for that! :)